動態追蹤技術（四）：基於 Linux bcc/BPF 實現 Go 程式動態追蹤

這是一個建立於 的文章，其中的資訊可能已經有所發展或是發生改變。

摘要

• 原文：Brendan Gregg's Blog :《Golang bcc/BPF Function Tracing》，31 Jan 2017
• 引子：gdb、go execution tracer、GODEBUG、gctrace、schedtrace
• 一、gccgo Function Counting
• 二、Go gc Function Counting
• 三、Per-event invocations of a function
• 四、Interface Arguments
• 五、Function Latency
• 六、總結
• 七、Tips：構建 LLVM 和 Clang 開發工具庫

在這篇文章中，我將迅速調研一種跟蹤的 Go 程式的新方法：基於 Linux 4.x eBPF 實現動態跟蹤。如果你去搜尋 Go 和 BPF，你會發現使用 BPF 介面的 Go 語言介面（例如，gobpf）。這不是我所探索的東西：我將使用 BPF 工具實現 Go 應用程式的效能分析和調試。

目前已經有多種調試和追蹤 Go 程式的方法，包括但不限於：

• gdb
• go execution tracer ：用於高層異常和阻塞事件

Go execution tracer. (import "runtime/trace")

• GODEBUG （一個跨平台的Go程式調試工具）、 gctrace 和 schedtrace

BPF 追蹤以做很多事，但都有自己的優點和缺點，接下來將詳細說明。首先我從一個簡單的 Go 程式開始（ hello.go）

package mainimport "fmt"func main() {        fmt.Println("Hello, BPF!")}

一、gccgo Function Counting

我開始會使用 gccgo 編譯，然後使用 Go gc 編譯器 。（區別：gccgo 可以產生最佳化後的二進位檔案，但是基於老版本的 Go。）

## 編譯$ gccgo -o hello hello.go$ ./helloHello, BPF!

現在我將使用 bcc 工具的 funccount 來動態跟蹤和計數所有以 “fmt.” 開頭的 Go 庫函數調用，在另一個終端重新運行 Hello 程式效果如下：

# funccount 'go:fmt.*'Tracing 160 functions for "go:fmt.*"... Hit Ctrl-C to end.^CFUNC                                    COUNTfmt..import                                 1fmt.padString.pN7_fmt.fmt                   1fmt.fmt_s.pN7_fmt.fmt                       1fmt.WriteString.pN10_fmt.buffer             1fmt.free.pN6_fmt.pp                         1fmt.fmtString.pN6_fmt.pp                    1fmt.doPrint.pN6_fmt.pp                      1fmt.init.pN7_fmt.fmt                        1fmt.printArg.pN6_fmt.pp                     1fmt.WriteByte.pN10_fmt.buffer               1fmt.Println                                 1fmt.truncate.pN7_fmt.fmt                    1fmt.Fprintln                                1fmt.$nested1                                1fmt.newPrinter                              1fmt.clearflags.pN7_fmt.fmt                  2Detaching...

Neat! 輸出結果中包含該程式的 fmt.Println() 函數調用。

我不需要進入任何特殊的模式才能實現這個效果，對於一個已經在啟動並執行 Go 應用我可以直接開始測量而不需要重啟進程。 So how does it even work? 這要歸功於 uprobes ，Linux 3.5 新增的特性，詳見Linux uprobes: User-Level Dynamic Tracing 。

It overwrites instructions with a soft interrupt to kernel instrumentation, and reverses the process when tracing has ended.

gccgo 編譯的輸出提供一個標準的符號表用於函數尋找。在這種情況下，我利用 libgo 當測量工具（假定“lib”在“go:”之前），作為 gccgo 發出的一個二進位動態連結程式庫（libgo 包含 fmt 包）。uprobes 可以串連到已經啟動並執行進程，或者像我現在一樣作為一個二進位庫，捕捉所有調用自己的進程。

為了提高效率，我在核心上下文中進行函數調用計數，只將計數發送到使用者空間。例如：

$ file hellohello: ELF 64-bit LSB executable, x86-64, version 1 (SYSV), dynamically linked, interpreter /lib64/ld-linux-x86-64.so.2, for GNU/Linux 2.6.32, BuildID[sha1]=4dc45f1eb023f44ddb32c15bbe0fb4f933e61815, not stripped$ ls -lh hello-rwxr-xr-x 1 bgregg root 29K Jan 12 21:18 hello$ ldd hello    linux-vdso.so.1 =>  (0x00007ffc4cb1a000)    libgo.so.9 => /usr/lib/x86_64-linux-gnu/libgo.so.9 (0x00007f25f2407000)    libgcc_s.so.1 => /lib/x86_64-linux-gnu/libgcc_s.so.1 (0x00007f25f21f1000)    libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007f25f1e27000)    /lib64/ld-linux-x86-64.so.2 (0x0000560b44960000)    libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007f25f1c0a000)    libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007f25f1901000)$ objdump -tT /usr/lib/x86_64-linux-gnu/libgo.so.9 | grep fmt.Println0000000001221070 g     O .data.rel.ro   0000000000000008              fmt.Println$descriptor0000000000978090 g     F .text  0000000000000075              fmt.Println0000000001221070 g    DO .data.rel.ro   0000000000000008  Base        fmt.Println$descriptor0000000000978090 g    DF .text  0000000000000075  Base        fmt.Println

這些內容看起來非常像一個編譯過的 C 語言二進位程式，因此可以使用包括 bcc/BPF在內的許多現有的調試工具和追蹤器觀測。相對於測量即時編譯的運行時要簡單得多（例如 Java 和 Node.js）。到目前為止，這個例子唯一的麻煩事函數名稱中可能包含非標準的字元，例如“.”。

funccount 提供 -p 選項來匹配進程號（PID），-i 選項來控制輸出頻率。它目前能夠同時處理 1000 個探測點，匹配 “fmt.*” 時運行正常，但是匹配 libgo 的所有函數就出現異常。諸如此類的問題在 bcc/BPF 中還有不少，我們需要尋找其它的方法來處理。

# funccount 'go:*'maximum of 1000 probes allowed, attempted 21178

二、Go gc Function Counting

使用 Go 語言的 gc 編譯器實現 fmt 函數調用計數：

$ go build hello.go$ ./helloHello, BPF!

# funccount '/home/bgregg/hello:fmt.*'Tracing 78 functions for "/home/bgregg/hello:fmt.*"... Hit Ctrl-C to end.^CFUNC                                    COUNTfmt.init.1                                  1fmt.(*fmt).padString                        1fmt.(*fmt).truncate                         1fmt.(*fmt).fmt_s                            1fmt.newPrinter                              1fmt.(*pp).free                              1fmt.Fprintln                                1fmt.Println                                 1fmt.(*pp).fmtString                         1fmt.(*pp).printArg                          1fmt.(*pp).doPrint                           1fmt.glob.func1                              1fmt.init                                    1Detaching...

你依然能夠追蹤到 fmt.Println() ，這個二進位程式與 libgo 有所不同：包含該函數的是一個 2M 的靜態庫（而非動態庫的 29K ）。另一個區別就是函數名稱包含更多特殊字元，例如 "*", "(",等等，我懷疑如果不能修正處理的haul將影響其它調試器（例如 bcc 追蹤器）。

$ file hellohello: ELF 64-bit LSB executable, x86-64, version 1 (SYSV), statically linked, not stripped$ ls -lh hello-rwxr-xr-x 1 bgregg root 2.2M Jan 12 05:16 hello$ ldd hello    not a dynamic executable$ objdump -t hello | grep fmt.Println000000000045a680 g     F .text  00000000000000e0 fmt.Println

三、Per-event invocations of a function

3.1 gccgo Function Tracing

現在我將嘗試使用 Sasha Goldshtein 的追蹤工具，也是基於 bcc，用來查看每一個函數呼叫事件。我將回到 gccgo，使用一個非常簡單的樣本程式（ from the go tour ），functions.go:

package mainimport "fmt"func add(x int, y int) int {    return x + y}func main() {    fmt.Println(add(42, 13))}

追蹤 add() 函數。所有參數都輸出在右側，trace 還有其他選項（協助 -h ），例如輸出時間戳記和堆棧。

\# trace '/home/bgregg/functions:main.add'PID    TID    COMM         FUNC             14424  14424  functions    main.add  #... and with both its arguments:\# trace '/home/bgregg/functions:main.add "%d %d" arg1, arg2'PID    TID    COMM         FUNC             -14390  14390  functions    main.add         42 13

3.2 Go gc Function Tracing

同樣的程式，如果使用 go build 就沒有 main.add() ? 禁用代碼嵌入（ Disabling inlining）即可。

$ go build functions.go# trace '/home/bgregg/functions:main.add "%d %d" arg1, arg2'could not determine address of symbol main.add$ objdump -t functions | grep main.add$

$ go build -gcflags '-l' functions.go$ objdump -t functions | grep main.add0000000000401000 g     F .text  0000000000000020 main.add# trace '/home/bgregg/functions:main.add "%d %d" arg1, arg2'PID    TID    COMM         FUNC             -16061  16061  functions    main.add         536912504 16

That's wrong. 參數應該是 42 和 13 而不是 536912504 和 16。
使用 gdb 查看結果如下：

$ gdb ./functions[...]warning: File "/usr/share/go-1.6/src/runtime/runtime-gdb.py" auto-loading has been declined by your 'auto-load safe-path' set to "$debugdir:$datadir/auto-load".[...](gdb) b main.addBreakpoint 1 at 0x401000: file /home/bgregg/functions.go, line 6.(gdb) rStarting program: /home/bgregg/functions[New LWP 16082][New LWP 16083][New LWP 16084]Thread 1 "functions" hit Breakpoint 1, main.add (x=42, y=13, ~r2=4300314240) at /home/bgregg/functions.go:66           return x + y(gdb) i rrax            0xc820000180 859530330496rbx            0x584ea0 5787296rcx            0xc820000180 859530330496rdx            0xc82005a048 859530698824rsi            0x10 16rdi            0xc82000a2a0 859530371744rbp            0x0  0x0rsp            0xc82003fed0 0xc82003fed0r8             0x41 65r9             0x41 65r10            0x4d8ba0 5082016r11            0x0  0r12            0x10 16r13            0x52a3c4 5415876r14            0xa  10r15            0x8  8rip            0x401000 0x401000eflags         0x206    [ PF IF ]cs             0xe033   57395ss             0xe02b   57387ds             0x0  0es             0x0  0fs             0x0  0gs             0x0  0

啟動資訊中包含一個關於 runtime-gdb.py 的警告，它非常有用：如果需要進一步深入挖掘 Go 上下文，我希望能夠修複並找出警示原因。即使沒有該資訊，gdb 依然可以輸出參數變數的值是 "x=42, y=13"。我也將它們從寄存器匯出與 x86_64 ABI（Application Binary Interface，應用程式二進位介面）對比，which is how bcc's trace reads them. From the syscall(2) man page:

       arch/ABI      arg1  arg2  arg3  arg4  arg5  arg6  arg7  Notes       ──────────────────────────────────────────────────────────────────[...]       x86_64        rdi   rsi   rdx   r10   r8    r9    -

The reason is that Go's gc compiler is not following the standard AMD64 ABI function calling convention, which causes problems with this and other debuggers.

42 和 13 沒有出現在 rdi , rsi 或者其它任何一個寄存器。原因是 Go 的 gc 編譯器不遵循標準的 AMD64 ABI 函數呼叫慣例，其它調試器也會存在這個問題。這很煩人。我猜 Go 語言的傳回值使用的是另外一種 ABI，因為它可以返回多個值，所以即使入口參數是標準的，我們仍然會遇到差異。我瀏覽了指南（Quick Guide to Go's Assembler and the Plan 9 assembly manual），看起來函數在堆棧上傳遞。這些是我們的 42 和 13：

(gdb) x/3dg $rsp0xc82003fed0:   4198477 420xc82003fee0:   13

BPF can dig these out too. As a proof of concept, I just hacked in a couple of new aliases, "go1" and "go2" for those entry arguments:

BPF 也可以挖掘這些資訊。為了驗證這一個概念，我為入口參數聲明一對新的別名“go1”和“go2” 。希望您閱讀本文的時候，我（或者其他人）已經將它加入到 bcc 追蹤工具中，最好是 "goarg1", "goarg2", 等等。

# trace '/home/bgregg/functions:main.add "%d %d" go1, go2'PID    TID    COMM         FUNC             -17555  17555  functions    main.add         42 13

四、Interface Arguments

你可以寫一個自訂的 bcc/BPF 程式來挖掘，為了處理介面參數我們可以給 bcc 的跟蹤程式添加多個別名。輸入參數是介面的樣本：

func Println(a ...interface{}) (n int, err error) {    return Fprintln(os.Stdout, a...)

$ gdb ./hello[...](gdb) b fmt.PrintlnBreakpoint 1 at 0x401c50(gdb) rStarting program: /home/bgregg/hello[Thread debugging using libthread_db enabled]Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".[New Thread 0x7ffff449c700 (LWP 16836)][New Thread 0x7ffff3098700 (LWP 16837)][Switching to Thread 0x7ffff3098700 (LWP 16837)]Thread 3 "hello" hit Breakpoint 1, fmt.Println (a=...) at ../../../src/libgo/go/fmt/print.go:263263 ../../../src/libgo/go/fmt/print.go: No such file or directory.(gdb) p a$1 = {__values = 0xc208000240, __count = 1, __capacity = 1}(gdb) p a.__values$18 = (struct {...} *) 0xc208000240(gdb) p a.__values[0]$20 = {__type_descriptor = 0x4037c0 <__go_tdn_string>, __object = 0xc208000210}(gdb) x/s *0xc2080002100x403483:   "Hello, BPF!"

五、Function Latency

• 樣本：迴圈調用 fmt.Println() 函數的時延長條圖（納秒）

WARNING: Go 函數調用過程中，如果從一個進程（goroutine）切換到另外一個系統進程，funclatency 無法匹配入口-返回。這種情境需要一個新的工具 —— gofunclatency ，它基於 Go 內建的 GOID 替代系統的 TID 追蹤時延，在某些情況下， uretprobes 修改 Go 程式可能出現崩潰的問題，因此在調試之前需要準備周全的計劃。

# funclatency 'go:fmt.Println'Tracing 1 functions for "go:fmt.Println"... Hit Ctrl-C to end.^CFunction = fmt.Println [3041]     nsecs               : count     distribution         0 -> 1          : 0        |                                        |         2 -> 3          : 0        |                                        |         4 -> 7          : 0        |                                        |         8 -> 15         : 0        |                                        |        16 -> 31         : 0        |                                        |        32 -> 63         : 0        |                                        |        64 -> 127        : 0        |                                        |       128 -> 255        : 0        |                                        |       256 -> 511        : 0        |                                        |       512 -> 1023       : 0        |                                        |      1024 -> 2047       : 0        |                                        |      2048 -> 4095       : 0        |                                        |      4096 -> 8191       : 0        |                                        |      8192 -> 16383      : 27       |****************************************|     16384 -> 32767      : 3        |****                                    |Detaching...

Tips

6.1 安裝和編譯 BCC

git clone https://github.com/iovisor/bcc.gitmkdir bcc/build; cd bcc/buildcmake -DCMAKE_INSTALL_PREFIX=/usr \      -DLUAJIT_INCLUDE_DIR=`pkg-config --variable=includedir luajit` \ # for lua support      ..makesudo make installcmake -DPYTHON_CMD=python3 .. # build python3 bindingpushd src/python/makesudo make installpopd

6.2 構建 LLVM 和 Clang 開發工具庫

yum install gccyum install gcc-g++wget https://cmake.org/files/v3.9/cmake-3.9.0-rc4.tar.gztar -xvf cmake-3.9.0-rc4.tar.gzcd cmake-3.9.0./bootstrap  gmakegmake installexport CMAKE_ROOT=/usr/local/share/cmake-3.9.0export PATH=$PATH:$CMAKE_ROOTgit clone http://llvm.org/git/llvm.gitcd llvm/tools;git clone http://llvm.org/git/clang.gitcd ..; mkdir -p build/install; cd buildcmake -G "Unix Makefiles" -DLLVM_TARGETS_TO_BUILD="BPF;X86" -DCMAKE_BUILD_TYPE=Release -DCMAKE_INSTALL_PREFIX=$PWD/install ..makemake installexport PATH=$PWD/install/bin:$PATH

6.3 LLVM 與 Clang

LLVM （Low Level Virtual Machine）是一種編譯器基礎設施，以C++寫成。起源於2000年伊利諾大學厄巴納-香檳分校維克拉姆·艾夫（Vikram Adve）與克裡斯·拉特納（Chris Lattner）的研究，他們想要為所有靜態及動態語言創造出動態編譯技術。2005年，Apple直接僱用了克裡斯·拉特納及他的團隊，為了蘋果電腦開發應用程式，期間克裡斯·拉特納設計發明了 Swift 語言，LLVM 成為 Mac OS X 及 iOS 開發工具的一部分。LLVM 的範圍早已經不局限於建立一個虛擬機器，成為了眾多編譯工具及低級工具技術的統稱，適用於LLVM下的所有項目，包含LLVM中介碼（LLVM IR）、LLVM除錯工具、LLVM C++標準庫等。

目前 LLVM 已支援包括ActionScript、Ada、D語言、Fortran、GLSL、Haskell、Java位元組碼、Objective-C、Swift、Python、Ruby、Rust、Scala1以及C#等語言。

Clang 是LLVM編譯器工具集的前端（front-end），目的是輸出代碼對應的抽象文法樹（Abstract Syntax Tree, AST），並將代碼編譯成LLVM Bitcode。接著在後端（back-end）使用 LLVM 編譯成平台相關的機器語言 。Clang支援C、C++、Objective C。它的目標是提供一個 GCC 的替代品。作者是克裡斯·拉特納（Chris Lattner），在蘋果公司的贊助支援下進行開發。Clang項目包括Clang前端和Clang靜態分析器等。

6.4 ABI

應用二進位介面（Application Binary Interface， ABI）描述了應用程式和作業系統之間或其他應用程式的低級介面。ABI涵蓋了各種細節，如：

• 資料類型的大小、布局;

• 呼叫慣例（控制著函數的參數如何傳送以及如何接受傳回值），例如，是所有的參數都通過棧傳遞，還是部分參數通過寄存器傳遞；哪個寄存器用於哪個函數參數；通過棧傳遞的第一個函數參數是最先push到棧上還是最後；

• 目標檔案的二進位格式、程式庫等等。

• ABI vs API
  應用程式介面 (API)定義了原始碼和庫之間的介面，因此同樣的代碼可以在支援這個API的任何系統中編譯，然而ABI允許編譯好的目標代碼在使用相容 ABI 的系統中無需改動就能運行。