perf-tools/examples/uprobe_example.txt

Demonstrations of uprobe, the Linux ftrace version.

Trace the readline() function from all processes named "bash":

# ./uprobe p:bash:readline
Tracing uprobe readline (p:readline /bin/bash:0x8db60). Ctrl-C to end.
            bash-11886 [003] d... 19601233.618462: readline: (0x48db60)
            bash-11886 [003] d... 19601235.152067: readline: (0x48db60)
            bash-11915 [003] d... 19601238.976244: readline: (0x48db60)
^C
Ending tracing...

readline() is the bash shell's function for reading interactive input, and
a line is printed each time I entered commands in separate bash shells.
The line contains default ftrace columns: the process name, "-", and PID;
the CPU, flags, a timestamp (in units of seconds), the probe name, then
other arguments. These columns are documented in the kernel source, under
Documentation/trace/ftrace.txt.

The first line of output is informational, and shows what uprobe is really
doing: it turned "bash" into "/bin/bash", using a $PATH lookup (via which(1)).
It then turned the "readline" symbol into 0x8db60, using objdump(1) for
symbol lookups.

Note that this traces _all_ bash processes simultaneously.


Tracing PID 11886 only:

# ./uprobe -p 11886 p:bash:readline
Tracing uprobe readline (p:readline /bin/bash:0x8db60). Ctrl-C to end.
            bash-11886 [002] d... 19601657.753893: readline: (0x48db60)
            bash-11886 [002] d... 19601658.246613: readline: (0x48db60)
            bash-11886 [002] d... 19601658.386666: readline: (0x48db60)
            bash-11886 [002] d... 19601661.415952: readline: (0x48db60)
^C
Ending tracing...

This may be important if you are tracing shared library functions, and only care
about one target process.


You can specify the full path to a binary to trace:

# ./uprobe p:/bin/bash:readline
Tracing uprobe readline (p:readline /bin/bash:0x8db60). Ctrl-C to end.
            bash-11886 [002] d... 19601746.902461: readline: (0x48db60)
            bash-11886 [002] d... 19601749.543485: readline: (0x48db60)
            bash-11886 [001] d... 19601749.702369: readline: (0x48db60)
^C
Ending tracing...

This might be useful if uprobe picked the wrong binary to trace, as shown by
the informational line, and you wanted to specify it directly. It is also useful
for tracing binaries not in the $PATH, which uprobe can't otherwise find.


Use -l to list symbols available to trace; eg, searching for functions
containing "readline" in bash:

# ./uprobe -l bash | grep readline
initialize_readline
pcomp_set_readline_variables
posix_readline_initialize
readline
readline_internal_char
readline_internal_setup
readline_internal_teardown


Tracing the return of readline() with return value as a string:

# ./uprobe 'r:bash:readline +0($retval):string'
Tracing uprobe readline (r:readline /bin/bash:0x8db60 +0($retval):string). Ctrl-C to end.
            bash-11886 [003] d... 19601837.001935: readline: (0x41e876 <- 0x48db60) arg1="ls -l"
            bash-11886 [002] d... 19601851.008409: readline: (0x41e876 <- 0x48db60) arg1="echo "hello world""
            bash-11886 [002] d... 19601854.099730: readline: (0x41e876 <- 0x48db60) arg1="df -h"
            bash-11886 [002] d... 19601858.805740: readline: (0x41e876 <- 0x48db60) arg1="cd .."
            bash-11886 [003] d... 19601898.378753: readline: (0x41e876 <- 0x48db60) arg1="foo bar"
^C
Ending tracing...

Now I can see the commands entered. Note that this traces what bash reads in,
even if the command eventually fails. Eg, the last command "foo bar" didn't
work (No command 'foo' found).

Note that this invocation now uses "r:" at the start of the probe description,
instead of "p:". r is for return probes, p for entry probes.


Tracing sleep() calls in all running libc shared libraries:

# ./uprobe p:libc:sleep
Tracing uprobe sleep (p:sleep /lib/x86_64-linux-gnu/libc-2.15.so:0xbf130). Ctrl-C to end.
          svscan-2134  [000] d... 19602402.959904: sleep: (0x7f2dba562130)
            cron-923   [000] d... 19602404.640507: sleep: (0x7f3e26d9e130)
            cron-923   [002] d... 19602404.655232: sleep: (0x7f3e26d9e130)
            cron-923   [002] d... 19602405.189271: sleep: (0x7f3e26d9e130)
          svscan-2134  [000] d... 19602407.959947: sleep: (0x7f2dba562130)
[...]

This shows different programs calling sleep -- likely threads waiting for work.

I ran a "sleep 1" command in a bash shell, which wasn't seen above: probably
using a different sleep library call, which I'd need to trace separately.


Including headers (-H):

# ./uprobe -H p:libc:sleep
Tracing uprobe sleep (p:sleep /lib/x86_64-linux-gnu/libc-2.15.so:0xbf130). Ctrl-C to end.
# tracer: nop
#
# entries-in-buffer/entries-written: 0/0   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
          svscan-2134  [000] d... 19603052.976770: sleep: (0x7f2dba562130)
          svscan-2134  [002] d... 19603057.976927: sleep: (0x7f2dba562130)
[...]

These are documented in Documentation/trace/ftrace.txt.


Tracing sleep() with its argument (seconds):

# ./uprobe 'p:libc:sleep %di'
Tracing uprobe sleep (p:sleep /lib/x86_64-linux-gnu/libc-2.15.so:0xbf130 %di). Ctrl-C to end.
          svscan-2134  [002] d... 19602517.962925: sleep: (0x7f2dba562130) arg1=0x5
          svscan-2134  [002] d... 19602522.963082: sleep: (0x7f2dba562130) arg1=0x5
            cron-923   [002] d... 19602524.187733: sleep: (0x7f3e26d9e130) arg1=0x3c
          svscan-2134  [002] d... 19602527.963267: sleep: (0x7f2dba562130) arg1=0x5
[...]

So svcan was sleeping for 5 seconds, and cron for 60 seconds (0x3c = 60).

The argument is specified by its register, %di. This is platform dependent: %di
may only be meaningful on x86. If you're on a different architecture (eg, ARM),
you will probably need to use something else.

If working with registers is not for you, then consider tracing this using
perf_events with debuginfo installed: in which case you can use the variable
names. Or consider a different tracer.


Here is an example of the optional filter expression, to only trace the return
of fopen() when it failed and returned NULL (0):

# ./uprobe 'r:libc:fopen file=$retval' 'file == 0'
Tracing uprobe fopen (r:fopen /lib/x86_64-linux-gnu/libc-2.15.so:0x6e540 file=$retval). Ctrl-C to end.
           prog1-23982 [000] d... 19602894.346872: fopen: (0x40051e <- 0x7f637867f540) file=0x0
^C
Ending tracing...

The argument $retval was given a vanity name "file", which was then tested in
the filter expression "file == 0".


Tracing func_abc() in my test program, and including user-level stacks:

# ./uprobe -s p:/root/func_abc:func_c
Tracing uprobe func_c (p:func_c /root/func_abc:0x4f4). Ctrl-C to end.
        func_abc-25394 [000] d... 19603250.054040: func_c: (0x4004f4)
        func_abc-25394 [000] d... 19603250.054056: <user stack trace>
 =>  <00000000004004f4>
 =>  <0000000000400527>
 =>  <0000000000400537>
 =>  <00007fca9f0e376d>
        func_abc-25394 [000] d... 19603251.054250: func_c: (0x4004f4)
        func_abc-25394 [000] d... 19603251.054266: <user stack trace>
 =>  <00000000004004f4>
 =>  <0000000000400527>
 =>  <0000000000400537>
 =>  <00007fca9f0e376d>
^C
Ending tracing...

The output has the raw hex addresses. If this is too much of a nuisance, then
try tracing this using perf_events which should automate the translation.

It can get worse, eg:

l# ./uprobe -s p:bash:readline
Tracing uprobe readline (p:readline /bin/bash:0x8db60). Ctrl-C to end.
            bash-11886 [002] d... 19603434.397818: readline: (0x48db60)
            bash-11886 [002] d... 19603434.397832: <user stack trace>
 =>  <000000000048db60>
            bash-11886 [002] d... 19603434.592500: readline: (0x48db60)
            bash-11886 [002] d... 19603434.592510: <user stack trace>
 =>  <000000000048db60>
^C
Ending tracing...

Here the stack trace is missing (0x48db60 is the traced function, transposed
from the base load address). This is due to compiler optimizations. It can be
fixed by recompiling with -fno-omit-frame-pointer, or, using perf_events and
a different method of stack walking.


Use -h to print the USAGE message:

# ./uprobe -h
USAGE: uprobe [-FhHsv] [-d secs] [-p PID] {-l target |
              uprobe_definition [filter]}
                 -F              # force. trace despite warnings.
                 -d seconds      # trace duration, and use buffers
                 -l target       # list functions from this executable
                 -p PID          # PID to match on I/O issue
                 -v              # view format file (don't trace)
                 -H              # include column headers
                 -s              # show user stack traces
                 -h              # this usage message

Note that these examples may need modification to match your kernel
version's function names and platform's register usage.
   eg,
       # trace readline() calls in all running "bash" executables:
           uprobe p:bash:readline
       # trace readline() with explicit executable path:
           uprobe p:/bin/bash:readline
       # trace the return of readline() with return value as a string:
           uprobe 'r:bash:readline +0($retval):string'
       # trace strcpy() calls in all running libc shared libraries:
           uprobe p:libc:sleep
       # trace strcpy() with register %di (x86):
           uprobe 'p:libc:sleep %di'
       # trace this address (use caution, can cause failures):
           uprobe p:libc:0xbf130
       # trace gettimeofday() for PID 1182 only:
           uprobe -p 1182 p:libc:gettimeofday
       # trace the return of fopen() only when it returns NULL:
           uprobe 'r:libc:fopen file=$retval' 'file == 0'

See the man page and example file for more info.