forked from iovisor/bcc
/
trace_example.txt
386 lines (321 loc) · 17.6 KB
/
trace_example.txt
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
Demonstrations of trace.
trace probes functions you specify and displays trace messages if a particular
condition is met. You can control the message format to display function
arguments and return values.
For example, suppose you want to trace all commands being exec'd across the
system:
# trace 'sys_execve "%s", arg1'
PID COMM FUNC -
4402 bash sys_execve /usr/bin/man
4411 man sys_execve /usr/local/bin/less
4411 man sys_execve /usr/bin/less
4410 man sys_execve /usr/local/bin/nroff
4410 man sys_execve /usr/bin/nroff
4409 man sys_execve /usr/local/bin/tbl
4409 man sys_execve /usr/bin/tbl
4408 man sys_execve /usr/local/bin/preconv
4408 man sys_execve /usr/bin/preconv
4415 nroff sys_execve /usr/bin/locale
4416 nroff sys_execve /usr/bin/groff
4418 groff sys_execve /usr/bin/grotty
4417 groff sys_execve /usr/bin/troff
^C
The ::sys_execve syntax specifies that you want an entry probe (which is the
default), in a kernel function (which is the default) called sys_execve. Next,
the format string to print is simply "%s", which prints a string. Finally, the
value to print is the first argument to the sys_execve function, which happens
to be the command that is exec'd. The above trace was generated by executing
"man ls" in a separate shell. As you see, man executes a number of additional
programs to finally display the man page.
Next, suppose you are looking for large reads across the system. Let's trace
the read system call and inspect the third argument, which is the number of
bytes to be read:
# trace 'sys_read (arg3 > 20000) "read %d bytes", arg3'
PID COMM FUNC -
4490 dd sys_read read 1048576 bytes
4490 dd sys_read read 1048576 bytes
4490 dd sys_read read 1048576 bytes
4490 dd sys_read read 1048576 bytes
^C
During the trace, I executed "dd if=/dev/zero of=/dev/null bs=1M count=4".
The individual reads are visible, with the custom format message printed for
each read. The parenthesized expression "(arg3 > 20000)" is a filter that is
evaluated for each invocation of the probe before printing anything.
Event message filter is useful while you only interesting the specific event.
Like the program open thousands file and you only want to see the "temp" file
and print stack.
# trace 'do_sys_open "%s", arg2' -UK -f temp
PID TID COMM FUNC -
9557 9557 a.out do_sys_open temp.1
do_sys_open+0x1 [kernel]
do_syscall_64+0x5b [kernel]
entry_SYSCALL_64_after_hwframe+0x44 [kernel]
__open_nocancel+0x7 [libc-2.17.so]
__libc_start_main+0xf5 [libc-2.17.so]
9558 9558 a.out do_sys_open temp.2
do_sys_open+0x1 [kernel]
do_syscall_64+0x5b [kernel]
entry_SYSCALL_64_after_hwframe+0x44 [kernel]
__open_nocancel+0x7 [libc-2.17.so]
__libc_start_main+0xf5 [libc-2.17.so]
Process name filter is porting from tools/opensnoop
# trace 'do_sys_open "%s", arg2' -UK -n out
PID TID COMM FUNC -
9557 9557 a.out do_sys_open temp.1
do_sys_open+0x1 [kernel]
do_syscall_64+0x5b [kernel]
entry_SYSCALL_64_after_hwframe+0x44 [kernel]
__open_nocancel+0x7 [libc-2.17.so]
__libc_start_main+0xf5 [libc-2.17.so]
You can also trace user functions. For example, let's simulate the bashreadline
script, which attaches to the readline function in bash and prints its return
value, effectively snooping all bash shell input across the system:
# trace 'r:bash:readline "%s", retval'
PID COMM FUNC -
2740 bash readline echo hi!
2740 bash readline man ls
^C
The special retval keyword stands for the function's return value, and can
be used only in a retprobe, specified by the 'r' prefix. The next component
of the probe is the library that contains the desired function. It's OK to
specify executables too, as long as they can be found in the PATH. Or, you
can specify the full path to the executable (e.g. "/usr/bin/bash").
Sometimes it can be useful to see where in code the events happen. There are
flags to print the kernel stack (-K), the user stack (-U) and optionally
include the virtual address in the stacks as well (-a):
# trace.py -U -a 'r::sys_futex "%d", retval'
PID TID COMM FUNC -
793922 793951 poller sys_futex 0
7f6c72b6497a __lll_unlock_wake+0x1a [libpthread-2.23.so]
627fef folly::FunctionScheduler::run()+0x46f [router]
7f6c7345f171 execute_native_thread_routine+0x21 [libstdc++.so.6.0.21]
7f6c72b5b7a9 start_thread+0xd9 [libpthread-2.23.so]
7f6c7223fa7d clone+0x6d [libc-2.23.so]
Multiple probes can be combined on the same command line. For example, let's
trace failed read and write calls on the libc level, and include a time column:
# trace 'r:c:read ((int)retval < 0) "read failed: %d", retval' \
'r:c:write ((int)retval < 0) "write failed: %d", retval' -T
TIME PID COMM FUNC -
05:31:57 3388 bash write write failed: -1
05:32:00 3388 bash write write failed: -1
^C
Note that the retval variable must be cast to int before comparing to zero.
The reason is that the default type for argN and retval is an unsigned 64-bit
integer, which can never be smaller than 0.
trace has also some basic support for kernel tracepoints. For example, let's
trace the block:block_rq_complete tracepoint and print out the number of sectors
transferred:
# trace 't:block:block_rq_complete "sectors=%d", args->nr_sector' -T
TIME PID COMM FUNC -
01:23:51 0 swapper/0 block_rq_complete sectors=8
01:23:55 10017 kworker/u64: block_rq_complete sectors=1
01:23:55 0 swapper/0 block_rq_complete sectors=8
^C
Suppose that you want to trace a system-call in a short-lived process, you can use
the -s option to trace. The option is followed by list of libraries/executables to
use for symbol resolution.
# trace -s /lib/x86_64-linux-gnu/libc.so.6,/bin/ping 'p:c:inet_pton' -U
Note: Kernel bpf will report stack map with ip/build_id
PID TID COMM FUNC
4175 4175 ping inet_pton
inet_pton+0x136340 [libc.so.6]
getaddrinfo+0xfb510 [libc.so.6]
_init+0x2a08 [ping]
During the trace, 'ping -c1 google.com' was executed to obtain the above results
To discover the tracepoint structure format (which you can refer to as the "args"
pointer variable), use the tplist tool. For example:
# tplist -v block:block_rq_complete
block:block_rq_complete
dev_t dev;
sector_t sector;
unsigned int nr_sector;
int errors;
char rwbs[8];
This output tells you that you can use "args->dev", "args->sector", etc. in your
predicate and trace arguments.
More and more high-level libraries are instrumented with USDT probe support.
These probes can be traced by trace just like kernel tracepoints. For example,
trace new threads being created and their function name, include time column
and on which CPU it happened:
# trace 'u:pthread:pthread_create "%U", arg3' -T -C
TIME CPU PID TID COMM FUNC -
13:22:01 25 2627 2629 automount pthread_create expire_proc_indirect+0x0 [automount]
13:22:01 5 21360 21414 osqueryd pthread_create [unknown] [osqueryd]
13:22:03 25 2627 2629 automount pthread_create expire_proc_indirect+0x0 [automount]
13:22:04 15 21360 21414 osqueryd pthread_create [unknown] [osqueryd]
13:22:07 25 2627 2629 automount pthread_create expire_proc_indirect+0x0 [automount]
13:22:07 4 21360 21414 osqueryd pthread_create [unknown] [osqueryd]
^C
The "%U" format specifier tells trace to resolve arg3 as a user-space symbol,
if possible. Similarly, use "%K" for kernel symbols.
Ruby, Node, and OpenJDK are also instrumented with USDT. For example, let's
trace Ruby methods being called (this requires a version of Ruby built with
the --enable-dtrace configure flag):
# trace 'u:ruby:method__entry "%s.%s", arg1, arg2' -p $(pidof irb) -T
TIME PID COMM FUNC -
12:08:43 18420 irb method__entry IRB::Context.verbose?
12:08:43 18420 irb method__entry RubyLex.ungetc
12:08:43 18420 irb method__entry RuxyLex.debug?
^C
In the previous invocation, arg1 and arg2 are the class name and method name
for the Ruby method being invoked.
You can also trace exported functions from shared libraries, or an imported
function on the actual executable:
# sudo ./trace.py 'r:/usr/lib64/libtinfo.so:curses_version "Version=%s", retval'
# tput -V
PID TID COMM FUNC -
21720 21720 tput curses_version Version=ncurses 6.0.20160709
^C
Occasionally, it can be useful to filter specific strings. For example, you
might be interested in open() calls that open a specific file:
# trace 'p:c:open (STRCMP("test.txt", arg1)) "opening %s", arg1' -T
TIME PID COMM FUNC -
01:43:15 10938 cat open opening test.txt
01:43:20 10939 cat open opening test.txt
^C
In the preceding example, as well as in many others, readability may be
improved by providing the function's signature, which names the arguments and
lets you access structure sub-fields, which is hard with the "arg1", "arg2"
convention. For example:
# trace 'p:c:open(char *filename) "opening %s", filename'
PID TID COMM FUNC -
17507 17507 cat open opening FAQ.txt
^C
# trace 'p::SyS_nanosleep(struct timespec *ts) "sleep for %lld ns", ts->tv_nsec'
PID TID COMM FUNC -
777 785 automount SyS_nanosleep sleep for 500000000 ns
777 785 automount SyS_nanosleep sleep for 500000000 ns
777 785 automount SyS_nanosleep sleep for 500000000 ns
777 785 automount SyS_nanosleep sleep for 500000000 ns
^C
Remember to use the -I argument include the appropriate header file. We didn't
need to do that here because `struct timespec` is used internally by the tool,
so it always includes this header file.
As a final example, let's trace open syscalls for a specific process. By
default, tracing is system-wide, but the -p switch overrides this:
# trace -p 2740 'do_sys_open "%s", arg2' -T
TIME PID COMM FUNC -
05:36:16 15872 ls do_sys_open /etc/ld.so.cache
05:36:16 15872 ls do_sys_open /lib64/libselinux.so.1
05:36:16 15872 ls do_sys_open /lib64/libcap.so.2
05:36:16 15872 ls do_sys_open /lib64/libacl.so.1
05:36:16 15872 ls do_sys_open /lib64/libc.so.6
05:36:16 15872 ls do_sys_open /lib64/libpcre.so.1
05:36:16 15872 ls do_sys_open /lib64/libdl.so.2
05:36:16 15872 ls do_sys_open /lib64/libattr.so.1
05:36:16 15872 ls do_sys_open /lib64/libpthread.so.0
05:36:16 15872 ls do_sys_open /usr/lib/locale/locale-archive
05:36:16 15872 ls do_sys_open /home/vagrant
^C
In this example, we traced the "ls ~" command as it was opening its shared
libraries and then accessing the /home/vagrant directory listing.
Lastly, if a high-frequency event is traced you may overflow the perf ring
buffer. This shows as "Lost N samples":
# trace sys_open
5087 5087 pgrep sys_open
5087 5087 pgrep sys_open
5087 5087 pgrep sys_open
5087 5087 pgrep sys_open
5087 5087 pgrep sys_open
Lost 764896 samples
Lost 764896 samples
Lost 764896 samples
The perf ring buffer size can be changed with -b. The unit is size per-CPU buffer
size and is measured in pages. The value must be a power of two and defaults to
64 pages.
# trace.py 'sys_setsockopt(int fd, int level, int optname, char* optval, int optlen)(level==0 && optname == 1 && STRCMP("{0x6C, 0x00, 0x00, 0x00}", optval))' -U -M 1 --bin_cmp
PID TID COMM FUNC -
1855611 1863183 worker sys_setsockopt found
In this example we are catching setsockopt syscall to change IPv4 IP_TOS
value only for the cases where new TOS value is equal to 108. we are using
STRCMP helper in binary mode (--bin_cmp flag) to compare optval array
against int value of 108 (parametr of setsockopt call) in hex representation
(little endian format)
USAGE message:
usage: trace [-h] [-b BUFFER_PAGES] [-p PID] [-L TID] [-v] [-Z STRING_SIZE]
[-S] [-M MAX_EVENTS] [-t] [-T] [-K] [-U] [-a] [-I header]
probe [probe ...]
Attach to functions and print trace messages.
positional arguments:
probe probe specifier (see examples)
optional arguments:
-h, --help show this help message and exit
-b BUFFER_PAGES, --buffer-pages BUFFER_PAGES
number of pages to use for perf_events ring buffer
(default: 64)
-p PID, --pid PID id of the process to trace (optional)
-L TID, --tid TID id of the thread to trace (optional)
-v, --verbose print resulting BPF program code before executing
-Z STRING_SIZE, --string-size STRING_SIZE
maximum size to read from strings
-s SYM_FILE_LIST when collecting stack trace in build id format,
use the coma separated list for symbol resolution
-S, --include-self do not filter trace's own pid from the trace
-M MAX_EVENTS, --max-events MAX_EVENTS
number of events to print before quitting
-t, --timestamp print timestamp column (offset from trace start)
-T, --time print time column
-n NAME, --name NAME only print process names containing this name
-f MSG_FILTER, --msg-filter MSG_FILTER
only print message of event containing this string
-C, --print_cpu print CPU id
-B, --bin_cmp allow to use STRCMP with binary values
-K, --kernel-stack output kernel stack trace
-U, --user-stack output user stack trace
-a, --address print virtual address in stacks
-I header, --include header
additional header files to include in the BPF program
as either full path, or relative to current working directory,
or relative to default kernel header search path
EXAMPLES:
trace do_sys_open
Trace the open syscall and print a default trace message when entered
trace 'do_sys_open "%s", arg2'
Trace the open syscall and print the filename being opened
trace 'do_sys_open "%s", arg2' -n main
Trace the open syscall and only print event that process names containing "main"
trace 'do_sys_open "%s", arg2' -f config
Trace the open syscall and print the filename being opened filtered by "config"
trace 'sys_read (arg3 > 20000) "read %d bytes", arg3'
Trace the read syscall and print a message for reads >20000 bytes
trace 'r::do_sys_open "%llx", retval'
Trace the return from the open syscall and print the return value
trace 'c:open (arg2 == 42) "%s %d", arg1, arg2'
Trace the open() call from libc only if the flags (arg2) argument is 42
trace 'c:malloc "size = %d", arg1'
Trace malloc calls and print the size being allocated
trace 'p:c:write (arg1 == 1) "writing %d bytes to STDOUT", arg3'
Trace the write() call from libc to monitor writes to STDOUT
trace 'r::__kmalloc (retval == 0) "kmalloc failed!"'
Trace returns from __kmalloc which returned a null pointer
trace 'r:c:malloc (retval) "allocated = %x", retval'
Trace returns from malloc and print non-NULL allocated buffers
trace 't:block:block_rq_complete "sectors=%d", args->nr_sector'
Trace the block_rq_complete kernel tracepoint and print # of tx sectors
trace 'u:pthread:pthread_create (arg4 != 0)'
Trace the USDT probe pthread_create when its 4th argument is non-zero
trace 'p::SyS_nanosleep(struct timespec *ts) "sleep for %lld ns", ts->tv_nsec'
Trace the nanosleep syscall and print the sleep duration in ns
trace -c /sys/fs/cgroup/system.slice/workload.service '__x64_sys_nanosleep' '__x64_sys_clone'
Trace nanosleep/clone syscall calls only under workload.service
cgroup hierarchy.
trace -I 'linux/fs.h' \
'p::uprobe_register(struct inode *inode) "a_ops = %llx", inode->i_mapping->a_ops'
Trace the uprobe_register inode mapping ops, and the symbol can be found
in /proc/kallsyms
trace -I 'kernel/sched/sched.h' \
'p::__account_cfs_rq_runtime(struct cfs_rq *cfs_rq) "%d", cfs_rq->runtime_remaining'
Trace the cfs scheduling runqueue remaining runtime. The struct cfs_rq is defined
in kernel/sched/sched.h which is in kernel source tree and not in kernel-devel
package. So this command needs to run at the kernel source tree root directory
so that the added header file can be found by the compiler.
trace -I 'net/sock.h' \\
'udpv6_sendmsg(struct sock *sk) (sk->sk_dport == 13568)'
Trace udpv6 sendmsg calls only if socket's destination port is equal
to 53 (DNS; 13568 in big endian order)
trace -I 'linux/fs_struct.h' 'mntns_install "users = %d", $task->fs->users'
Trace the number of users accessing the file system of the current task
trace -s /lib/x86_64-linux-gnu/libc.so.6,/bin/ping 'p:c:inet_pton' -U
Trace inet_pton system call and use the specified libraries/executables for
symbol resolution.
"