Trace - 一文读懂tracepoint

tracepoint是Linux内核静态定义的一些调试点，它分布于内核的各个子系统中，然而在实际工作中可能很多人并没有用过这个功能，或者对它没有太多了解，那么就通过本文一起来了解下tracepoint吧。tracepoint是内核预先定义的静态探测点，可以用于挂载钩子函数来做trace。当没有钩子函数时，它几乎没有损耗，只有挂载了钩子函数才会真正启用trace功能。这个钩子函数可以由开发者编写内核module来实现，并且需要在钩子函数中获取我们调试所需要的信息并导出到用户态，这样我们就可以获取内核运行时的信息了。

直接使用tracepoint并不是那么的容易，因此内核提供了event trace功能。event trace的实现依赖于tracepoint机制，内核提前帮我们实现了钩子函数并挂到tracepoint上，当使能一个event trace时，它会输出内容到ftrace ringbuffer中，这样就可以获取到内核运行信息了。当然有时候event trace并不符合我们的需要，那么此时就只得自己编写module来实现需求了。

如何查看tracepoint

查看tracepoint有多种方式，比如简单的通过debugfs查看：

/sys/kernel/debug/tracing/events/

系统中定义的tracepoint都在该events目录中，比如查看block子系统中的tracepoint：

ls /sys/kernel/debug/tracing/events/block/

block_bio_backmerge  block_bio_complete    block_bio_queue  block_dirty_buffer  block_plug      block_rq_complete  block_rq_issue  block_rq_requeue  block_split         block_unplug  filter

block_bio_bounce     block_bio_frontmerge  block_bio_remap  block_getrq         block_rq_abort  block_rq_insert    block_rq_remap  block_sleeprq     block_touch_buffer  enable

除了这种基础方法，还可以使用perf来查看：

perf list tracepoint

这个命令会打印出来所有的tracepoint。

对于支持bpf的内核版本，还可以bpftrace来查看：

bpftrace -l tracepoint:*

tracepoint数据格式

每个tracepoint都会按照自己定义的格式来输出信息，可以在用户态来查看tracepoint记录的内容格式，比如：

cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_open/format

name: sys_enter_open

ID: 475

format:

        field:unsigned short common_type;       offset:0;       size:2; signed:0;

        field:unsigned char common_flags;       offset:2;       size:1; signed:0;

        field:unsigned char common_preempt_count;       offset:3;       size:1; signed:0;

        field:int common_pid;   offset:4;       size:4; signed:1;



        field:int nr;   offset:8;       size:4; signed:1;

        field:const char * filename;    offset:16;      size:8; signed:0;

        field:int flags;        offset:24;      size:8; signed:0;

        field:umode_t mode;     offset:32;      size:8; signed:0;



print fmt: "filename: 0x%08lx, flags: 0x%08lx, mode: 0x%08lx", ((unsigned long)(REC->filename)), ((unsigned long)(REC->flags)), ((unsigned long)(REC->mode))

格式信息可以用来解析二进制的trace流数据，也可以用这个格式中的内容来做trace filter，利用filter功能指定过滤条件后，将只会看到过滤后的事件数据。格式信息中包括两部分内容，第一部分是通用的格式，这类通用字段都带有common前缀，这是所有的tracepoint event都具备的字段。第二部分就是各个tracepoint所自定义的格式字段了，比如上面的nr，filename等等。格式信息的最后一列是tracepoint的打印内容格式，通过这个可以看到打印数据的字段来源。

如何使用tracepoint

tracepoint复用了ftrace的ringbuffer，当使能了一个tracepoint之后，可以通过cat /sys/kernel/debug/tracing/trace来查看它的输出。另外上文也有提到，还可以通过设置filter过滤事件。

举例说明，比如想要过滤所有的openat事件，指定过滤所有打开flags为0的事件：

echo flags==0 > /sys/kernel/debug/tracing/events/syscalls/sys_enter_openat/filter
echo 1 > /sys/kernel/debug/tracing/events/syscalls/sys_enter_openat/enable
cat /sys/kernel/debug/tracing/trace_pipe

如果想要把过滤条件清除，只需要写入0到指定的filter即可：

echo 0 > /sys/kernel/debug/tracing/events/syscalls/sys_enter_openat/filter

到这里我们就掌握了tracepoint的基本使用方法。

再举一个例子，想要跟踪sched_switch这个tracepoint点，设置过滤条件prev_pid和next_pid都为1的进程。

echo "(prev_pid == 1 || next_pid == 1)" >  /sys/kernel/debug/tracing/events/sched/sched_switch/filter
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
cat /sys/kernel/debug/tracing/trace_pipe

输出的示例如下：

        <idle>-0     [003] d... 1412218.564007: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=systemd next_pid=1 next_prio=120
         systemd-1     [003] d... 1412218.564109: sched_switch: prev_comm=systemd prev_pid=1 prev_prio=120 prev_state=D ==> next_comm=YDEdr next_pid=2184088 next_prio=120
          <idle>-0     [003] d... 1412222.984930: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=systemd next_pid=1 next_prio=120
         systemd-1     [003] d... 1412222.985006: sched_switch: prev_comm=systemd prev_pid=1 prev_prio=120 prev_state=D ==> next_comm=swapper/3 next_pid=0 next_prio=120
          <idle>-0     [002] d... 1412222.987441: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=systemd next_pid=1 next_prio=120
         systemd-1     [002] d... 1412222.987513: sched_switch: prev_comm=systemd prev_pid=1 prev_prio=120 prev_state=D ==> next_comm=YDService next_pid=2184066 next_prio=120

可以看到对应的prev_id或者next_pid为1时才会输出

perf中使用tracepoint

借助perf工具，可以跟踪tracepoint事件，前文已经介绍了如何用perf查看tracepoint，假如想要跟踪网络驱动收发包的情况：

perf record -e 'net:netif_rx','net:net_dev_queue' -a   -- sleep 10

记录10秒后，使用：

perf script

来查看记录到的信息，截取部分示例如下：

         swapper     0 [000] 18846825.547490: net:net_dev_queue: dev=eth0 skbaddr=0xffff881fe98e0800 len=58
           fping 13009 [000] 18846825.547921: net:net_dev_queue: dev=eth0 skbaddr=0xffff881fe98e0e00 len=98
           fping 13009 [000] 18846825.557986: net:net_dev_queue: dev=eth1 skbaddr=0xffff881fe98e0e00 len=98

bpftrace中使用tracepoint

bpftrace工具也可以跟踪tracepoint事件，前面已经提到，查看bpftrace可跟踪的事件，可以通过：

bpftrace -l tracepoint:*

这里需要掌握的更关键的一点，是如何在bpftrace脚本中使用tracepoint提供的数据，这里可以通过-v选项查看bpftrace可以访问的tracepoint的字段。比如想要跟踪openat系统调用，如果代码中想要获取tracepoint中的一些字段信息做处理，那么就要知道这个tracepoint可以使用哪些字段。那么可以这么操作：

bpftrace -v -l tracepoint:syscalls:sys_enter_openat 
tracepoint:syscalls:sys_enter_openat
    int __syscall_nr;
    int dfd;
    const char * filename;
    int flags;
    umode_t mode;

命令的输出显示了该tracepoint中支持访问的字段，假如我们想要打印每次open文件时的filename，那么示例如下：

bpftrace -e 'tracepoint:syscalls:sys_enter_openat {@[comm]=str(args->filename);} END {print(@); clear(@);}'

执行一段时间后，中断执行后输出：

Attaching 2 probes...

@[awk]: /dev/null
@[cat]: /proc/meminfo
@[dbus-daemon]: /proc/3713504/cmdline
@[grep]: /usr/lib/locale/en_US.utf8/LC_CTYPE
@[lsblk]: device/type
@[sh]: /usr/lib/locale/en_US.utf8/LC_CTYPE
@[sshd]: /etc/selinux/targeted/contexts/openssh_contexts
@[sssd_nss]: /etc/passwd
@[systemd]: /proc/3713493/cgroup

这里需要掌握的就是如何使用字段，在bpftrace脚本中可以直接利用args->filename来引用tracepoint中的filename字段。

systemtap中使用tracepoint

systemtap作为一个trace工具，同样对内核的tracepoint提供了支持，可以用下面的命令来查看可以用的tracepoint点：

stap -L 'kernel.trace("*")'

举例跟踪sched:sched_switch事件，查看-L列出的信息：

kernel.trace("sched:sched_switch") $preempt:bool $prev:struct task_struct* $next:struct task_struct*

这个命令也同样列举除了能够引用的变量：$preempt、 $prev和 $next，这三个变量在systemtap脚本中可以直接引用，例如：

probe kernel.trace("sched:sched_switch")

{

    printf("prev pid: %d next pid:%d\n", $prev->pid, $next->pid);

}

如何选择tracepoint

前面介绍了tracepoint怎么用，这只是一个基础，而更重要的是在遇到不同场景下，如何找到合适的tracepoint帮助我们解决问题。问题的根本还是在于对Linux内核的了解，这就需要掌握内核提供的的tracepoint具体作用是什么，在什么情况下会运行到。还是那句话，"Read the fucking source code！"作为抛砖引玉，本文将介绍如何在代码中查找tracepoint位置，后续的深入就得靠个人慢慢修行了。

先来看代码上怎么找tracepoint的定义，现在的内核已经不再直接使用tracepoint的宏定义来实现了，而更倾向于使用TRACE_EVENT，它会对tracepoint做一层封装。直接内核代码中搜索：

grep –rnw  TRACE_EVENT

这里只是定义一个tracepoint相关的数据结构，那么放置一个tracepoint到内核代码的某个位置时直接使用：

trace_tracepoint_name

比如定义一个foo_bar：

TRACE_EVENT(foo_bar, ...)

在放置时，就应该使用：

trace_foo_bar(...);

再举个例子，假如想要查找tracepoint:sched_switch的位置：

grep   -rn "trace_sched_switch" .

./kernel/sched/core.c:5070:             trace_sched_switch(preempt, prev, next);

查看的方法大致类似，通过搜索代码来找到tracepoint的位置，进而掌握在什么情况下可以使用该tracepoint来进行跟踪。这个过程我也同样在持续学习中。