管你要 trace 什麼、bpftrace 用下去就對了 — COSCUP 2025

Transcript

1. 管你要 trace 什麼 bpftrace 用下去就對了 Shung-Hsi Yu 2025-08-09 COSCUP
2. 2 Story Time
3. 3 $ systemctl restart super-important.service Job for super-important.service failed because the control process exited with error code. See "systemctl status super-important.service" and "journalctl -xe" for details.
4. $ systemctl status super-important.service • super-important.service Loaded: loaded (/etc/systemd/system/super-important.service; disabled… Active: failed (Result: exit-code) since Thu 2025-07-12 00:00:01 UTC Process: 80054 ExecStart=/usr/sbin/super-important (code=exited, status… Jul 12 00:00:01 system systemd[1]: Starting Your Own Service... Jul 12 00:00:01 system super-important[80054]: Configuration file not found! 4
6. $ man super-important No manual entry for super-important Possibly, man page is not installed, try online at: https://manpages.opensuse.org/something 6
9. $ systemctl status super-important.service • super-important.service Loaded: loaded (/etc/systemd/system/super-important.service; disabled… Active: failed (Result: exit-code) since Thu 2025-07-12 00:00:01 UTC Process: 80054 ExecStart=/usr/sbin/super-important (code=exited, status… Jul 12 00:00:01 system systemd[1]: Starting Your Own Service... Jul 12 00:00:01 system super-important[80054]: Configuration file not found! 9
11. 11 $ bpftrace -e ' tracepoint:syscalls:sys_enter_open, /comm == "super-important"/ { printf("%s", str(args->filename)) }' Attaching 1 probes… /etc/super-important-special.conf
12. 12 Intro to bpftrace
13. 13 A tracing tool
14. 14 A tracing tool logging debugging
15. 15 A tracing tool logging debugging
16. 16 Tracing - Is this function called? What function is called? - What are the arguments? - What is the return value? - How long does something take?
17. 17 bpftrace Language - Event-driven - Awk-like language, inspired by DTrace - C-like data structure definition & usage
18. 18 Syntax probe { action }
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 == "super-important"/ { printf("%s", str(args->filename)) }' Attaching 1 probes… /etc/super-important-special.conf
22. 22 tracepoint:syscalls:sys_enter_open /comm == "super-important"/ { printf("%s", str(args->filename)); }
23. 23 tracepoint:syscalls:sys_enter_open /comm == "super-important"/ { printf("%s", str(args->filename)); }
24. 24 tracepoint:syscalls:sys_enter_open /comm == "super-important"/ { printf("%s", str(args->filename)); }
25. 25 tracepoint:syscalls:sys_enter_open /comm == "super-important"/ { printf("%s", str(args->filename)); }
26. 26 tracepoint:syscalls:sys_enter_open /comm == "super-important"/ { printf("%s", str(args->filename)); }
28. 28 tracepoint:syscalls:sys_enter_open /comm == "super-important"/ { printf("%s", str(args->filename)); }
29. 29 Syntax probe { action }
30. 30 Syntax probe { action }
31. 31 Syntax probe { action }
32. 32 tracepoint:syscalls:sys_enter_open, /comm == "super-important"/ { printf("%s", str(args->filename)); }
33. 33 tracepoint:syscalls:sys_enter_open, /comm == "super-important"/ { printf("%s", str(args->filename)); }
34. 34 $ bpftrace -vl 'tracepoint:syscalls:sys_enter_open' tracepoint:syscalls:sys_enter_open int __syscall_nr const char * filename …
35. 35 tracepoint:syscalls:sys_enter_open, /comm == "super-important"/ { printf("%s", str(args->filename)); }
36. 36 tracepoint:syscalls:sys_enter_open /comm == "super-important"/ { printf("%s", str(args->filename)); }
37. 37 Built-ins - Special variables - args: arguments associated with probe - comm: program name of current process - pid: ID of current process
38. 38 tracepoint:syscalls:sys_enter_open /comm == "super-important"/ { printf("%s", str(args->filename)); }
39. 39 tracepoint:syscalls:sys_enter_open /comm == "super-important"/ { printf("%s", str(args->filename)); }
40. 40 $ bpftrace -vl 'tracepoint:syscalls:sys_enter_open' tracepoint:syscalls:sys_enter_open int __syscall_nr const char * filename /* string pointer, need str() to read */ …
41. 41 tracepoint:syscalls:sys_enter_open /comm == "super-important"/ { printf("%s", str(args->filename)); }
42. 42 tracepoint:syscalls:sys_enter_open /comm == "super-important"/ { printf("%s", str(args->filename)); }
43. 43 Functions - Helpers provided by bpftrace - printf(): printing with formatting - str(): convert string pointer to actual string
44. 44 tracepoint:syscalls:sys_enter_open /comm == "super-important"/ { printf("%s", str(args->filename)); }
45. 45 tracepoint:syscalls:sys_enter_open /comm == "super-important"/ { printf("%s", 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 == "super-important"/ { printf("%s", str(args->filename)); }
48. 48 Syntax probe [/predicate/] { action }
49. 49 tracepoint:syscalls:sys_enter_open /comm == "super-important"/ { printf("%s", str(args->filename)); }
50. 50 tracepoint:syscalls:sys_enter_open { if (comm != "super-important") { return; } printf("%s", str(args->filename));
51. 51 tracepoint:syscalls:sys_enter_open /comm == "super-important"/ { printf("%s", str(args->filename)); }
52. 52 Syntax probe[, probe, …] /predicate/ { action }
53. 53 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == "super-important"/ { printf("%s", str(args->filename)); }
54. 54 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == "super-important"/ { printf("%s", str(args->filename)); }
55. 55 Doing more with bpftrace
56. 56 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == "super-important"/ { printf("%s", str(args->filename)); }
57. 57 Built-ins - Special variables - $1, $2, …: nth positional parameter passed to the bpftrace program
58. 58 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { printf("%s", str(args->filename));
59. 59 #!/usr/bin/bpftrace tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { printf("%s", str(args->filename));
60. 60 #!/usr/bin/bpftrace tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { printf("%s", str(args->filename));
61. 61 $ ./opensnoop.bt 'super-important' Attaching 3 probes… /etc/super-important-special.conf
62. 62 $ ./opensnoop.bt 'super-important' Attaching 3 probes… /etc/super-important-special.conf
63. 63 $ ./opensnoop.bt 'super-important' Attaching 3 probes… /etc/super-important-special.conf # successful???
64. 64 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { printf("%s", str(args->filename)); }
65. 65 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { printf("%s", str(args->filename)); }
66. 66 $ bpftrace -vl 'tracepoint:syscalls:sys_exit_open' tracepoint:syscalls:sys_exit_open int __syscall_nr long ret /* return code */
67. 67 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { printf("%d", args->ret); }
68. 68 tracepoint:syscalls:sys_enter_open … /comm == str($1)/ { printf("%s", str(args->filename)); } tracepoint:syscalls:sys_exit_open … /comm == str($1)/ { printf("%d", args->ret); }
69. 69 $ ./opensnoop2.bt 'super-important' Attaching 6 probes… /lib64/libc.so.6 3 /etc/super-important-special.conf -2
70. 70 $ ./opensnoop2.bt 'super-important' Attaching 6 probes… /lib64/libc.so.6 3 /etc/super-important-special.conf -2
71. 71 tracepoint:syscalls:sys_enter_open … /comm == str($1)/ { str(args->filename)??? } tracepoint:syscalls:sys_exit_open … /comm == str($1)/ { printf("%s %d", args->filename???, args->ret); }
72. - A BPF memory object, e.g. @filename - storage area - (usually) key-value map - i.e. similar to a global variable 72 Map Variable
73. 73 tracepoint:syscalls:sys_enter_open … /comm == str($1)/ { @filename = str(args->filename); } tracepoint:syscalls:sys_exit_open … /comm == str($1)/ { printf("%s: %d", @filename, args->ret); }
74. 74 $ ./opensnoop3.bt 'super-important' Attaching 6 probes… /lib64/libc.so.6: 3 /etc/your-own-special.conf: -2
75. 75 tracepoint:syscalls:sys_enter_open … /comm == str($1)/ { @filename = str(args->filename); } tracepoint:syscalls:sys_exit_open … /… && args->ret < 0 / { printf("%s: %d", @filename, args->ret); }
76. 76 $ ./opensnoop4.bt 'super-important' Attaching 6 probes… /etc/your-own-special.conf: -2
77. 77 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1) && !!@files[tid]/ { printf("%s: %d\n", args->filename, args->ret); delete(@files[tid]); /* Remove used value */
78. 78 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 */
79. 79 Calculating with bpftrace
80. 80 Operators and Expressions - Supports arithmetic operators - + - * / - Logical (&&), Bitwise (^ |), and Relational (<= !=) works, too
81. 81 Latency - How long does it take? - Get a timestamp when started - Get a timestamp when ended - Calculate difference between the timestamps
82. 82 Functions - Helpers provided by bpftrace - nsecs(): returns a timestamp in nanoseconds - can drop parenthesis when no argument
83. tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { @start = nsecs(); /* Record start time */ } 83
84. 84 tracepoint:syscalls:sys_enter_open, tracepoint:syscalls:sys_enter_openat* /comm == str($1)/ { @start = nsecs(); /* Record start time */ }
85. 85 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { $duration = nsecs() - @start; /* end - start */ printf("Took %d\n", $duration);
86. 86 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { $duration = nsecs() - @start; /* end - start */ printf("Took %d\n", $duration);
87. 87 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { $duration = nsecs() - @start; /* end - start */ printf("Took %d\n", $duration);
88. 88 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { $duration = nsecs() - @start; /* end - start */ printf("Took %d\n", $duration);
89. - Lexical-scoped variable, e.g. $duration - stores simple values - numbers (int, long, …), strings - i.e. similar to a local variable 89 Scratch Variable
90. 90 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { $duration = nsecs() - @start; /* end - start */ printf("Took %d\n", $duration);
91. 91 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { $duration = nsecs() - @start; /* end - start */ printf("Took %d\n", $duration);
92. 92 $ ./sys_latency.bt 'super-important' Attaching 6 probes... Took 18791ns Took 8102ns Took 115726ns Took 9762ns
93. 93 Dealing with Lots of Data - What if open() was calls 1k times per seconds? - Statistics to the rescue: - minimum, maximum, average, sum - quantile, histogram, time-series
94. 94 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { $duration = nsecs - @start; /* end - start */ printf("Took %d\n", $duration);
95. 95 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { $duration = nsecs - @start; /* end - start */ printf("Took %d\n", $duration);
96. 96 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { $duration = nsecs - @start; /* end - start */ @latency = hist($duration);
97. 97 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { $duration = nsecs - @start; /* end - start */ @latency = hist($duration);
98. 98 tracepoint:syscalls:sys_exit_open, tracepoint:syscalls:sys_exit_openat* /comm == str($1)/ { $duration = nsecs - @start; /* end - start */ @latency = hist($duration);
99. $ ./sys_latency_hist.bt 'super-important' @latency: [256, 512) 64 | | [512, 1K) 216818 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@| [1K, 2K) 160007 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ | [2K, 4K) 30255 |@@@@@@@ | [4K, 8K) 7114 |@ | [8K, 16K) 318 | | [16K, 32K) 150 | | 99
100. 100 What can you trace?
101. 101 Probe - Any (non-inlined) function in kernel or application - TCP connection change -> kernel’s tcp_set_state() - read/write to disk -> tracepoint:block:block_io - database query -> MySQL/Postgres query__start() - interactive shell usage -> bash’s readline()
102. 102 Why bpftrace?
103. 103 bpftrace Strengths 1. Safe 2. Dynamic Tracing 3. Low Overhead 4. Easy
104. 104 bpftrace Strengths 1. Safe 2. Dynamic Tracing 3. Low Overhead 4. Easy eBPF
105. 105 bpftrace Strengths 1. Safe 2. Dynamic Tracing 3. Low Overhead 4. Easy eBPF Make kernel programming possible for everyone
106. 106 bpftrace Strengths 1. Safe 2. Dynamic Tracing 3. Low Overhead 4. Easy eBPF Image from https://ebpf.io/what-is-ebpf/
107. 107 bpftrace Strengths 1. Safe 2. Dynamic Tracing 3. Low Overhead 4. Easy
108. 108 Comparing with Alternatives 1. Adding debug statements/printf() 2. Use debugger 3. Similar Tools
109. 109 Adding printf() - Needs to recompile and restart the process - more than once (?) - No Heisenbug
110. 110 Using Debugger - Stop the world - Reproducer required
111. 111 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
112. 112 Where To Go From Here?
113. 113 Install bpftrace openSUSE/SLES zypper install bpftrace bpftrace-tools Debian/Ubuntu apt-get install bpftrace Alma/CentOS/RHEL/Rocky dnf install bpftrace
114. $ sudo bpftrace -e 'BEGIN { print("Hello World!"); exit(0); }' Attaching 1 probe... Hello World! 114
115. $ 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 115
116. 116 Resources Book - BPF Performance Tools 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
117. 117 Thank you for listening!
118. 118 Appendix