Merge pull request #409 from goldshtn/trace2

trace: trace function execution with custom format strings and filters

README.md

@@ -108,6 +108,7 @@ Tools:
 - tools/[tcpconnect](tools/tcpconnect.py): Trace TCP active connections (connect()). [Examples](tools/tcpconnect_example.txt).
 - tools/[tcpconnlat](tools/tcpconnlat.py): Trace TCP active connection latency (connect()). [Examples](tools/tcpconnlat_example.txt).
 - tools/[tcpretrans](tools/tcpretrans.py): Trace TCP retransmits and TLPs. [Examples](tools/tcpretrans_example.txt).
+- tools/[trace](tools/trace.py): Trace arbitrary functions, with filters. [Examples](tools/trace_example.txt)
 - tools/[vfscount](tools/vfscount.py) tools/[vfscount.c](tools/vfscount.c): Count VFS calls. [Examples](tools/vfscount_example.txt).
 - tools/[vfsstat](tools/vfsstat.py) tools/[vfsstat.c](tools/vfsstat.c): Count some VFS calls, with column output. [Examples](tools/vfsstat_example.txt).
 - tools/[wakeuptime](tools/wakeuptime.py): Summarize sleep to wakeup time by waker kernel stack. [Examples](tools/wakeuptime_example.txt).

man/man8/trace.8

+.TH trace 8  "2016-02-18" "USER COMMANDS"
+.SH NAME
+trace \- Trace a function and print its arguments or return value, optionally evaluating a filter. Uses Linux eBPF/bcc.
+.SH SYNOPSIS
+.B trace [-h] [-p PID] [-v] [-Z STRING_SIZE] [-S] [-M MAX_EVENTS] [-o] probe [probe ...]
+.SH DESCRIPTION
+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. 
+
+Since this uses BPF, only the root user can use this tool.
+.SH REQUIREMENTS
+CONFIG_BPF and bcc.
+.SH OPTIONS
+.TP
+\-h
+Print usage message.
+.TP
+\-p PID
+Trace only functions in the process PID.
+.TP
+\-v
+Display the generated BPF program, for debugging purposes.
+.TP
+\-z STRING_SIZE
+When collecting string arguments (of type char*), collect up to STRING_SIZE 
+characters. Longer strings will be truncated.
+.TP
+\-S
+If set, trace messages from trace's own process. By default, this is off to
+avoid tracing storms -- for example, if you trace the write system call, and
+consider that trace is writing to the standard output.
+.TP
+\-M MAX_EVENTS
+Print up to MAX_EVENTS trace messages and then exit.
+.TP
+\-o
+Print times relative to the beginning of the trace (offsets), in seconds. The
+default is to print absolute time.
+.TP
+probe [probe ...]
+One or more probes that attach to functions, filter conditions, and print
+information. See PROBE SYNTAX below.
+.SH PROBE SYNTAX
+The general probe syntax is as follows:
+
+.B [{p,r}]:[library]:function [(predicate)] ["format string"[, arguments]]
+.TP
+.B [{p,r}]
+Probe type \- "p" for function entry, "r" for function return. The default
+probe type is "p".
+.TP
+.B [library]
+Library containing the probe.
+Specify the full path to the .so or executable file where the function to probe
+resides. Alternatively, you can specify just the lib name: for example, "c"
+refers to libc. If no library name is specified, the kernel is assumed. Also,
+you can specify an executable name (without a full path) if it is in the PATH.
+For example, "bash".
+.TP
+.B function
+The function to probe.
+.TP
+.B [(predicate)]
+The filter applied to the captured data. Only if the filter evaluates as true,
+the trace message will be printed. The filter can use any valid C expression
+that refers to the argument values: arg1, arg2, etc., or to the return value
+retval in a return probe. If necessary, use C cast operators to coerce the
+arguments to the desired type. For example, if arg1 is of type int, use the
+expression ((int)arg1 < 0) to trace only invocations where arg1 is negative.
+Note that only arg1-arg6 are supported, and only if the function is using the
+standard x86_64 convention where the first six arguments are in the RDI, RSI, 
+RDX, RCX, R8, R9 registers. If no predicate is specified, all function 
+invocations are traced.
+.TP
+.B ["format string"[, arguments]]
+A printf-style format string that will be used for the trace message. You can
+use the following format specifiers: %s, %d, %u, %lld, %llu, %hd, %hu, %c,
+%x, %llx -- with the same semantics as printf's. Make sure to pass the exact
+number of arguments as there are placeholders in the format string. The
+format specifier replacements may be any C expressions, and may refer to the
+same special keywords as in the predicate (arg1, arg2, etc.).
+
+The predicate expression and the format specifier replacements for printing
+may also use the following special keywords: $pid, $tgid to refer to the 
+current process' pid and tgid; $uid, $gid to refer to the current user's
+uid and gid; $cpu to refer to the current processor number.
+.SH EXAMPLES
+.TP
+Trace all invocations of the open system call with the name of the file being opened:
+#
+.B trace '::do_sys_open """%s"", arg2'
+.TP
+Trace all invocations of the read system call where the number of bytes requested is greater than 20,000:
+#
+.B trace '::sys_read (arg3 > 20000) """read %d bytes"", arg3'
+.TP
+Trace all malloc calls and print the size of the requested allocation:
+#
+.B trace ':c:malloc """size = %d"", arg1'
+.TP
+Trace returns from the readline function in bash and print the return value as a string:
+#
+.B trace 'r:bash:readline """%s"", retval' 
+.SH SOURCE
+This is from bcc.
+.IP
+https://github.com/iovisor/bcc
+.PP
+Also look in the bcc distribution for a companion _examples.txt file containing
+example usage, output, and commentary for this tool.
+.SH OS
+Linux
+.SH STABILITY
+Unstable - in development.
+.SH AUTHOR
+Sasha Goldshtein

tools/trace_example.txt

+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'
+TIME     PID    COMM         FUNC             -
+05:11:51 4402   bash         sys_execve       /usr/bin/man
+05:11:51 4411   man          sys_execve       /usr/local/bin/less
+05:11:51 4411   man          sys_execve       /usr/bin/less
+05:11:51 4410   man          sys_execve       /usr/local/bin/nroff
+05:11:51 4410   man          sys_execve       /usr/bin/nroff
+05:11:51 4409   man          sys_execve       /usr/local/bin/tbl
+05:11:51 4409   man          sys_execve       /usr/bin/tbl
+05:11:51 4408   man          sys_execve       /usr/local/bin/preconv
+05:11:51 4408   man          sys_execve       /usr/bin/preconv
+05:11:51 4415   nroff        sys_execve       /usr/bin/locale
+05:11:51 4416   nroff        sys_execve       /usr/bin/groff
+05:11:51 4418   groff        sys_execve       /usr/bin/grotty
+05:11:51 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'
+TIME     PID    COMM         FUNC             -
+05:18:23 4490   dd           sys_read         read 1048576 bytes
+05:18:23 4490   dd           sys_read         read 1048576 bytes
+05:18:23 4490   dd           sys_read         read 1048576 bytes
+05:18:23 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'
+TIME     PID    COMM         FUNC             -
+05:24:50 2740   bash         readline         echo hi!
+05:24:53 2740   bash         readline         man ls
+^C
+
+The special retval keywords 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").
+
+Multiple probes can be combined on the same command line. For example, let's
+trace failed read and write calls on the libc level:
+
+# trace 'r:c:read ((int)retval < 0) "read failed: %d", retval' \
+        'r:c:write ((int)retval < 0) "write failed: %d", retval'
+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.
+
+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'
+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.
+
+
+USAGE message:
+
+# trace -h
+usage: trace.py [-h] [-p PID] [-v] [-Z STRING_SIZE] [-S] [-M MAX_EVENTS] [-o]
+                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
+  -p PID, --pid PID     id of the process 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
+  -o, --offset          use relative time from first traced message
+
+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_return
+        Trace the return from the open syscall
+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 = %p", retval
+        Trace returns from malloc and print non-NULL allocated buffers
+