tools/argdist_example.txt

Demonstrations of argdist.


argdist probes functions you specify and collects parameter values into a
histogram or a frequency count. This can be used to understand the distribution
of values a certain parameter takes, filter and print interesting parameters
without attaching a debugger, and obtain general execution statistics on
various functions.

For example, suppose you want to find what allocation sizes are common in
your application:

# ./argdist -p 2420 -c -C 'p:c:malloc(size_t size):size_t:size'
[01:42:29]
p:c:malloc(size_t size):size_t:size
        COUNT      EVENT
[01:42:30]
p:c:malloc(size_t size):size_t:size
        COUNT      EVENT
[01:42:31]
p:c:malloc(size_t size):size_t:size
        COUNT      EVENT
        1          size = 16
[01:42:32]
p:c:malloc(size_t size):size_t:size
        COUNT      EVENT
        2          size = 16
[01:42:33]
p:c:malloc(size_t size):size_t:size
        COUNT      EVENT
        3          size = 16
[01:42:34]
p:c:malloc(size_t size):size_t:size
        COUNT      EVENT
        4          size = 16
^C

It seems that the application is allocating blocks of size 16. The COUNT
column contains the number of occurrences of a particular event, and the
EVENT column describes the event. In this case, the "size" parameter was 
probed and its value was 16, repeatedly.

Now, suppose you wanted a histogram of buffer sizes passed to the write()
function across the system:

# ./argdist -c -H 'p:c:write(int fd, void *buf, size_t len):size_t:len'
[01:45:22]
p:c:write(int fd, void *buf, size_t len):size_t:len
     len                 : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 2        |*************                           |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 2        |*************                           |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 6        |****************************************|
[01:45:23]
p:c:write(int fd, void *buf, size_t len):size_t:len
     len                 : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 11       |***************                         |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 4        |*****                                   |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 28       |****************************************|
        64 -> 127        : 12       |*****************                       |
[01:45:24]
p:c:write(int fd, void *buf, size_t len):size_t:len
     len                 : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 21       |****************                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 6        |****                                    |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 52       |****************************************|
        64 -> 127        : 26       |********************                    |
^C

It seems that most writes fall into three buckets: very small writes of 2-3
bytes, medium writes of 32-63 bytes, and larger writes of 64-127 bytes.

But these are writes across the board -- what if you wanted to focus on writes
to STDOUT?

# ./argdist -c -H 'p:c:write(int fd, void *buf, size_t len):size_t:len:fd==1'
[01:47:17]
p:c:write(int fd, void *buf, size_t len):size_t:len:fd==1
     len                 : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 1        |****************************************|
        16 -> 31         : 0        |                                        |
        32 -> 63         : 1        |****************************************|
[01:47:18]
p:c:write(int fd, void *buf, size_t len):size_t:len:fd==1
     len                 : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 2        |*************                           |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 3        |********************                    |
        64 -> 127        : 6        |****************************************|
[01:47:19]
p:c:write(int fd, void *buf, size_t len):size_t:len:fd==1
     len                 : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 3        |*********                               |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 5        |***************                         |
        64 -> 127        : 13       |****************************************|
^C

The "fd==1" part is a filter that is applied to every invocation of write().
Only if the filter condition is true, the value is recorded.

You can also use argdist to trace kernel functions. For example, suppose you
wanted a histogram of kernel allocation (kmalloc) sizes across the system,
printed twice with 3 second intervals:

# ./argdist -i 3 -n 2 -H 'p::__kmalloc(size_t size):size_t:size'
[01:50:00]
p::__kmalloc(size_t size):size_t:size
     size                : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 6        |****************************************|
[01:50:03]
p::__kmalloc(size_t size):size_t:size
     size                : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 22       |****************************************|
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 5        |*********                               |
       128 -> 255        : 2        |***                                     |

Occasionally, numeric information isn't enough and you want to capture strings.
What are the strings printed by puts() across the system?

# ./argdist -i 10 -n 1 -C 'p:c:puts(char *str):char*:str'
[01:53:54]
p:c:puts(char *str):char*:str
        COUNT      EVENT
        2          str = Press ENTER to start.

It looks like the message "Press ENTER to start." was printed twice during the
10 seconds we were tracing.

What about reads? You could trace gets() across the system and print the 
strings input by the user (note how "r" is used instead of "p" to attach a
probe to the function's return):

# ./argdist -i 10 -n 1 -C 'r:c:gets():char*:(char*)$retval:$retval!=0'
[02:12:23]
r:c:gets():char*:$retval:$retval!=0
        COUNT      EVENT
        1          (char*)$retval = hi there
        3          (char*)$retval = sasha
        8          (char*)$retval = hello

Similarly, we could get a histogram of the error codes returned by read():

# ./argdist -i 10 -c 1 -H 'r:c:read()'
[02:15:36]
r:c:read()
     retval              : count     distribution
         0 -> 1          : 29       |****************************************|
         2 -> 3          : 11       |***************                         |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 3        |****                                    |
        16 -> 31         : 2        |**                                      |
        32 -> 63         : 22       |******************************          |
        64 -> 127        : 5        |******                                  |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 1        |*                                       |
       512 -> 1023       : 1        |*                                       |
      1024 -> 2047       : 0        |                                        |
      2048 -> 4095       : 2        |**                                      |

In return probes, you can also trace the latency of the function (unless it is
recursive) and the parameters it had on entry. For example, we can identify
which processes are performing slow synchronous filesystem reads -- say,
longer than 0.1ms (100,000ns):

# ./argdist -C 'r::__vfs_read():u32:$PID:$latency > 100000'
[01:08:48]
r::__vfs_read():u32:$PID:$latency > 100000
        COUNT      EVENT
        1          $PID = 10457
        21         $PID = 2780
[01:08:49]
r::__vfs_read():u32:$PID:$latency > 100000
        COUNT      EVENT
        1          $PID = 10457
        21         $PID = 2780
^C

It looks like process 2780 performed 21 slow reads.

Occasionally, entry parameter values are also interesting. For example, you
might be curious how long it takes malloc() to allocate memory -- nanoseconds
per byte allocated. Let's go:

# ./argdist -H 'r:c:malloc(size_t size):u64:$latency/$entry(size);ns per byte' -n 1 -i 10
[01:11:13]
     ns per byte         : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 4        |*****************                       |
         4 -> 7          : 3        |*************                           |
         8 -> 15         : 2        |********                                |
        16 -> 31         : 1        |****                                    |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 7        |*******************************         |
       128 -> 255        : 1        |****                                    |
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 1        |****                                    |
      1024 -> 2047       : 1        |****                                    |
      2048 -> 4095       : 9        |****************************************|
      4096 -> 8191       : 1        |****                                    | 

It looks like a tri-modal distribution. Some allocations are extremely cheap,
and take 2-15 nanoseconds per byte. Other allocations are slower, and take
64-127 nanoseconds per byte. And some allocations are slower still, and take
multiple microseconds per byte.

You could also group results by more than one field. For example, __kmalloc
takes an additional flags parameter that describes how to allocate memory:

# ./argdist -c -C 'p::__kmalloc(size_t size, gfp_t flags):gfp_t,size_t:flags,size'
[03:42:29]
p::__kmalloc(size_t size, gfp_t flags):gfp_t,size_t:flags,size
        COUNT      EVENT
        1          flags = 16, size = 152
        2          flags = 131280, size = 8
        7          flags = 131280, size = 16
[03:42:30]
p::__kmalloc(size_t size, gfp_t flags):gfp_t,size_t:flags,size
        COUNT      EVENT
        1          flags = 16, size = 152
        6          flags = 131280, size = 8
        19         flags = 131280, size = 16
[03:42:31]
p::__kmalloc(size_t size, gfp_t flags):gfp_t,size_t:flags,size
        COUNT      EVENT
        2          flags = 16, size = 152
        10         flags = 131280, size = 8
        31         flags = 131280, size = 16
[03:42:32]
p::__kmalloc(size_t size, gfp_t flags):gfp_t,size_t:flags,size
        COUNT      EVENT
        2          flags = 16, size = 152
        14         flags = 131280, size = 8
        43         flags = 131280, size = 16
^C

The flags value must be expanded by hand, but it's still helpful to eliminate
certain kinds of allocations or visually group them together.

argdist also has basic support for kernel tracepoints. It is sometimes more
convenient to use tracepoints because they are documented and don't vary a lot
between kernel versions. For example, let's trace the net:net_dev_start_xmit
tracepoint and print out the protocol field from the tracepoint structure:

# argdist -C 't:net:net_dev_start_xmit():u16:args->protocol'
[13:01:49]
t:net:net_dev_start_xmit():u16:args->protocol
        COUNT      EVENT
        8          args->protocol = 2048
^C

Note that to discover the format of the net:net_dev_start_xmit tracepoint, you
use the tplist tool (tplist -v net:net_dev_start_xmit).


Occasionally, it is useful to filter certain expressions by string. This is not
trivially supported by BPF, but argdist provides a STRCMP helper you can use in
filter expressions. For example, to get a histogram of latencies opening a
specific file, run this:

# argdist -c -H 'r:c:open(char *file):u64:$latency/1000:STRCMP("test.txt",$entry(file))'
[02:16:38]
[02:16:39]
[02:16:40]
     $latency/1000       : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 2        |****************************************|
[02:16:41]
     $latency/1000       : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 1        |**********                              |
        16 -> 31         : 4        |****************************************|
[02:16:42]
     $latency/1000       : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 1        |********                                |
        16 -> 31         : 5        |****************************************|
[02:16:43]
     $latency/1000       : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 1        |********                                |
        16 -> 31         : 5        |****************************************|


Here's a final example that finds how many write() system calls are performed
by each process on the system:

# argdist -c -C 'p:c:write():int:$PID;write per process' -n 2
[06:47:18]
write by process
        COUNT      EVENT
        3          $PID = 8889
        7          $PID = 7615
        7          $PID = 2480
[06:47:19]
write by process
        COUNT      EVENT
        9          $PID = 8889
        23         $PID = 7615
        23         $PID = 2480


USAGE message:

# argdist -h
usage: argdist [-h] [-p PID] [-z STRING_SIZE] [-i INTERVAL] [-n COUNT] [-v]
               [-c] [-T TOP] [-H specifier] [-C[specifier] [-I header]

Trace a function and display a summary of its parameter values.

optional arguments:
  -h, --help            show this help message and exit
  -p PID, --pid PID     id of the process to trace (optional)
  -z STRING_SIZE, --string-size STRING_SIZE
                        maximum string size to read from char* arguments
  -i INTERVAL, --interval INTERVAL
                        output interval, in seconds
  -n COUNT, --number COUNT
                        number of outputs
  -v, --verbose         print resulting BPF program code before executing
  -c, --cumulative      do not clear histograms and freq counts at each interval
  -T TOP, --top TOP     number of top results to show (not applicable to
                        histograms)
  -H specifier, --histogram specifier
                        probe specifier to capture histogram of (see examples
                        below)
  -C specifier, --count specifier
                        probe specifier to capture count of (see examples
                        below)
  -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

Probe specifier syntax:
        {p,r,t,u}:{[library],category}:function(signature)[:type[,type...]:expr[,expr...][:filter]][#label]
Where:
        p,r,t,u    -- probe at function entry, function exit, kernel tracepoint,
                      or USDT probe
                      in exit probes: can use $retval, $entry(param), $latency
        library    -- the library that contains the function
                      (leave empty for kernel functions)
        category   -- the category of the kernel tracepoint (e.g. net, sched)
        signature  -- the function's parameters, as in the C header
        type       -- the type of the expression to collect (supports multiple)
        expr       -- the expression to collect (supports multiple)
        filter     -- the filter that is applied to collected values
        label      -- the label for this probe in the resulting output

EXAMPLES:

argdist -H 'p::__kmalloc(u64 size):u64:size'
        Print a histogram of allocation sizes passed to kmalloc

argdist -p 1005 -C 'p:c:malloc(size_t size):size_t:size:size==16'
        Print a frequency count of how many times process 1005 called malloc
        with an allocation size of 16 bytes

argdist -C 'r:c:gets():char*:$retval#snooped strings'
        Snoop on all strings returned by gets()

argdist -H 'r::__kmalloc(size_t size):u64:$latency/$entry(size)#ns per byte'
        Print a histogram of nanoseconds per byte from kmalloc allocations

argdist -C 'p::__kmalloc(size_t size, gfp_t flags):size_t:size:flags&GFP_ATOMIC'
        Print frequency count of kmalloc allocation sizes that have GFP_ATOMIC

argdist -p 1005 -C 'p:c:write(int fd):int:fd' -T 5
        Print frequency counts of how many times writes were issued to a
        particular file descriptor number, in process 1005, but only show
        the top 5 busiest fds

argdist -p 1005 -H 'r:c:read()'
        Print a histogram of error codes returned by read() in process 1005

argdist -C 'r::__vfs_read():u32:$PID:$latency > 100000'
        Print frequency of reads by process where the latency was >0.1ms

argdist -H 'r::__vfs_read(void *file, void *buf, size_t count):size_t:$entry(count):$latency > 1000000' 
        Print a histogram of read sizes that were longer than 1ms

argdist -H \
        'p:c:write(int fd, const void *buf, size_t count):size_t:count:fd==1'
        Print a histogram of buffer sizes passed to write() across all
        processes, where the file descriptor was 1 (STDOUT)

argdist -C 'p:c:fork()#fork calls'
        Count fork() calls in libc across all processes
        Can also use funccount.py, which is easier and more flexible 

argdist -H 't:block:block_rq_complete():u32:args->nr_sector'
        Print histogram of number of sectors in completing block I/O requests

argdist -C 't:irq:irq_handler_entry():int:args->irq'
        Aggregate interrupts by interrupt request (IRQ)

argdist -C 'u:pthread:pthread_start():u64:arg2' -p 1337
        Print frequency of function addresses used as a pthread start function,
        relying on the USDT pthread_start probe in process 1337

argdist -H 'p:c:sleep(u32 seconds):u32:seconds' \
        -H 'p:c:nanosleep(struct timespec *req):long:req->tv_nsec'
        Print histograms of sleep() and nanosleep() parameter values

argdist -p 2780 -z 120 \
        -C 'p:c:write(int fd, char* buf, size_t len):char*:buf:fd==1'
        Spy on writes to STDOUT performed by process 2780, up to a string size
        of 120 characters 

argdist -I 'kernel/sched/sched.h' \
        -C 'p::__account_cfs_rq_runtime(struct cfs_rq *cfs_rq):s64:cfs_rq->runtime_remaining'
        Trace on 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.