天天看點

使用 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]](

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 社群的所有工作]

繼續閱讀