管你要 trace 什麼 bpftrace 用下去就對了 (KaLUG場)

Transcript

1. 管你要 trace 什麼 bpftrace 用下去就對了 Shung-Hsi Yu 2025-07-12 KaLUG
2. About me Shung-Hsi Yu @shunghsiyu(@fosstodon.org) Based in Taitung, Taiwan Works at SUSE Kernel Engineer Maintains (e)BPF stack in SLES and openSUSE 2
3. 3 Story Time
4. 4 $ systemctl restart your-own.service Job for your-own.service failed because the control process exited with error code. See "systemctl status your-own.service" and "journalctl -xe" for details.
5. $ systemctl status your-own.service • your-own.service Loaded: loaded (/etc/systemd/system/your-own.service; disabled; vendo… Active: failed (Result: exit-code) since Thu 2025-07-12 00:00:01 UTC Process: 80054 ExecStart=/usr/sbin/your-own (code=exited, status=1/FAIL… Jul 12 00:00:01 system systemd[1]: Starting Your Own Service... Jul 12 00:00:01 system your-own[80054]: Configuration file not found! 5
7. $ man your-own No manual entry for your-own Possibly, man page is not installed, try online at: https://manpages.opensuse.org/something 7
10. $ systemctl status your-own.service • your-own.service Loaded: loaded (/etc/systemd/system/your-own.service; disabled; vendo… Active: failed (Result: exit-code) since Thu 2025-07-12 00:00:01 UTC Process: 80054 ExecStart=/usr/sbin/your-own (code=exited, status=1/FAIL… Jul 12 00:00:01 system systemd[1]: Starting Your Own Service... Jul 12 00:00:01 system your-own[80054]: Configuration file not found! 10
12. 12 $ bpftrace -e ' tracepoint:syscalls:sys_enter_open, /comm == "your-own"/ { print(str(args->filename)) }' Attaching 1 probes… /etc/your-own-special.conf
13. 13 Intro to bpftrace
14. 14 A tracing tool
15. 15 A tracing tool logging debugging
16. 16 A tracing tool logging debugging
17. 17 Tracing - Is this function called? What function is called? - What are the arguments? - What is the return value? - How long does something take?
18. 18 bpftrace Language - Event-driven - Awk-like language, inspired by DTrace - C-like data structure definition & usage
19. 19 Syntax probe { action }
20. 20 Probe - an event (usually with wildecard/* support) - specific function called/returns - “tracepoint” (declared by developer) - bpftrace started, timer firing, etc…
21. 21 $ bpftrace -e ' tracepoint:syscalls:sys_enter_open, /comm == "your-own"/ { print(str(args->filename)) }' Attaching 1 probes… /etc/your-own-special.conf
22. 22 tracepoint:syscalls:sys_enter_open /comm == "your-own"/ { print(str(args->filename)); }
23. 23 tracepoint:syscalls:sys_enter_open /comm == "your-own"/ { print(str(args->filename)); }
24. 24 tracepoint:syscalls:sys_enter_open /comm == "your-own"/ { print(str(args->filename)); }
25. 25 System Call (Syscall) - Interface for userspace program (e.g. Python) - Request the kernel to do something - e.g. open a file
26. 26 tracepoint:syscalls:sys_enter_open /comm == "your-own"/ { print(str(args->filename)); }
27. 27 Syntax probe { action }
28. 28 Syntax probe { action }
29. 29 tracepoint:syscalls:sys_enter_open, /comm == "your-own"/ { print(str(args->filename)); }
30. 30 tracepoint:syscalls:sys_enter_open, /comm == "your-own"/ { print(str(args->filename)); }
31. 31 $ bpftrace -vl 'tracepoint:syscalls:sys_enter_open' tracepoint:syscalls:sys_enter_open int __syscall_nr const char * filename …
32. 32 tracepoint:syscalls:sys_enter_open, /comm == "your-own"/ { print(str(args->filename)); }
33. 33 tracepoint:syscalls:sys_enter_open /comm == "your-own"/ { print(str(args->filename)); }
34. 34 Built-ins - Special variables - args: arguments associated with probe - comm: program name of current process - pid: ID of current process
35. 35 tracepoint:syscalls:sys_enter_open /comm == "your-own"/ { print(str(args->filename)); }
36. 36 tracepoint:syscalls:sys_enter_open /comm == "your-own"/ { print(str(args->filename)); }
37. 37 $ bpftrace -vl 'tracepoint:syscalls:sys_enter_open' tracepoint:syscalls:sys_enter_open int __syscall_nr const char * filename /* string pointer, need str() to read */ …
38. 38 tracepoint:syscalls:sys_enter_open /comm == "your-own"/ { print(str(args->filename)); }
39. 39 tracepoint:syscalls:sys_enter_open /comm == "your-own"/ { print(args->filename); /* without str(), just prints an address */ }
40. $ bpftrace -e 'tracepoint:syscalls:sys_enter_open { print(args->filename) }' 0x555b28de2190 0x564f6b064cd0 0x55a2ef9643a0 0x564e6d170020 40
41. 41 tracepoint:syscalls:sys_enter_open /comm == "your-own"/ { print(str(args->filename)); }
42. 42 tracepoint:syscalls:sys_enter_open /comm == "your-own"/ { print(str(args->filename)); }
43. 43 Functions - Helpers provided by bpftrace - print(): simple printing of given value - str(): convert string pointer to actual string
44. 44 tracepoint:syscalls:sys_enter_open /comm == "your-own"/ { print(str(args->filename)); }
45. 45 tracepoint:syscalls:sys_enter_open /comm == "your-own"/ { print(str(args->filename)); }
46. 46 Built-ins - Special variables - args: arguments associated with probe - comm: program name of current process - pid: ID of current process
47. 47 tracepoint:syscalls:sys_enter_open /comm == "your-own"/ { print(str(args->filename)); }
48. 48 Syntax probe { action }
49. 49 Syntax probe [/predicate/] { action }
50. 50 tracepoint:syscalls:sys_enter_open /comm == "your-own"/ { print(str(args->filename)); }
51. 51 tracepoint:syscalls:sys_enter_open { if (comm != "your-own") { return; } print(str(args->filename));
52. 52 tracepoint:syscalls:sys_enter_open /comm == "your-own"/ { print(str(args->filename)); }
53. 53 Syntax probe[, probe, …] /predicate/ { action }
54. 54 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == "your-own"/ { print(str(args->filename)); }
55. 55 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == "your-own"/ { print(str(args->filename)); }
56. 56 Doing more with bpftrace
57. 57 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == "your-own"/ { print(str(args->filename)); }
58. 58 Built-ins - Special variables - $1, $2, …: nth positional parameter passed to the bpftrace program
59. 59 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { print(str(args->filename));
60. 60 #!/usr/bin/bpftrace tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { print(str(args->filename));
61. 61 #!/usr/bin/bpftrace tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { print(str(args->filename));
62. 62 $ ./opensnoop.bt 'your-own' Attaching 3 probes… /etc/your-own-special.conf
63. 63 $ ./opensnoop.bt 'your-own' Attaching 3 probes… /etc/your-own-special.conf
64. 64 $ ./opensnoop.bt 'your-own' Attaching 3 probes… /etc/your-own-special.conf # successful???
65. 65 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { print(str(args->filename)); }
66. 66 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { print(str(args->filename)); }
67. 67 $ bpftrace -vl 'tracepoint:syscalls:sys_exit_open' tracepoint:syscalls:sys_exit_open int __syscall_nr long ret /* return code */
68. 68 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { print(args->ret); }
69. 69 $ ./opensnoop2.bt 'your-own' Attaching 6 probes… /lib64/libc.so.6 3 /etc/your-own-special.conf -2
70. 70 $ errno 2 ENOENT 2 No such file or directory
71. 71 $ ./opensnoop2.bt 'your-own' Attaching 6 probes… /lib64/libc.so.6 3 /etc/your-own-special.conf -2
72. 72 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { print(str(args->filename)); }
73. 73 Functions - Helpers provided by bpftrace - print(): simple printing of given value - printf(): advance printing with formatting
74. 74 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { printf("%s: ", str(args->filename)); /* No newline */ }
75. 75 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { printf("%s: ", str(args->filename)); /* No newline */ }
76. 76 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { print(args->ret); }
77. 77 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { printf("%d\n", args->ret); }
78. 78 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { printf("%d\n", args->ret); }
79. 79 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { printf("%d\n", args->ret); }
80. 80 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { printf("%d\n", args->ret); }
81. 81 $ ./opensnoop3.bt 'your-own' Attaching 6 probes… /lib64/libc.so.6: 3 /etc/your-own-special.conf: -2
82. 82 $ ./opensnoop3.bt 'your-own' Attaching 6 probes… /lib64/libc.so.6: /etc/your-own-special.conf: 3 -2 /etc/your-own-special.conf: -2 /etc/your-own-special.conf: /lib64/libc.so.6: -2
83. 83 $ ./opensnoop3.bt 'your-own' Attaching 6 probes… /lib64/libc.so.6: /etc/your-own-special.conf: 3 -2 /etc/your-own-special.conf: -2 /etc/your-own-special.conf: /lib64/libc.so.6: -2
84. 84 Overlapping open() - More than one threads calling open() - Duration of their execution may overlap Thread 1 Thread 2 sys_enter_open sys_enter_open sys_exit_open sys_exit_open
85. 85 Built-ins - Special variables - tid: Thread ID of the current thread - uniquely identifies an execution
86. 86 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { printf("%s: ", str(args->filename)); /* No newline */ }
87. 87 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { printf("%d: %s\n", tid, str(args->filename)); /* With newline */ }
88. 88 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { printf("%d\n", args->ret); }
89. 89 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { printf("%d: %d\n", tid, args->ret); }
90. 90 $ ./opensnoop4.bt 'your-own' Attaching 6 probes… 30762: /lib64/libc.so.6 30764: /etc/your-own-special.conf 30762: 3 30764: -2
91. 91 $ ./opensnoop4.bt 'your-own' Attaching 6 probes… 30762: /lib64/libc.so.6 30764: /etc/your-own-special.conf 30762: 3 30764: -2
92. - A BPF memory object, e.g. @files - storage area - (usually) key-value map - i.e. similar to a global variable 92 Map Variable
93. 93 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { @files[tid] = str(args->filename); /* No printing */ }
94. 94 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { @files[tid] = str(args->filename); /* No printing */ }
95. 95 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1) && !!@files[tid]/ { printf("%s: %d\n", @files[tid], args->ret); delete(@files[tid]); /* Remove used value */
96. 96 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1) && !!@files[tid]/ { printf("%s: %d\n", @files[tid], args->ret); delete(@files[tid]); /* Remove used value */
97. 97 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1) && !!@files[tid]/ { printf("%s: %d\n", @files[tid], args->ret); delete(@files[tid]); /* Remove used value */
98. 98 $ ./opensnoop4.bt 'your-own' Attaching 6 probes… /lib64/libc.so.6: 3 /etc/your-own-special.conf: -2 /etc/your-own-special.conf: -2 /etc/your-own-special.conf: -2
99. 99 Calculating with bpftrace
100. 100 Operators and Expressions - Supports arithmetic operators - + - * / - Logical (&&), Bitwise (^ |), and Relational (<= !=) works, too
101. 101 Latency - How long does it take? - Get a timestamp when started - Get a timestamp when ended - Calculate difference between the timestamps
102. 102 Functions - Helpers provided by bpftrace - nsecs(): returns a timestamp in nanoseconds - can drop parenthesis when no argument
103. 103 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { @start[tid] = nsecs; /* Record start time */ }
104. 104 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { @start[tid] = nsecs; /* Record start time */ }
105. 105 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1) && !!@start[tid]/ { $duration = nsecs - @start[tid]; /* end - start */ printf("Took %d\n", $duration);
106. 106 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1) && !!@start[tid]/ { $duration = nsecs - @start[tid]; /* end - start */ printf("Took %d\n", $duration);
107. 107 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1) && !!@start[tid]/ { $duration = nsecs - @start[tid]; /* end - start */ printf("Took %d\n", $duration);
108. 108 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1) && !!@start[tid]/ { $duration = nsecs - @start[tid]; /* end - start */ printf("Took %d\n", $duration);
109. - Lexical-scoped variable, e.g. $duration - stores simple values - numbers (int, long, …), strings - i.e. similar to a local variable 109 Scratch Variable
110. 110 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1) && !!@start[tid]/ { $duration = nsecs - @start[tid]; /* end - start */ printf("Took %d\n", $duration);
111. 111 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1) && !!@start[tid]/ { $duration = nsecs - @start[tid]; /* end - start */ printf("Took %d\n", $duration);
112. 112 $ ./sys_latency.bt 'your-own' Attaching 6 probes... Took 18791ns Took 8102ns Took 115726ns Took 9762ns
113. 113 Dealing with Lots of Data - What is open() was calls 1k times per seconds? - Statistics to the rescue: - minimum, maximum, average, sum - quantile, histogram, time-series
114. 114 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1) && !!@start[tid]/ { $duration = nsecs - @start[tid]; /* end - start */ printf("Took %d\n", $duration);
115. 115 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1) && !!@start[tid]/ { $duration = nsecs - @start[tid]; /* end - start */ printf("Took %d\n", $duration);
116. 116 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1) && !!@start[tid]/ { $duration = nsecs - @start[tid]; /* end - start */ @latency = hist($duration);
117. 117 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1) && !!@start[tid]/ { $duration = nsecs - @start[tid]; /* end - start */ @latency = hist($duration);
118. 118 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1) && !!@start[tid]/ { $duration = nsecs - @start[tid]; /* end - start */ @latency = hist($duration);
119. $ ./sys_latency_hist.bt 'your-own' @latency: [256, 512) 64 | | [512, 1K) 216818 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@| [1K, 2K) 160007 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ | [2K, 4K) 30255 |@@@@@@@ | [4K, 8K) 7114 |@ | [8K, 16K) 318 | | [16K, 32K) 150 | | 119
120. 120 Why bpftrace?
121. 121 bpftrace Strengths 1. Safe 2. Dynamic Tracing 3. Low Overhead 4. Easy
122. 122 bpftrace Strengths 1. Safe 2. Dynamic Tracing 3. Low Overhead 4. Easy eBPF
123. 123 bpftrace Strengths 1. Safe 2. Dynamic Tracing 3. Low Overhead 4. Easy eBPF Make kernel programming possible for everyone
124. 124 bpftrace Strengths 1. Safe 2. Dynamic Tracing 3. Low Overhead 4. Easy eBPF Image from https://ebpf.io/what-is-ebpf/
125. 125 bpftrace Strengths 1. Safe 2. Dynamic Tracing 3. Low Overhead 4. Easy
126. 126 Comparing with Alternatives 1. Adding debug statements/printf() 2. Use debugger 3. Similar Tools
127. 127 Adding printf() - Needs to recompile and restart the process - more than once (?) - No Heisenbug
128. 128 Using Debugger - Stop the world - Reproducer required
129. 129 Similar Tools - strace/ltrace: high overhead, as high as 100x - ftrace: less dynamic, restricted process - LTTng: requires out-of-tree kernel module - bcc: less up-to-date in terms of features
130. 130 Where To Go From Here?
131. 131 Install bpftrace openSUSE/SLES zypper install bpftrace bpftrace-tools Debian/Ubuntu apt-get install bpftrace Alma/CentOS/RHEL/Rocky dnf install bpftrace
132. $ sudo bpftrace -e 'BEGIN { print("Hello World!"); exit(0); }' Attaching 1 probe... Hello World! 132
133. $ rpm -ql bpftrace-tools /usr/share/bpftrace/tools/bashreadline.bt /usr/share/bpftrace/tools/biolatency.bt … /usr/share/bpftrace/tools/doc/bashreadline_example.txt … /usr/share/man/man8/bashreadline.bt.8.gz 133
134. 134 Resources Videos - An introduction to bpftrace tracing language - bpftrace: a path to the ultimate Linux tracing… Texts - A thorough introduction to bpftrace - bpftrace(8) Manual Page
135. 135 Thank you for listening!
136. 136 Appendix
137. 137 Bonus Example
138. - Most important actions are done with shells - What commands? 138 Bash Inputs
139. - TCP connections (most interesting) - What hosts & port? 139 Network Connections
140. 140 /* In net/ipv4/tcp_output.c, build a SYN and send it off. */ int tcp_connect(struct sock *sk) { struct tcp_sock *tp = tcp_sk(sk); struct sk_buff *buff; …
141. 141 /* In net/ipv4/tcp_output.c, build a SYN and send it off. */ int tcp_connect(struct sock *sk) { struct tcp_sock *tp = tcp_sk(sk); struct sk_buff *buff; …
142. 142 struct sock { /* In include/net/sock.h */ struct sock_common { struct { __be32 skc_daddr; /* Destination address */ __be32 skc_rcv_saddr; }; struct { __be16 skc_dport; /* Destination port, in network byte order */
143. 143 struct sock { /* In include/net/sock.h */ struct sock_common { struct { __be32 skc_daddr; /* Destination address */ __be32 skc_rcv_saddr; }; struct { __be16 skc_dport; /* Destination port, in network byte order */
144. 144 /* In net/ipv4/tcp_output.c, build a SYN and send it off. */ int tcp_connect(struct sock *sk) { struct tcp_sock *tp = tcp_sk(sk); struct sk_buff *buff; …
145. 145 fentry:tcp_connect /args.sk->__sk_common.skc_family == 2/ { $daddr = ntop(args.sk->__sk_common.skc_daddr); $dport = bswap(args.sk->__sk_common.skc_dport); printf("%s:%d\n", $daddr, $dport);
146. 146 /* In net/ipv4/tcp_output.c, build a SYN and send it off. */ int tcp_connect(struct sock *sk) { struct tcp_sock *tp = tcp_sk(sk); struct sk_buff *buff; …
147. 147 fentry:tcp_connect /args.sk->__sk_common.skc_family == 2/ { $daddr = ntop(args.sk->__sk_common.skc_daddr); $dport = bswap(args.sk->__sk_common.skc_dport); printf("%s:%d\n", $daddr, $dport);
148. 148 struct sock { /* In include/net/sock.h */ struct sock_common { struct { __be32 skc_daddr; /* Destination address */ __be32 skc_rcv_saddr; }; struct { __be16 skc_dport; /* Destination port, in network byte order */
149. 149 struct sock { /* In include/net/sock.h */ struct sock_common { struct { __be32 skc_daddr; /* Destination address */ __be32 skc_rcv_saddr; }; struct { __be16 skc_dport; /* Destination port, in network byte order */
150. 150 fentry:tcp_connect /args.sk->__sk_common.skc_family == 2/ { $daddr = ntop(args.sk->__sk_common.skc_daddr); $dport = bswap(args.sk->__sk_common.skc_dport); printf("%s:%d\n", $daddr, $dport);
151. 151 Functions - Helpers provided by bpftrace - ntop(): convert IP address data to text - bswap(): reverse byte order
152. 152 fentry:tcp_connect /args.sk->__sk_common.skc_family == 2/ { $daddr = ntop(args.sk->__sk_common.skc_daddr); $dport = bswap(args.sk->__sk_common.skc_dport); printf("%s:%d\n", $daddr, $dport);
153. 153 fentry:tcp_connect /args.sk->__sk_common.skc_family == 2/ { $daddr = ntop(args.sk->__sk_common.skc_daddr); $dport = bswap(args.sk->__sk_common.skc_dport); printf("%s:%d\n", $daddr, $dport);
154. 154 fentry:tcp_connect /args.sk->__sk_common.skc_family == 2/ { $daddr = ntop(args.sk->__sk_common.skc_daddr); $dport = bswap(args.sk->__sk_common.skc_dport); printf("%s:%d\n", $daddr, $dport);
155. 155 Backgrounds
156. 156 eBPF
157. 157 Choosing a Probe - kprobe/kretprobe for kernel functions - uprobe/uretprobe for userspace functions - Tracepoint and USDT for predefined points