本文翻譯自 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]: 36433
Tracepoint 參數可以通過
args
來擷取。這裡我使用了
ksym()
bpftrace
函數來擷取對應位址的核心符号名。
更多的示例和資訊
我在 LSFMM (
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 會很有好處。最後我的郵箱是 [email protected]。
[感謝 Alastair Robertson 建立了 bpftrace, 以及這五年來在 bpftrace, BCC, 和 BPF 社群的所有工作]