浅谈动态追踪技术

本文主要介绍了动态追踪技术，并举例说明动态追踪技术的应用。

大部分情况，其实我们已经可以通过top，pidstat等命令定位到具体是哪一个服务出的问题。当然重启服务可以解决60%以上的服务异常问题，但是重启后会丢失现场。

重启一时爽，一直重启就不爽了。还是需要定位到具体的问题。我还是希望知道底病根在哪，最好直接告诉我哪个具体函数，哪条语句导致的问题或者bug。最差也得知道是大致什么节点的什么类型故障

很多人可能会想到GDB。虽然这些工具很伟大，但是这应该不适合我们sre在已经服务已经发病的情况下使用，因为线上的服务不能被中止。GDB在调试过程中设置断点会发出SIGSTOP信号，这会让被调试进程进入T (TASK_STOPPED or TASK_TRACED)暂停状态或跟踪状态。同时 GDB 所基于的 ptrace 这种很古老的系统调用，其中的坑和问题也非常多。

比如 ptrace 需要改变目标调试进程的父亲，还不允许多个调试者同时分析同一个进程，而且不太熟悉GDB的人可能会把程序调试挂了，这种交互式的追踪过程通常不考虑生产安全性，也不在乎性能损耗。另外提一下，strace也是基于ptrace的，所以strace也是对性能不友好的。

那么就要提到动态追踪技术了，动态追踪技术通常通过探针这样的机制发起查询。动态追踪一般来说是不需要应用目标来配合的，随时随地，按需采集，而且它非常大的优势为性能消耗极小（通常5%或者更低的水平）。

动态追踪的工具很多，systemtap，perf，ftrace，sysdig，dtrace，eBPF等，由于我们的线上服务器是Linux系统，且内核版本没有那么激进的使用最新的版本，所以我还是比较倾向于使用perf或者systemtap。就我个人而言，perf无疑是我的最爱了。

动态追踪的事件源根据事件类型不同，主要分为三类。静态探针， 动态探针以及硬件事件。

静态探针： 事先在代码中定义好的一类，已经编译进应用程序或内核中的探针。常见的有 tracepoints（这是散落在内核源代码中的一些hook，使能后一旦特定的代码被运行到时就会被触发）还有USDT探针。

动态探针： 事先没有在代码中定义，但是可以在运行时动态加载，比如函数返回值等。常见的有uprobes（跟踪用户态函数）和kprobes（跟踪内核态函数）。

硬件事件： 一般由PMC产生，比如intel的CPU，一般会内置统计性能的寄存器（Hardware Prefirmance Counter）。

复制代码

$ perf listList of pre-defined events (to be used in -e):branch-instructions OR cpu/branch-instructions/ [Kernel PMU event]branch-misses OR cpu/branch-misses/ [Kernel PMU event]... ...复制代码

复制代码

$ perf list | wc -l1196复制代码

复制代码

#include <sys/sdt.h>...voidmain_look(void){    ...    query = wait_for_new_query();    DTRACE_PROBE2(myserv, query__receive, query->clientname, query->msg);    process_query(query)    ...}复制代码

复制代码

$ perf probe --add 'do_sys_open filename:string'$ perf record -e probe:do_sys_open -aR -p  ${Service PID}$ perf script -i perf.data复制代码

复制代码

复制代码

# perf stat -e 'syscalls:sys_enter_*' gzip file 2>&1 | awk '$1 != 0' Performance counter stats for 'gzip file':                 1      syscalls:sys_enter_utimensat                 1      syscalls:sys_enter_unlink                 3      syscalls:sys_enter_newfstat                 1      syscalls:sys_enter_lseek             2,180      syscalls:sys_enter_read             4,337      syscalls:sys_enter_write                 3      syscalls:sys_enter_access                 1      syscalls:sys_enter_fchmod                 1      syscalls:sys_enter_fchown            ...       2.309268546 seconds time elapsed复制代码

复制代码

# time strace -c gzip file% time     seconds  usecs/call     calls    errors syscall------ ----------- ----------- --------- --------- ---------------- 67.69    0.125751          29      4337           write 27.36    0.050826          23      2180           read  4.12    0.007661        7661         1           unlink  0.20    0.000377          94         4           openat  0.12    0.000231          77         3         3 access  0.08    0.000157          22         7           close  ...------ ----------- ----------- --------- --------- ----------------100.00    0.185767                  6568         4 totalreal    0m2.919suser    0m0.669ssys    0m2.263s复制代码

复制代码

复制代码

$ perf record -e block:block_rq_issue -ag -p ${Service PID}$ perf report -i perf.dataSamples: 105  of event 'block:block_rq_issue', Event count (approx.): 105  Children      Self  Trace output-    0.95%     0.95%  8,0 R 0 () 24895224 + 1024 [python]     0     __GI___libc_read     tracesys     sys_read     vfs_read     do_sync_read     xfs_file_aio_read     xfs_file_buffered_aio_read     generic_file_aio_read     page_cache_async_readahead   ondemand_readahead     __do_page_cache_readahead     ... ...复制代码

复制代码

Samples: 21  of event 'cpu-clock', Event count (approx.): 5250000  Children      Self  Command  Shared Object        Symbol-   76.19%     0.00%  python   [kernel.vmlinux]     [k] system_call   - system_call      - 28.57% sys_recvfrom           SYSC_recvfrom         - sock_recvmsg            + 23.81% inet_recvmsg            - 4.76% security_socket_recvmsg                 selinux_socket_recvmsg                 sock_has_perm                 avc_has_perm_flags      + 23.81% sys_sendto      + 19.05% sys_shutdown      + 4.76% sys_newstat复制代码

复制代码

复制代码

复制代码

复制代码

复制代码

复制代码

void longa(){  int i,j;  for(i = 0; i < 10000000000000000; i++)  j=i;}void foo1(){  int i;  for(i = 0; i< 1000; i++)     longa();}int main(void){  foo1();}复制代码

编译后使用一下 perf stat

复制代码

$ perf stat ./a.out Performance counter stats for './a.out':      30249.723058      task-clock (msec)         #    1.000 CPUs utilized               150      context-switches          #    0.005 K/sec                 2      cpu-migrations            #    0.000 K/sec               113      page-faults               #    0.004 K/sec   <not supported>      cycles   <not supported>      instructions   <not supported>      branches   <not supported>      branch-misses      30.260523538 seconds time elapsed复制代码

复制代码

复制代码

复制代码

git clone --depth=1 https://github.com/brendangregg/FlameGraphperf record -F 99 -a -g -- sleep 30; ./FlameGraph/jmapsperf script > out.stacks01cat out.stacks01 | ./FlameGraph/stackcollapse-perf.pl | grep -v cpu_idle | /    ./FlameGraph/flamegraph.pl --color=java --hash > out.stacks01.svg复制代码

就在前不久，一阵急促的短信报警涌来，是线上服务器的load告警了，我开始扫码登陆服务器，熟练的使用 top -c 观察着线上服务器的指标。

大致现象我没有截图，口述一下吧，有2个服务的cpu使用率达到300%，wa有些高，我怀疑到是程序bug了疯狂读磁盘。于是使用iotop，查看io情况，可以看到总体的写磁盘速度是 135M/s 。而读请求几乎是0 ，这是怎么回事，这几个服务在疯狂写数据？不应该吧，这几个服务似乎没有这么大的写磁盘需求啊，如果有，应该就是日志了。在看日志前，先 perf record -ag -p ${Service Pid} 记录服务的状态。查看了应用服务的日志，消息队列似乎处理出错了，日志量巨大且繁杂，各种日志都有。到底哪里有问题呢？虽然已经定位到故障可能和消息队列有关，但是还不能确定是哪里的问题。

中断 perf record 后，我利用上面提到的方法，导出火焰图。

可以看到应用程序主要在做抛异常、网络相关调用、gc、写磁盘的操作。除了已知的操作外，问题服务的其余大量操作都集中在网络的数据包收发上，再结合之前看到消息队列的相关报错，应该定位是网络连接消息队列出的问题，应该消息队列连不上了，而代码有重试机制。

根据猜测，再到日志中找线索，果然是这个问题。如果是在大海般的日志中捞出有用的日志信息可能还需要些时间吧，这里需要提一下，传统的埋点多了不好，少了也不好，总归是比较难以权衡的。（因为该java服务没有开启PreserveFramePointer，所以看不到java代码级的调用）于是很快的完成了故障的定位，接下来就好办了，哪里有问题治哪里。

PS：perf 和 systemtap 的使用我这里只是很粗浅的介绍了一下，大神brendan gregg有详细博客去介绍动态追踪的每一个细节。开源社区也有很多动态追踪的扩展，如春哥在OpenResty的性能追踪上有很多十分赞的工具，同时我表示十分赞叹OpenResty的强大。我在动态追踪的路上还是一个初级学习者，远远比不上春哥等大神级别的人物，如果有什么错误也请指正。