Lines Matching +full:system +full:- +full:trace
1 Demonstrations of trace.
4 trace probes functions you specify and displays trace messages if a particular
8 For example, suppose you want to trace all commands being exec'd across the
9 system:
11 # trace 'sys_execve "%s", arg1'
12 PID COMM FUNC -
32 to be the command that is exec'd. The above trace was generated by executing
36 Next, suppose you are looking for large reads across the system. Let's trace
37 the read system call and inspect the third argument, which is the number of
40 # trace 'sys_read (arg3 > 20000) "read %d bytes", arg3'
41 PID COMM FUNC -
48 During the trace, I executed "dd if=/dev/zero of=/dev/null bs=1M count=4".
57 # trace 'do_sys_open "%s", arg2@user' -UK -f temp
58 PID TID COMM FUNC -
63 __open_nocancel+0x7 [libc-2.17.so]
64 __libc_start_main+0xf5 [libc-2.17.so]
69 __open_nocancel+0x7 [libc-2.17.so]
70 __libc_start_main+0xf5 [libc-2.17.so]
74 # trace 'do_sys_open "%s", arg2@user' -UK -n out
75 PID TID COMM FUNC -
80 __open_nocancel+0x7 [libc-2.17.so]
81 __libc_start_main+0xf5 [libc-2.17.so]
83 You can also trace user functions. For example, let's simulate the bashreadline
85 value, effectively snooping all bash shell input across the system:
87 # trace 'r:bash:readline "%s", retval'
88 PID COMM FUNC -
100 flags to print the kernel stack (-K), the user stack (-U) and optionally
101 include the virtual address in the stacks as well (-a):
103 # trace.py -U -a 'r::sys_futex "%d", retval'
104 PID TID COMM FUNC -
106 7f6c72b6497a __lll_unlock_wake+0x1a [libpthread-2.23.so]
109 7f6c72b5b7a9 start_thread+0xd9 [libpthread-2.23.so]
110 7f6c7223fa7d clone+0x6d [libc-2.23.so]
113 trace failed read and write calls on the libc level, and include a time column:
115 # trace 'r:c:read ((int)retval < 0) "read failed: %d", retval' \
116 'r:c:write ((int)retval < 0) "write failed: %d", retval' -T
117 TIME PID COMM FUNC -
118 05:31:57 3388 bash write write failed: -1
119 05:32:00 3388 bash write write failed: -1
123 The reason is that the default type for argN and retval is an unsigned 64-bit
126 trace has also some basic support for kernel tracepoints. For example, let's
127 trace the block:block_rq_complete tracepoint and print out the number of sectors
130 # trace 't:block:block_rq_complete "sectors=%d", args->nr_sector' -T
131 TIME PID COMM FUNC -
137 Suppose that you want to trace a system-call in a short-lived process, you can use
138 the -s option to trace. The option is followed by list of libraries/executables to
140 # trace -s /lib/x86_64-linux-gnu/libc.so.6,/bin/ping 'p:c:inet_pton' -U
148 During the trace, 'ping -c1 google.com' was executed to obtain the above results
153 # tplist -v block:block_rq_complete
161 This output tells you that you can use "args->dev", "args->sector", etc. in your
162 predicate and trace arguments.
165 More and more high-level libraries are instrumented with USDT probe support.
166 These probes can be traced by trace just like kernel tracepoints. For example,
167 trace new threads being created and their function name, include time column
170 # trace 'u:pthread:pthread_create "%U", arg3' -T -C
171 TIME CPU PID TID COMM FUNC -
180 The "%U" format specifier tells trace to resolve arg3 as a user-space symbol,
184 trace Ruby methods being called (this requires a version of Ruby built with
185 the --enable-dtrace configure flag):
187 # trace 'u:ruby:method__entry "%s.%s", arg1, arg2' -p $(pidof irb) -T
188 TIME PID COMM FUNC -
197 You can also trace exported functions from shared libraries, or an imported
200 # sudo ./trace.py 'r:/usr/lib64/libtinfo.so:curses_version "Version=%s", retval'
201 # tput -V
203 PID TID COMM FUNC -
211 # trace 'p:c:open (STRCMP("test.txt", arg1)) "opening %s", arg1' -T
212 TIME PID COMM FUNC -
220 lets you access structure sub-fields, which is hard with the "arg1", "arg2"
223 # trace 'p:c:open(char *filename) "opening %s", filename'
224 PID TID COMM FUNC -
228 # trace 'p::SyS_nanosleep(struct timespec *ts) "sleep for %lld ns", ts->tv_nsec'
229 PID TID COMM FUNC -
236 Remember to use the -I argument include the appropriate header file. We didn't
240 To aggregate amount of trace, you need specify -A with -M EVENTS. A typical
244 3, to confirm kernel timer setting frequence by 'funccount -i 1 clockevents_program_event'
245 4, to trace timer setting by 'trace clockevents_program_event -K -A -M 1000'
263 -->COUNT 271
267 As a final example, let's trace open syscalls for a specific process. By
268 default, tracing is system-wide, but the -p switch overrides this:
270 # trace -p 2740 'do_sys_open "%s", arg2@user' -T
271 TIME PID COMM FUNC -
281 05:36:16 15872 ls do_sys_open /usr/lib/locale/locale-archive
289 Lastly, if a high-frequency event is traced you may overflow the perf ring
292 # trace sys_open
302 The perf ring buffer size can be changed with -b. The unit is size per-CPU buffer
306 …trace.py 'sys_setsockopt(int fd, int level, int optname, char* optval, int optlen)(level==0 && opt…
307 PID TID COMM FUNC -
312 STRCMP helper in binary mode (--bin_cmp flag) to compare optval array
329 After compiling the code with -O3 optimization the object code looks
332 objdump --disassemble=main --prefix-addresses a.out
353 with trace lets insert probes to those offsets. The following
358 trace 'p:/tmp/a.out:main+0xd "%x", ctx->dx' 'p:/tmp/a.out:main+0x25 "%x", ctx->dx'
359 PID TID COMM FUNC -
366 usage: trace [-h] [-b BUFFER_PAGES] [-p PID] [-L TID] [--uid UID] [-v]
367 [-Z STRING_SIZE] [-S] [-M MAX_EVENTS] [-t] [-u] [-T] [-C]
368 [-c CGROUP_PATH] [-n NAME] [-f MSG_FILTER] [-B]
369 [-s SYM_FILE_LIST] [-K] [-U] [-a] [-I header]
372 Attach to functions and print trace messages.
378 -h, --help show this help message and exit
379 -b BUFFER_PAGES, --buffer-pages BUFFER_PAGES
382 -p PID, --pid PID id of the process to trace (optional)
383 -L TID, --tid TID id of the thread to trace (optional)
384 --uid UID id of the user to trace (optional)
385 -v, --verbose print resulting BPF program code before executing
386 -Z STRING_SIZE, --string-size STRING_SIZE
388 -S, --include-self do not filter trace's own pid from the trace
389 -M MAX_EVENTS, --max-events MAX_EVENTS
391 -t, --timestamp print timestamp column (offset from trace start)
392 -u, --unix-timestamp print UNIX timestamp instead of offset from trace
393 start, requires -t
394 -T, --time print time column
395 -C, --print_cpu print CPU id
396 -c CGROUP_PATH, --cgroup-path CGROUP_PATH
398 -n NAME, --name NAME only print process names containing this name
399 -f MSG_FILTER, --msg-filter MSG_FILTER
401 -B, --bin_cmp allow to use STRCMP with binary values
402 -s SYM_FILE_LIST, --sym_file_list SYM_FILE_LIST
405 -K, --kernel-stack output kernel stack trace
406 -U, --user-stack output user stack trace
407 -a, --address print virtual address in stacks
408 -I header, --include header
413 -A, --aggregate aggregate amount of each trace
417 trace do_sys_open
418 Trace the open syscall and print a default trace message when entered
419 trace kfree_skb+0x12
420 Trace the kfree_skb kernel function after the instruction on the 0x12 offset
421 trace 'do_sys_open "%s", arg2@user'
422 Trace the open syscall and print the filename being opened @user is
427 trace 'do_sys_open "%s", arg2@user' -n main
428 Trace the open syscall and only print event that process names containing "main"
429 trace 'do_sys_open "%s", arg2@user' --uid 1001
430 Trace the open syscall and only print event that processes with user ID 1001
431 trace 'do_sys_open "%s", arg2@user' -f config
432 Trace the open syscall and print the filename being opened filtered by "config"
433 trace 'sys_read (arg3 > 20000) "read %d bytes", arg3'
434 Trace the read syscall and print a message for reads >20000 bytes
435 trace 'r::do_sys_open "%llx", retval'
436 Trace the return from the open syscall and print the return value
437 trace 'c:open (arg2 == 42) "%s %d", arg1, arg2'
438 Trace the open() call from libc only if the flags (arg2) argument is 42
439 trace 'c:malloc "size = %d", arg1'
440 Trace malloc calls and print the size being allocated
441 trace 'p:c:write (arg1 == 1) "writing %d bytes to STDOUT", arg3'
442 Trace the write() call from libc to monitor writes to STDOUT
443 trace 'r::__kmalloc (retval == 0) "kmalloc failed!"'
444 Trace returns from __kmalloc which returned a null pointer
445 trace 'r:c:malloc (retval) "allocated = %x", retval'
446 Trace returns from malloc and print non-NULL allocated buffers
447 trace 't:block:block_rq_complete "sectors=%d", args->nr_sector'
448 Trace the block_rq_complete kernel tracepoint and print # of tx sectors
449 trace 'u:pthread:pthread_create (arg4 != 0)'
450 Trace the USDT probe pthread_create when its 4th argument is non-zero
451 trace 'u:pthread:libpthread:pthread_create (arg4 != 0)'
453 trace 'p::SyS_nanosleep(struct timespec *ts) "sleep for %lld ns", ts->tv_nsec'
454 Trace the nanosleep syscall and print the sleep duration in ns
455 trace -c /sys/fs/cgroup/system.slice/workload.service '__x64_sys_nanosleep' '__x64_sys_clone'
456 Trace nanosleep/clone syscall calls only under workload.service
458 trace -I 'linux/fs.h' \
459 'p::uprobe_register(struct inode *inode) "a_ops = %llx", inode->i_mapping->a_ops'
460 Trace the uprobe_register inode mapping ops, and the symbol can be found
462 trace -I 'kernel/sched/sched.h' \
463 'p::__account_cfs_rq_runtime(struct cfs_rq *cfs_rq) "%d", cfs_rq->runtime_remaining'
464 Trace the cfs scheduling runqueue remaining runtime. The struct cfs_rq is defined
465 in kernel/sched/sched.h which is in kernel source tree and not in kernel-devel
468 trace -I 'net/sock.h' \
469 'udpv6_sendmsg(struct sock *sk) (sk->sk_dport == 13568)'
470 Trace udpv6 sendmsg calls only if socket's destination port is equal
472 trace -I 'linux/fs_struct.h' 'mntns_install "users = %d", $task->fs->users'
473 Trace the number of users accessing the file system of the current task
474 trace -s /lib/x86_64-linux-gnu/libc.so.6,/bin/ping 'p:c:inet_pton' -U
475 Trace inet_pton system call and use the specified libraries/executables for