使用 bpftrace 分析内核

本文翻译自 Brendan Gregg 的 Kernel analysis with bpftrace

在 2019 Linux Storage, Filesystem, and Memory-Management Summit(LSFMM) 峰会期间，我发表一篇关于 BPF observability 的演讲，其中包括我在 Netflix 生产服务器上使用 bpftrace debug 的问题的过程。这篇文章中，我会为内核的开发者们提供一节 bpftrace 速成课程，帮助他们更便利的分析代码的方法。

最近我和其他开发者讨论 tcp_sendmsg()，他们担心一些比较大的报文（例如 100 MB）会导致失败。100MB？？我怀疑 Netflix 在生产环境中是否发送了这么大的报文。大家可能很熟悉这个函数原型(net/ipv4/tcp.c)：

int tcp_sendmsg(struct sock *sk, struct msghdr *msg, size_t size);

bpftrace 已经安装在 Netflix （也包括其他的公司）的生产服务器，所以我使用 ssh 登录到一台比较繁忙的服务器上去查看10秒内报文大小的分散情况：

# bpftrace -e 'k:tcp_sendmsg { @size = hist(arg2); } interval:s:10 { exit(); }'
    Attaching 2 probes...

    @size:
[4, 8)                25 |                                                    |
[8, 16)               74 |                                                    |
[16, 32)               5 |                                                    |
[32, 64)           13603 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[64, 128)           2527 |@@@@@@@@@                                           |
[128, 256)            21 |                                                    |
[256, 512)           181 |                                                    |
[512, 1K)           1587 |@@@@@@                                              |
[1K, 2K)            2992 |@@@@@@@@@@@                                         |
[2K, 4K)            9367 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@                 |
[4K, 8K)           12461 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@     |
[8K, 16K)            995 |@@@                                               |
[16K, 32K)          1977 |@@@@@@@                                             |
[32K, 64K)           428 |@                                                   |
[64K, 128K)           14 |                                                    |
[128K, 256K)           2 |                                                    |

最大的报文在128到256KB 的区间中。这里使用了 kprobe(“k”) 跟踪 tcp_sendmsg()，并保存 arg2(size) 的直方图到一个名为 “@size”(名字不重要，只是注释) 的 BPF map 中。10s后会触发一个定时事件并退出，此时会把所有的 BPF map 中的内容打印出来。

是否会发生错误呢？

# bpftrace -e 'kr:tcp_sendmsg { @retvals[retval > 0 ? 0 : retval] = count(); }
interval:s:10 { exit(); }' Attaching 2 probes... @retvals[0]: 49794

没有错误发生。这里我用的是 kretprobe(“kr”)，统计 retval 的值是否为负数错误代码，或是报文大小。我不关心具体的报文大小，所以使用了一个三元操作符将所有的正数返回值设为0。

bpftrace 可以让你能够快速发现这些问题，并且在生产环境中，不需要 debuginfo(Netflix 通常也不会安装)。现在来看，在 Netflix 的 workload 下，不太会遇到大报文 tcp_sendmsg() 的问题。

更多的单行命令

此前的 tcp_sendmsg() 问题已经展示了  bpftrace 的内核分析能力。这里有一些其他的单行命令来展示  bpftrace 的能力，你可以把这些换成其他的内核函数：

获取 tcp_sendmsg() szie 大于 8192 字节的所有事件:

bpftrace -e 'k:tcp_sendmsg /arg2 > 8192/ { printf("PID %d: %d bytes\n", pid, arg2); }'

获取每个进程(PID 和 comm)的请求大小的直方图：

bpftrace -e 'k:tcp_sendmsg { @size[pid, comm] = hist(arg2); }'

返回值出现频率统计：

 bpftrace -e 'kr:tcp_sendmsg { @return[retval] = count(); }'

获取每秒的统计：事件数，平均大小，和总字节数：

bpftrace -e 'k:tcp_sendmsg { @size = stats(arg2); } interval:s:1 { print(@size); clear(@size); }'

统计调用栈：

bpftrace -e 'k:tcp_sendmsg { @[kstack] = count(); }'

统计调用栈，深度为3：

bpftrace -e 'k:tcp_sendmsg { @[kstack(3)] = count(); }'

获取函数调用延时的直方图，纳秒级：

bpftrace -e 'k:tcp_sendmsg { @ts[tid] = nsecs; } kr:tcp_sendmsg /@ts[tid]/ { @ns = hist(nsecs - @ts[tid]); delete(@ts[tid]); }'

最后一个例子在探测点（线程 ID 作为主键）保存时间戳，并在另外一个探测点获得这个时间戳。这个模式可以用来计算各种延时。

data 结构体

这些例子中缺少一个重要的功能：结构体探测。再看下这个函数原型：

int tcp_sendmsg(struct sock *sk, struct msghdr *msg, size_t size);

bpftrace 为 kprobe 函数参数提供了  arg0-argN 机制，按照函数调用的约定，将它们映射到对应的寄存器（例如在 x86_64 中，arg2 为 %rdx ）。因为  bpftrace 可以读取 OS 中安装的内核头文件，通过引入正确的头文件并转化好参数，可以访问结构体中的数据：

#include <net/sock.h>     [...]
            $sk = (struct sock *)arg0;

这个 bpftrace 的例子，可以打印出  tcp_sendmsg() 的地址信息，大小和返回值。例如：

# ./tcp_sendmsg.bt 
    Attaching 2 probes...
    10.0.0.65       49978 -> 52.37.243.173   443  : 63 bytes, retval 63
    127.0.0.1       58566 -> 127.0.0.1       22   : 36 bytes, retval 36
    127.0.0.1       22    -> 127.0.0.1       58566: 36 bytes, retval 36
    [...]

tcp_sendmsg.bt 源码：

#!/usr/local/bin/bpftrace 
    #include <net/sock.h> 
    k:tcp_sendmsg
    {
	    @sk[tid] = arg0;
	    @size[tid] = arg2;
    }
    
    kr:tcp_sendmsg
    /@sk[tid]/
    {
	    $sk = (struct sock *)@sk[tid];
	    $size = @size[tid];
	    $af = $sk->__sk_common.skc_family;
	    if ($af == AF_INET) {
		    $daddr = ntop($af, $sk->__sk_common.skc_daddr);
		    $saddr = ntop($af, $sk->__sk_common.skc_rcv_saddr);
		    $lport = $sk->__sk_common.skc_num;
		    $dport = $sk->__sk_common.skc_dport;
		    $dport = ($dport >> 8) | (($dport << 8) & 0xff00);
		    printf("%-15s %-5d -> %-15s %-5d: %d bytes, retval %d\n",
		        $saddr, $lport, $daddr, $dport, $size, retval);
	    } else {
		    printf("IPv6...\n");
	    }
	    delete(@sk[tid]);
	    delete(@size[tid]);
    }

在 kprobe 中， sk 和  size 保存在每线程ID 的 map 中，这样可以在  tcp_sendmsg() kretprobe 返回时获取这些信息。kretprobe 转换  sk 并打印其中的信息，如果这是一个 IPv4 报文，使用  bpftrace 函数  ntop() 将地址转换为字符串。目的端口从网络序转化为主机序。简单起见，我跳过了 IPv6，不过你可以通过添加代码来处理 IPv6 的情况(ntop() 也支持 IPv6 地址)。

当前正在为 bpftrace 工具开发支持 BPF Type Format(BTF)，这样会带来很多好处，例如在内核头文件没有结构体定义的情况下也可以看到。

进阶示例

目前为止，我已经演示了简单直接的跟踪能力。接下来我会展示 off-CPU 优化作为进阶示例。

对于 task 的 CPU 优化通常是比较容易的：我可以对栈采样，检查 performance-monitoring counters(PMCs) 和 model-specific registers(MSRs)，可以确定当前在 CPU 上运行的 task，以及为什么会变慢。Off-CPU 优化，换句话说，也是有一些问题的。我可以找到在上下文切换时阻塞的栈，但是它们经常会被其他东西阻塞(select(), epoll(), 或者 lock)。我需要知道这些东西是什么。

BPF 也为这个问题提供了解决办法：保存调用栈，并可以后续获取分析的能力（我很希望 DTrace 去做，可惜它做不到）。下面是 bpftrace 的解决方案，显示了进程名称，阻塞的栈，唤醒进程的栈，和微秒级别阻塞时间的直方图：

# ./offwake.bt
   Attaching 4 probes...
   Tracing off-CPU time (us) with waker stacks. Ctrl-C to end.
   ^C
[...]

   @us[ssh,
       finish_task_switch+1
       schedule+44
       schedule_hrtimeout_range_clock+185
       schedule_hrtimeout_range+19
       poll_schedule_timeout+69
       do_select+1378
       core_sys_select+471
       sys_select+183
       do_syscall_64+115
       entry_SYSCALL_64_after_hwframe+61
   ,
       try_to_wake_up+1
       pollwake+115
       __wake_up_common+115
       __wake_up_common_lock+128
       __wake_up_sync_key+30
       sock_def_readable+64
       tcp_rcv_established+1281
       tcp_v4_do_rcv+144
       tcp_v4_rcv+2423
       ip_local_deliver_finish+98
       ip_local_deliver+111
       ip_rcv_finish+297
       ip_rcv+655
       __netif_receive_skb_core+1074
       __netif_receive_skb+24
       netif_receive_skb_internal+69
       napi_gro_receive+197
       ieee80211_deliver_skb+200
       ieee80211_rx_handlers+5376
       ieee80211_prepare_and_rx_handle+1865
       ieee80211_rx_napi+914
       iwl_mvm_rx_rx_mpdu+1205
       iwl_mvm_rx+77
       iwl_pcie_rx_handle+571
       iwl_pcie_irq_handler+1577
       irq_thread_fn+38
       irq_thread+325
       kthread+289
       ret_from_fork+53
]:
[64, 128)              1 |@@                                                  |
[128, 256)             1 |@@                                                  |
   [256, 512)             1 |@@                                                  |
[512, 1K)              1 |@@                                                  |
[1K, 2K)               4 |@@@@@@@@@@                                          |
[2K, 4K)              10 |@@@@@@@@@@@@@@@@@@@@@@@@@@@                         |
[4K, 8K)              18 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   |
[8K, 16K)              3 |@@@@@@@@                                            |
[16K, 32K)            16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@         |
[32K, 64K)            19 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[64K, 128K)            3 |@@@@@@@@                                            |

我只保留了一对栈的输出结果。 这里可以看到 ssh 进程阻塞在  select()  中，而唤醒进程的栈则在等待一个网络报文。 从直方图可以看出这个 offcpu/waker 路径中的微秒级别的时延。

其中 offwake.bt 的源码：

#!/usr/local/bin/bpftrace 
   #include <linux/sched.h> 
   BEGIN
   {
	   printf("Tracing off-CPU time (us) with waker stacks. Ctrl-C to end.\n");
   }
   
   kprobe:try_to_wake_up
   {
	   $p = (struct task_struct *)arg0;
	   @waker[$p->pid] = kstack;
   }
   
   kprobe:finish_task_switch
   {
	   $prev = (struct task_struct *)arg0;
   
	   // record timestamp of sleeping task:
	   @ts[$prev->pid] = nsecs;
   
	   if (@ts[tid]) {
		   $offcpu_us = (nsecs - @ts[tid]) / 1000;
		   @us[comm, kstack, @waker[tid]] = hist($offcpu_us);
		   delete(@ts[tid]);
		   delete(@waker[tid]);
	   }
   }
   
   END
   {
	   clear(@waker);
	   clear(@ts);
   }

这里  try_to_wake_up()  的内核栈会按照它的 task ID 保存起来，之后会从  finish_task_switch()  中获取。 这就是一个简易的  bpftrace  版本的 offwaketime BCC 工具，包含在内核代码  samples/bpf/offwaketime*  中。

在我之前的 Performance@Scale talk( slides   [Slideshare] ,  video )演讲中，我介绍过这个问题和相应的 BPF 解决方案，并且演示了如何将调用栈可视化为火焰图。 有时候你需要知道是谁唤醒了那个唤醒者，以及是谁唤醒了他们，等等这些。 通过遍历唤醒链，我可以构建出一个 链路图 来展示调用延迟中对应的源代码（通常是来自中断）。

Tracepoints

上面的例子都是在使用 kprobes，它们会随着内核的升级而更新。 对于  bpftrace  而言，tracepoints 相对于 kprobe 更合适一点，尽管它们也会随着内核版本而发生变化，这样也会比 kprobe 更好，kprobe 随时都可能发生变化，甚至会被 inline 而消失。 不过有一些 kprobe 更稳定，特别是内核内部的一些接口，例如 VFS， struct file_operations ,  struct proto  等等。

一个简单的例子，展示了  timer:timer:hrtimer_start  tracepint 所提供的参数：

# bpftrace -lv 't:timer:hrtimer_start'
   tracepoint:timer:hrtimer_start
       void * hrtimer;
       void * function;
       s64 expires;
       s64 softexpires;

每个函数的参数调用频率：

# bpftrace -e 't:timer:hrtimer_start { @[ksym(args->function)] = count(); }'
   Attaching 1 probe...
   ^C
   
   @[sched_rt_period_timer]: 6
   @[watchdog_timer_fn]: 16
   @[intel_uncore_fw_release_timer]: 290
   @[it_real_fn]: 376
   @[hrtimer_wakeup]: 12301
   @[tick_sched_timer]: 36433

Tracepoint 参数可以通过 args 来获取。这里我使用了  ksym() bpftrace 函数来获取对应地址的内核符号名。

更多的示例和信息

我在 LSFMM (slides [Slideshare]) 依次介绍了 Netflix 生产环境的例子。大部分例子可以在 bpftrace 仓库的 tools 中找到。在 LSFMM 中，我也预先演示了为一本 BPF 分析书籍（Addison-Wesley 初版）所编写的其他工具；这些都可以在 BPF 书籍的页面上找到。

你打算自己尝试一下 bpftrace ，可以参考 INSTALL，并获取最新的版本: 0.9.1 或更新的版本。不同的发行版有不同的安装包，Netflix 和 Facebook 有它们内部自己的安装包，或者你可以从源码构建。 bpftrace 现在依赖 LLVM 和 Clang(BCC 同样依赖)，将来的版本尝试将它们作为一个可选项。

也可以看看 bpftrace 速查表了解这门语言，还有完整的手册。

那么 perf 和 ftrace 呢？

我会使用最合适的工具，并不局限于 bpftrace ，很多时候我会使用 perf 或者 ftrace，例如：

• 统计多个函数的调用频率：使用 ftrace，它可以很快的初始化。BPF kprobe 使用 multi-attach perf_event_open() 会更快，现在还在开发；

• 函数调用流程跟踪：使用 ftrace function graphing 功能；

• PMC 统计：perf；

• CPU 周期采样并包含时间戳：perf，因为 perf.data 输出格式优化得很好；

对于最后一个例子而言，有时候我需要每个采样点的时间戳，大部分时候并不需要，这时我会使用 bpftrace 。例如按照 99HZ 的频率对内核栈进行采样：

# bpftrace -e 'profile:hz:99 { @[kstack] = count(); }'

结论

时代在变化，现在 Linux 拥有了一个进阶的跟踪工具 bpftrace ，基于 eBPF 和 Linux全新开发，并在 Netflix 和其他公司的真实生产环境中解决了各种问题。通过简单的单行命令或者其他的小工具，你可以用各种方式来发现你自己代码中的问题。这篇文章已经展示了很多这种例子。

如果你想要了解你的代码在 Netflix 生产环境是如何运行的，可以将你的 bpftrace 程序通过 email 发送给我，我可以将结果回复给你（在不会透露公司或者客户的情况下）。如果它能够发现 Linux 在我们的 workload 下，有哪些低效的地方，并且能够提供修复方法，这对于 Netflix 会很有好处。最后我的邮箱是 [email protected]。

[感谢 Alastair Robertson 创建了 bpftrace, 以及这五年来在 bpftrace, BCC, 和 BPF 社区的所有工作]