| 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. |
| |
| 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 |
| |
| 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. |
| |
| |
| 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, --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 |
| -C, --print_cpu print CPU id |
| -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 '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 -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 |
| " |
