# Chapter 2 這份筆記主要紀錄怎麼插入與使用各種 BPF 的 probe。主要的參考資料是 [BPF Performance Tools: Linux System and Application Observability](http://www.brendangregg.com/bpf-performance-tools-book.html) 一書中的第 2 章。 # Probe 在這當中特別指 `kprobe` , `kretprobe`, 跟 `uprobe`, `uretprobe` 這種名字帶有 probe 的機制。這類 probe 的特點是動態的，可以在程式執行到一半時決定要啟動或是關閉，而且機制多半與 breakpoint 的使用有關。`kprobe` 用在 kernel space，而 `uprobe` 用在 user space。 而`kretprobe` 跟 `uretprobe` 則是前兩者的衍生，是在函式回傳時觸發。比如說在進入函式時設置 `uprobe`，搭配 `uretprobe` 就可以統計整個函式執行時的相關資訊 (比如說執行時間)。 ## kprobe & kretprobe 主要的機制在 [An introduction to KProbes](https://lwn.net/Articles/132196/) 一文中提到：想要放 probe 的那道指令會被暫時換成 [int3](https://x86.puri.sm/html/file_module_x86_id_142.html)，跳到 debug exception handler 後開始做統計。 而 `kretprobe` 根據書上的說法是在函式進入點設置 `kprobe`，這個 `kprobe` 被觸發時，會把函式原先的 return address 儲存，並且改為成某個用於統計的 handler。函式結束執行時，因為 return address 被改成 handler 的緣故，所以會跳進 handler 進行相關動作，到 handler 執行結束後，才會跳回原先函數該有的那個 return address。 如果有 `bpftrace`，可以使用： ```shell= $ sudo bpftrace -l 'kprobe*' ``` 可以找出所有的 `kprobe`: ```shell= $ bpftrace -l 'kprobe*' kprobe:trace_initcall_finish_cb kprobe:initcall_blacklisted kprobe:do_one_initcall kprobe:do_one_initcall kprobe:trace_initcall_start_cb kprobe:run_init_process kprobe:try_to_run_init_process kprobe:match_dev_by_label kprobe:match_dev_by_uuid kprobe:rootfs_mount kprobe:name_to_dev_t kprobe:bstat kprobe:bstat kprobe:calibration_delay_done [...] ``` 核心的原始碼中有一些在核心中新增 `kprobe` 的 [範例](https://elixir.bootlin.com/linux/latest/source/samples/kprobes/kprobe_example.c)。 大致上來說，相關的系統呼叫都會有對應的 `tracepoint`，這些 tracepoint 是靜態的，可預期會繼續維護的來源。而一些用於實作系統呼叫所使用的函數，或是核心其他部份的用到函數，大致上可以從 `kprobe` 下手。比如 `init_module` 這個系統呼叫可以查到對應的 tracepoint: ```shell= $ sudo bpftrace -l | grep init_module [...] tracepoint:syscalls:sys_enter_init_module tracepoint:syscalls:sys_exit_init_module tracepoint:syscalls:sys_enter_finit_module tracepoint:syscalls:sys_exit_finit_module [...] ``` 但在這個系統呼叫裡面用到的 `load_module` 就只有 `kprobe` ```shell= $ sudo bpftrace -l | grep load_module kprobe:load_module ``` ## uprobe 相較於針對核心內部函數的 `kprobe`，`uprobe` 插在一些 user space 的物件中。可以用 `bpftrace` 去問那個程式有提供哪些 `uprobe`。下面舉一些簡單的例子： ### 例子：Hello World 假設現在 `/tmp` 中現在有一個 hello world 程式： ```=c= #include <stdio.h> int main() { printf("hello, world\n"); } ``` 假定編完(`gcc`)之後的程式名稱叫作 `hello`，那麼用： ```shell= $ sudo bpftrace -l 'uprobe:/tmp/hello*' ``` 就可以找到這個程式對應的 `uprobe`： ```shell= $ sudo bpftrace -l 'uprobe:/tmp/hello*' uprobe:/tmp/hello:deregister_tm_clones uprobe:/tmp/hello:register_tm_clones uprobe:/tmp/hello:__do_global_dtors_aux uprobe:/tmp/hello:frame_dummy uprobe:/tmp/hello:__libc_csu_fini uprobe:/tmp/hello:__libc_csu_init uprobe:/tmp/hello:_start uprobe:/tmp/hello:main ``` ### 例子：函數進入點 比如說如果 `/tmp` 下有一個程式 `fun.c`： ```c= #include <stdio.h> int bar() { printf("I'm bar"); return 'b'; } int foo() { return bar(); } int fun() { foo(); bar(); return foo(); } int main() { fun(); } ``` 假定編出來(`gcc fun.c -o fun`) 之後，名稱叫作 `fun`，那麼去看他的 `uprobe`： ```shell= $ sudo bpftrace -l 'uprobe:/tmp/fun:*' uprobe:/tmp/fun:deregister_tm_clones uprobe:/tmp/fun:register_tm_clones uprobe:/tmp/fun:__do_global_dtors_aux uprobe:/tmp/fun:frame_dummy uprobe:/tmp/fun:__libc_csu_fini uprobe:/tmp/fun:bar uprobe:/tmp/fun:fun uprobe:/tmp/fun:__libc_csu_init uprobe:/tmp/fun:foo uprobe:/tmp/fun:_start uprobe:/tmp/fun:main ``` 就會發現 `foo`, `bar` 等函數都會自動有自己的 `uprobe`。 > 我不確定哪種編譯條件會使可執行檔能(或不能)使用 uprobe。上面這個程式我並沒有加什麼特定條件編譯，僅有使用 `gcc fun.c -o fun` 來編譯。 ### 例子：lab0-c 又或者是如果把 [lab0-c](https://github.com/sysprog21/lab0-c) 的程式放到 `/tmp` 下編完，然後就可以發現裡面那些相關的函數都會有自己的 uprobe： ```shell= $ sudo bpftrace -l 'uprobe:/tmp/lab0-c/qtest:q*' uprobe:/tmp/lab0-c/qtest:queue_init uprobe:/tmp/lab0-c/qtest:queue_quit uprobe:/tmp/lab0-c/qtest:q_reverse uprobe:/tmp/lab0-c/qtest:q_remove_head uprobe:/tmp/lab0-c/qtest:q_size uprobe:/tmp/lab0-c/qtest:q_insert_head uprobe:/tmp/lab0-c/qtest:q_new uprobe:/tmp/lab0-c/qtest:q_insert_tail uprobe:/tmp/lab0-c/qtest:q_free ``` ## uretprobe 另外，如果把 `urpobe` 改成 `uretprobe`，那就會改為設置 `uretprobe` (註：但如果用 `bpftrace -l` 看的話不會看到 `uretprobe`。不確定理由是什麼)。 某個函數的 uprobe 跟　uretprobe 搭配就可以對這個函數在執行期間發生的一些事情進行統計。 ### 例子：以 uprobe 計算 thread function 所花的時間： `uprobe` 可以在進入函式時觸發，而 `uretprobe` 可以在函式回傳時觸發，所以就可以針對函式執行期間發生的事情進行統計。這邊舉一個量 thread function 執行時間的例子。比如說假設現在有一個程式叫作　`read_rand.c`，他做的事情式是：開 4 個執行緒去讀　`/dev/random`： ```c= #include <unistd.h> #include <stdio.h> #include <fcntl.h> #include <pthread.h> #define FILE_PATH "/dev/random" #define READ_NUM (1 << 4) #define THREAD_NUM 4 int fd; pthread_t threads[THREAD_NUM]; char buf[THREAD_NUM][READ_NUM + 1]; int thread_args[THREAD_NUM]; void *thread_fun(void *arg) { int n = *((int*)arg); int ret = 0; ret = read(fd, &(buf[n][0]), READ_NUM); if (ret != READ_NUM) { printf("WARNING : thread %d only read %d of %d bytes.\n", n, ret, READ_NUM); } } int main() { fd = open(FILE_PATH, O_RDONLY); if (fd < 0) { perror("ERROR : Fail to open file.\n"); return 1; } for (int i = 0; i < THREAD_NUM; i++) { thread_args[i] = i; pthread_create(&threads[i], NULL, thread_fun, &thread_args[i]); } for (int i = 0; i < THREAD_NUM; i++) { pthread_join(threads[i], NULL); } } ``` > 之所以舉這個例子是因為 `/dev/random` 的熵會用盡，直到收集到足夠的熵(比如要動一動滑鼠) 之前會堵塞，這時就可以觀察不同 thread 的的時間差。 假定這程式是在 `/tmp` 之下，編譯： ```shell= $ gcc read_rand.c -lpthread -o read_rand ``` 並且使用以下的 `bpftrace` script，假定這個檔案叫作 `bpf-read-random.bt`： ```shell= uprobe:/tmp/read_rand:thread_fun { @start[tid] = nsecs; } uretprobe:/tmp/read_rand:thread_fun { @ns[pid, tid, @start[tid]] = (nsecs - @start[tid]); delete(@start[tid]); } ``` 先執行 `sudo bpftrace bpf-read-random.bt`，然後在另外一個終端機視窗執行 `read_random`。等到程式執行結束之後，再回到執行 `bpftrace` 的視窗，並且按 ctrl + C 中止 `bpftrace` (或是用 `tmux` 等等)。就會得到每個執行序執行 `thread_fun` 的時間統計： ```shell= $ sudo bpftrace bpf-read-random.bt Attaching 2 probes... ^C @ns[6197, 6198, 3736880380994]: 237204 @ns[6197, 6201, 3736880541719]: 6400700024 @ns[6197, 6199, 3736880438565]: 9550668973 @ns[6197, 6200, 3736880502074]: 14213411093 ``` 這當中， `@ns` 的第一個數字是行程的 `pid`，而第二個數字是這個行程中的執行續的 `tid`，第三個是 timestamp。 如果一直重複執行程式，因為`/dev/random` 中的熵有用盡的緣故，所以可能有的執行續在執行 `thread_fun` 時會一直被 block 住，就可以觀察到不同執行續在 `thread_fun` 中花的時間。 # Tracepoint 靜態的來源。定義在 include/trace/events 中，並且由核心開發團隊維護。像是 [include/trace/events/sched.h](https://github.com/torvalds/linux/blob/master/include/trace/events/sched.h) 中定義了 `sched` 相關的 tracepoint。另外 `SYSCALL_DEFINEx` 中用到的 [`SYSCALL_METADATA`](https://elixir.bootlin.com/linux/v5.3/source/include/linux/syscalls.h#L167) 也自動帶有進入與離開系統呼叫的 tracepoint。 具體的機制可見 Steven Rostedt 2019 年在 Kernel Recipe 的 ftrace: Where modifying a running kernel all started 中 21:53 部份： {%youtube 93uE_kWWQjs%} 概念上跟前面的 probe 很像，也是利用 int3 觸發，只是可以插進 int3 的部份先被換成 nop。但除了這之外多了很多同步的細節~~究竟為什麼能在 cache 的行為那麼複雜的狀況下還可以生出這種功能阿~~！ 而如果有 `bpftrace` 的話，使用 `bpftrace -l` 列出來的所有 event source 中，`tracepoint:*` 格式的就是 tracepoint。可以發現系統呼叫多半都有對應的 tracepoint: ```shell= $ sudo bpftrace -l | grep tracepoint:syscalls | less tracepoint:syscalls:sys_enter_socket tracepoint:syscalls:sys_exit_socket tracepoint:syscalls:sys_enter_socketpair tracepoint:syscalls:sys_exit_socketpair tracepoint:syscalls:sys_enter_bind tracepoint:syscalls:sys_exit_bind tracepoint:syscalls:sys_enter_listen tracepoint:syscalls:sys_exit_listen tracepoint:syscalls:sys_enter_accept4 [...] ``` 這樣一來，可以用讀 `sys_enter_read` 跟 `sys_exit_read` 去計算某一個系統呼叫的時間差。比如說如果在上面的 bpf script 中加入兩個讀 `sys_enter_read` 跟 `sys_exit_read` 兩個 tracepoint 的時間差： ```shell= probe:/tmp/read_rand:thread_fun { @start[tid] = nsecs; } uretprobe:/tmp/read_rand:thread_fun { @ns[pid, tid, @start[tid]] = (nsecs - @start[tid]); delete(@start[tid]); } tracepoint:syscalls:sys_enter_read /comm=="read_rand"/ { @start_read[tid] = nsecs; } tracepoint:syscalls:sys_exit_read /comm=="read_rand"/ { @ns_read[pid, tid, @start[tid]] = (nsecs - @start_read[tid]); delete(@start_read[tid]); } ``` 然後執行： ```shell= $ sudo bpftrace bpf-read-random.bt Attaching 4 probes... ^C @ns[6490, 6494, 4256156932713]: 1482014449 @ns[6490, 6492, 4256156818023]: 5536794592 @ns[6490, 6493, 4256156848076]: 8829644131 @ns[6490, 6491, 4256156761179]: 12395578717 @ns_read[6490, 6490, 0]: 1694 @ns_read[6490, 6494, 4256156932713]: 1481783766 @ns_read[6490, 6492, 4256156818023]: 5536708422 @ns_read[6490, 6493, 4256156848076]: 8829534186 @ns_read[6490, 6491, 4256156761179]: 12395459782 ``` 這邊會發現用讀取 `sys_[enter, exit]_read` 會輸出比較多條目，這是他統計的 `read` 不只有 `thread_fun` 中的呼叫(用 `strace` 可以驗證)。但可以從 `tid` 中得到哪些統計是和哪些執行續有關。 tracepoint 還有一個頗豪華的功能：看系統呼叫回傳值。這可以用 `-lv` 選項去查。比如說查 `sys_enter_read` 會使用到的參數： ```shell= $ sudo bpftrace -lv "tracepoint:syscalls:sys_enter_read" tracepoint:syscalls:sys_enter_read int __syscall_nr; unsigned int fd; char * buf; size_t count; ``` 當然也可以查 `sys_exit_read` 的： ```shell= $ sudo bpftrace -lv "tracepoint:syscalls:sys_exit_read" tracepoint:syscalls:sys_exit_read int __syscall_nr; long ret; ``` 有了這個資訊，把 `tracepoint:syscalls:syscall_exit_read` 的部份多加一行: ```shell= tracepoint:syscalls:sys_exit_read /comm=="read_rand"/ { @ns_read[pid, tid, @start[tid]] = (nsecs - @start_read[tid]); @ret[pid, tid, @start[tid]] = args->ret; delete(@start_read[tid]); } ``` 並且執行。就可以得到： ```shell= $ sudo bpftrace bpf-read-random.bt Attaching 4 probes... ^C @ns[7361, 7362, 5887835093241]: 165607 @ns[7361, 7363, 5887835150474]: 3852736820 @ns[7361, 7364, 5887835196053]: 4609519808 @ns[7361, 7365, 5887835211476]: 5438294584 @ns_read[7361, 7361, 0]: 1497 @ns_read[7361, 7362, 5887835093241]: 18234 @ns_read[7361, 7363, 5887835150474]: 3852626251 @ns_read[7361, 7364, 5887835196053]: 4609420484 @ns_read[7361, 7365, 5887835211476]: 5438209889 @ret[7361, 7363, 5887835150474]: 6 @ret[7361, 7364, 5887835196053]: 6 @ret[7361, 7365, 5887835211476]: 6 @ret[7361, 7362, 5887835093241]: 7 @ret[7361, 7361, 0]: 68 ``` 對照程式執行的標準輸出中的資訊可以驗證: ```shell= $ ./read_rand WARNING : thread 0 only read 7 of 16 bytes. WARNING : thread 1 only read 6 of 16 bytes. WARNING : thread 2 only read 6 of 16 bytes. WARNING : thread 3 only read 6 of 16 bytes. ``` # USDT 也是靜態的事件來源。機制跟 tracepoint 類似，只是換成在 user space 做這件事。在想要觸發的指令前插入 `nop`，並且在 ELF 檔案的特定區段註記。詳細在 [Using user-space tracepoints with BPF](https://lwn.net/Articles/753601/) 一文中可以見到。在書中是使用 FOLLY 做例子，而文章中是用安裝 systemtap 之後的 `<sys/sdt.h>` 來做： ```c= #include <sys/sdt.h> #include <sys/time.h> #include <unistd.h> int main(int argc, char **argv) { struct timeval tv; while(1) { gettimeofday(&tv, NULL); DTRACE_PROBE1(yeet-Im-a-USDT-probe, USDT-test-probe, tv.tv_sec); sleep(1); } return 0; } ``` 用 `gcc` 編譯： ```shell= $ gcc hello_usdt.c -o hello_usdt ``` 接著用 `readelf -n` 看： ```shell= $ readelf -n hello_usdt ``` 就會看到一段跟剛剛設置的 USDT 有關的註記： ```shell= $ readelf -n usdt_hello Displaying notes found in: .note.stapsdt Owner Data size Description stapsdt 0x00000045 NT_STAPSDT (SystemTap probe descriptors) Provider: yeet-Im-a-USDT-probe Name: USDT-test-probe Location: 0x00000000000011a0, Base: 0x0000000000002004, Semaphore: 0x0000000000000000 Arguments: -8@%rax ``` 也可以用 `bpftrace` 去看。假定這個程式位在 `/tmp` 下，那麼使用 `bpftrace -l 'usdt:<path>:*'` 可以查出這個物件有的 USDT。比如說： ```shell= $ sudo bpftrace -l 'usdt:/tmp/usdt_hello:*' ``` 就可以發現： ```shell= $ sudo bpftrace -l 'usdt:/tmp/usdt_hello:*' usdt:/tmp/usdt_hello:yeet-Im-a-USDT-probe:USDT-test-probe ``` 順帶一提：`DTRACE_PROBEn`原型可以看這個標頭檔的[原始程式](https://fossies.org/linux/systemtap/includes/sys/sdt.h)： ```C= /* DTrace compatible macro names. */ #define DTRACE_PROBE(provider,probe) \ STAP_PROBE(provider,probe) #define DTRACE_PROBE1(provider,probe,parm1) \ STAP_PROBE1(provider,probe,parm1) #define DTRACE_PROBE2(provider,probe,parm1,parm2) \ STAP_PROBE2(provider,probe,parm1,parm2) #define DTRACE_PROBE3(provider,probe,parm1,parm2,parm3) \ STAP_PROBE3(provider,probe,parm1,parm2,parm3) ``` # PMC 指硬體上的 performance monitoring unit ~~`perf` 的天下~~。 # 其他 Dynamic USDT (用在於直譯式語言); `perf_event` 也可能作為來源，但目前還在開發中。