Linux命令拾遗-动态追踪工具

简介

这是Linux命令拾遗系列的第六篇，本篇主要介绍工作中常用的动态追踪工具strace、arthas、bpftrace等。

本系列文章索引
Linux命令拾遗-入门篇
Linux命令拾遗-文本处理篇
Linux命令拾遗-软件资源观测
Linux命令拾遗-硬件资源观测
Linux命令拾遗-剖析工具

之前介绍了一些线程与内存剖析工具，如jstack、pstack能很容易观测到线程被卡在了什么位置，而jmap、gcore则容易排查内存泄露、oom等问题。

但线程与内存剖析，只能观测到进程的整体情况，有些时候我们需要观测到某一方法级别，比如调用方法test()时，传入的参数是什么，返回值是多少，花费了多少时间？这种情况下，我们就需要使用一些动态追踪工具了，如strace、arthas、bpftrace、systemtap等。

strace与ltrace

strace是Linux中用来观测系统调用的工具，学过操作系统原理都知道，操作系统向应用程序暴露了一批系统调用接口，应用程序只能通过这些系统调用接口来访问操作系统，比如申请内存、文件或网络io操作等。
用法如下：

# -T 打印系统调用花费的时间
# -tt 打印系统调用的时间点
# -s 输出的最大长度，默认32，对于调用参数较长的场景，建议加大
# -f 是否追踪fork出来子进程的系统调用，由于服务端服务普通使用线程池，建议加上
# -p 指定追踪的进程pid
# -o 指定追踪日志输出到哪个文件，不指定则直接输出到终端
$ strace -T -tt -f -s 10000 -p 87 -o strace.log

实例：抓取实际发送的SQL

有些时候，我们会发现代码中完全没问题的SQL，却查不到数据，这极有可能是由于项目中一些底层框架改写了SQL，导致真实发送的SQL与代码中的SQL不一样。

遇到这种情况，先别急着扒底层框架代码，那样会比较花时间，毕竟程序员的时间很宝贵，不然要加更多班的，怎么快速确认是不是这个原因呢？

有两种方法，第一种是使用wireshark抓包，第二种就是本篇介绍的strace了，由于程序必然要通过网络io相关的系统调用，将SQL命令发送到数据库，因此我们只需要用strace追踪所有系统调用，然后grep出发送SQL的系统调用即可，如下：

$ 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，可以用来追踪库调用，如下：

$ ltrace -T -tt -f -s 10000 -p 87 -o ltrace.log

基本用法和strace一样，一般来说，使用strace就够了。

arthas

arthas是java下的一款动态追踪工具，可以观测到java方法的调用参数、返回值等，除此之外，还提供了很多实用功能，如反编译、线程剖析、堆内存转储、火焰图等。
下载与使用

# 下载arthas
$ wget https://arthas.aliyun.com/download/3.4.6?mirror=aliyun -O arthas-packaging-3.4.6-bin.zip

# 解压
$ unzip arthas-packaging-3.4.6-bin.zip -d arthas && cd arthas/

# 进入arthas命令交互界面
$ java -jar arthas-boot.jar `pgrep -n java`
[INFO] arthas-boot version: 3.4.6
[INFO] arthas home: /home/work/arthas
[INFO] Try to attach process 3368243
[INFO] Attach process 3368243 success.
[INFO] arthas-client connect 127.0.0.1 3658
  ,---.  ,------. ,--------.,--.  ,--.  ,---.   ,---.
 /  O  \ |  .--. ''--.  .--'|  '--'  | /  O  \ '   .-'
|  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |`.  `-.
|  | |  ||  |\  \    |  |   |  |  |  ||  | |  |.-'    |
`--' `--'`--' '--'   `--'   `--'  `--'`--' `--'`-----'


wiki      https://arthas.aliyun.com/doc
tutorials https://arthas.aliyun.com/doc/arthas-tutorials.html
version   3.4.6
pid       3368243
time      2021-11-13 13:35:49

# help可查看arthas提供了哪些命令
[arthas@3368243]$ help
# help watch可查看watch命令具体用法
[arthas@3368243]$ help watch

watch、trace与stack
在arthas中，使用watch、trace、stack命令可以观测方法调用情况，如下：

# watch观测执行的查询SQL，-x 3指定对象展开层级
[arthas@3368243]$ watch org.apache.ibatis.executor.statement.PreparedStatementHandler parameterize '{target.boundSql.sql,target.boundSql.parameterObject}' -x 3
method=org.apache.ibatis.executor.statement.PreparedStatementHandler.parameterize location=AtExit
ts=2021-11-13 14:50:34; [cost=0.071342ms] result=@ArrayList[
    @String[select id,log_info,create_time,update_time,add_time from app_log where id=?],
    @ParamMap[
        @String[id]:@Long[41115],
        @String[param1]:@Long[41115],
    ],
]

# watch观测耗时超过200ms的SQL
[arthas@3368243]$ watch com.mysql.jdbc.PreparedStatement execute '{target.toString()}' 'target.originalSql.contains("select") && #cost > 200' -x 2
Press Q or Ctrl+C to abort.
Affect(class count: 3 , method count: 1) cost in 123 ms, listenerId: 25
method=com.mysql.jdbc.PreparedStatement.execute location=AtExit
ts=2021-11-13 14:58:42; [cost=1001.558851ms] result=@ArrayList[
    @String[com.mysql.jdbc.PreparedStatement@6283cfe6: select count(*) from app_log],
]

# trace追踪方法耗时，层层追踪，就可找到耗时根因，--skipJDKMethod false显示jdk方法耗时，默认不显示
[