本文翻译自 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 中,sksize 保存在每线程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 会很有好处。最后我的邮箱是 bgregg@netflix.com。

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