本文翻译自 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]](http://www.slideshare.net/brendangregg/linux-bpf-superpowers), 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]: 36433Tracepoint 参数可以通过 args 来获取。这里我使用了 ksym() bpftrace 函数来获取对应地址的内核符号名。
更多的示例和信息
我在 LSFMM (slides [[Slideshare]](https://www.slideshare.net/brendangregg/lsfmm-2019-bpf-observability-143092820)) 依次介绍了 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 社区的所有工作]
