原创：打码日记（微信公众号ID：codelogs），欢迎分享，转载请保留出处。
简介
这是Linux命令拾遗系列的第六篇，本篇主要介绍工作中常用的动态追踪工具strace、arthas、bpftrace等。
本系列文章索引
之前介绍了一些线程与内存剖析工具，如jstack、pstack能很容易观测到线程被卡在了什么位置，而jmap、gcore则容易排查内存泄露、oom等问题。
但线程与内存剖析，只能观测到进程的整体情况，有些时候我们需要观测到某一方法级别，比如调用方法test()时，传入的参数是什么，返回值是多少，花费了多少时间？这种情况下，我们就需要使用一些动态追踪工具了，如strace、arthas、bpftrace、systemtap等。
strace与ltrace
strace是Linux中用来观测系统调用的工具，学过操作系统原理都知道，操作系统向应用程序暴露了一批系统调用接口，应用程序只能通过这些系统调用接口来访问操作系统，比如申请内存、文件或网络io操作等。
用法如下：
1 | bash复制代码# -T 打印系统调用花费的时间 |
实例：抓取实际发送的SQL
有些时候，我们会发现代码中完全没问题的SQL，却查不到数据，这极有可能是由于项目中一些底层框架改写了SQL，导致真实发送的SQL与代码中的SQL不一样。
遇到这种情况，先别急着扒底层框架代码，那样会比较花时间，毕竟程序员的时间很宝贵，不然要加更多班的，怎么快速确认是不是这个原因呢？
有两种方法，第一种是使用wireshark抓包，第二种就是本篇介绍的strace了，由于程序必然要通过网络io相关的系统调用，将SQL命令发送到数据库，因此我们只需要用strace追踪所有系统调用，然后grep出发送SQL的系统调用即可，如下：
1 | shell复制代码$ strace -T -tt -f -s 10000 -p 87 |& tee strace.log |
从图中可以清晰看到，mysql的jdbc驱动是通过sendto系统调用来发送SQL，通过recvfrom来获取返回结果，可以发现，由于SQL是字符串，strace自动帮我们识别出来了，而返回结果因为是二进制的，就不容易识别了，需要非常熟悉mysql协议才行。
另外，从上面其实也很容易看出SQL执行耗时，计算相同线程号的sendto与recvfrom之间的时间差即可。
ltrace
由于大多数进程基本都会使用基础c库，而不是系统调用，如Linux上的glibc，Windows上的msvc，所以还有一个工具ltrace，可以用来追踪库调用，如下：
1 | bash复制代码$ ltrace -T -tt -f -s 10000 -p 87 -o ltrace.log |
基本用法和strace一样，一般来说，使用strace就够了。
arthas
arthas是java下的一款动态追踪工具，可以观测到java方法的调用参数、返回值等，除此之外，还提供了很多实用功能，如反编译、线程剖析、堆内存转储、火焰图等。
下载与使用
1 | bash复制代码# 下载arthas |
watch、trace与stack
在arthas中，使用watch、trace、stack命令可以观测方法调用情况，如下：
1 | bash复制代码# watch观测执行的查询SQL，-x 3指定对象展开层级 |
可以看到watch、trace、stack命令中都可以指定条件表达式，只要满足ognl表达式语法即可，ognl完整语法很复杂，如下是一些经常使用的：
| 分类 | 示例 |
|---|---|
| 内置变量 | watch/trace/stack命令中内置了params,target,returnObj,throwExp,#cost，分别表示参数,调用对象自身，返回值，异常，执行耗时。 |
| 属性获取 | 通过.user获取对象user属性值，.user.userId获取对象中user属性中的userId属性。 |
| 数组、集合或Map元素获取 | 通过.orders[0]获取数组或集合中第一个元素，通过.userMap["lisi"]获取Map中对应key值 |
| 对象方法调用 | 通过.getUser()可直接调用对象的方法 |
| 静态变量与方法访问 | 静态变量访问@class@member， 静态方法调用@class@method(args) |
| 条件判断 | 数值可使用> >= ==等比较，字符串可直接通过== !=比较，如.name=="zhangsan" |
| 逻辑运算 | 通过`&& |
| 数组包含 | 对于数组/List/Set，可以使用in,not in判断元素是否存在，如"zhangsan" in .names |
| 变量赋值 | 当前时间赋值到变量obj，#obj=new java.util.Date(), #obj.toString() |
| List、Map构造 | List构造{"green", "red", "blue"}， Map构造#{"id" : 1, "name" : "lisi", "birthday" : new java.util.Date()} |
| 字段提取 | 提取userList中的birthday，.userList.{birthday.getYear()} |
| 列表过滤 | 过滤出userList中的id<2的元素，.userList.{? id<2 } |
ognl
通过ognl命令，可直接查看静态变量的值，如下：
1 | bash复制代码# 调用System.getProperty静态函数，查看jvm默认字符编码 |
其它命令
arthas还提供了jvm大盘、线程剖析、堆转储、反编译、火焰图等功能，如下：
1 | bash复制代码# 显示耗cpu较多的前4个线程 |
可见，arthas已经不是一个单纯的动态追踪工具了，它把jvm下常用的诊断功能几乎全囊括了。
相关项目地址：
arthas.aliyun.com/doc/index.h…
bpftrace
arthas只能追踪java程序，对于原生程序(如MySQL)就无能为力了，好在Linux生态提供了大量的机制以及配套工具，可用于追踪原生程序的调用，如perf、bpftrace、systemtap等，由于bpftrace使用难度较小，本篇主要介绍它的用法。
bpftrace是基于ebpf技术实现的动态追踪工具，它对ebpf技术进行封装，实现了一种脚本语言，就像上面介绍的arthas基于ognl一样，它实现的脚本语言类似于awk，封装了常见语句块，并提供内置变量与内置函数，如下：
1 | bash复制代码$ sudo bpftrace -e 'BEGIN { printf("Hello, World!\n"); } ' |
实例：在调用端追踪慢SQL
前面我们用strace追踪过mysql的jdbc驱动，它使用sendto与recvfrom系统调用来与mysql服务器通信，因此，我们在sendto调用时，计下时间点，然后在recvfrom结束时，计算时间之差，就可以得到相应SQL的耗时了，如下：
- 先找到
sendto与recvfrom系统调用在bpftrace中的追踪点，如下：
1 | bash复制代码# 查找sendto|recvfrom系统调用的追踪点，可以看到sys_enter_开头的追踪点应该是进入时触发，sys_exit_开头的退出时触发 |
- 编写追踪脚本
trace_slowsql_from_syscall.bt，脚本代码如下：
1 | bash复制代码#!/usr/local/bin/bpftrace |
其中，comm表示进程名称，tid表示线程号，@query[tid]与@start[tid]类似map，以tid为key的话，这个变量就像一个线程本地变量了。
- 调用上面的脚本，可以看到各SQL执行耗时，如下：
1 | bash复制代码$ sudo BPFTRACE_STRLEN=80 bpftrace trace_slowsql_from_syscall.bt |
实例：在服务端追踪慢SQL
从调用端来追踪SQL耗时，会包含网络往返时间，为了得到更精确的SQL耗时，我们可以写一个追踪服务端mysql的脚本，来观测SQL耗时，如下：
- 确定mysqld服务进程的可执行文件与入口函数
1 | bash复制代码$ which mysqld |
- 使用uprobe追踪
dispatch_command的调用，如下：
1 | bash复制代码#!/usr/bin/bpftrace |
追踪脚本整体上与之前系统调用版本的类似，不过追踪点不一样而已。
实例：找出扫描大量行的SQL
众所周知，SQL执行时需要扫描数据，并且扫描的数据越多，SQL性能就会越差。
但对于一些中间情况，SQL扫描行数不多也不少，如2w条。且这2w条数据都在缓存中的话，SQL执行时间不会很长，导致没有记录在慢查询日志中，但如果这样的SQL并发量大起来的话，会非常耗费CPU。
对于mysql的话，扫描行的函数是row_search_mvcc（如果你经常抓取mysql栈的话，很容易发现这个函数），每扫一行调用一次，如果在追踪脚本中追踪此函数，记录下调用次数，就可以观测SQL的扫描行数了，如下：
1 | bash复制代码#!/usr/bin/bpftrace |
脚本运行效果如下：
1 | bash复制代码$ sudo BPFTRACE_STRLEN=80 bpftrace trace_mysql_scan.bt 200 |
如上所示，app_log是我建的一张测试表，共43716条数据，其中id字段是自增主键，seq值与id值一样，但没有索引。
可以看到上面的几个场景，不管什么场景，只要扫描行数变大，耗时就会变长，但也都没有超过500毫秒的，原因是这个表很小，数据可以全部缓存在内存中。
可见，像bpftrace这样的动态追踪工具是非常强大的，而且比arthas更加灵活，arthas只能追踪单个函数，而bpftrace可以跨函数追踪。
bpftrace使用手册：github.com/iovisor/bpf…
总结
已经介绍了不少诊断工具了，这里简单概括一下它们的应用场景：
- 软件资源观测，如ps、lsof、netstat，用来检查进程基本情况，如内存占用、打开哪些文件、创建了哪些连接等。
- 硬件资源观测，如top、iostat、sar等，类似Windows上任务管理器一样，让你对硬件资源占用以及在进程上情况有个大概了解，最多观测到线程级别，这些工具一般只能指示进一步调查的方向，很少能直接确认原因。
- 线程与内存剖析，如jstack、jmap等，比较容易分析线程卡住或内存oom问题，而oncpu火焰图容易找出热代码路径，分析高cpu瓶颈，offcpu火焰图则容易找出经常阻塞的代码路径，分析高耗时问题。
- 动态追踪工具，如arthas、bpftrace等，能追踪到方法调用级，常用于问题需要深入调查的场景，如问题不在代码实现上，而在调用数据上，就像上面row_search_mvcc函数一样，抓火焰图会发现它出现频繁，但由于它是核心函数，这个频繁可能是正常的，也可能是不正常的，需要将调用次数分散到SQL上才能确认。
往期内容
本文转载自: 掘金