动态追踪技术（四）：基于 Linux bcc/BPF 实现 Go 程序动态追踪-白红宇

动态追踪技术（四）：基于 Linux bcc/BPF 实现 Go 程序动态追踪

阅读量：5852 次

发布时间：2019-06-19

本文共 13356 字，大约阅读时间需要 44 分钟。

摘要

原文：

引子：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 程序的方法，包括但不限于：

：用于高层异常和阻塞事件

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!

现在我将使用工具的 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 新增的特性，详见。

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

现在我将尝试使用的追踪工具，也是基于，用来查看每一个函数调用事件。我将回到 gccgo，使用一个非常简单的示例程序（ from the ），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静态分析器等。