tools/funcslower_example.txt

Demonstrations of funcslower, the Linux eBPF/bcc version.


funcslower shows kernel or user function invocations slower than a threshold.
This can be used for last-resort diagnostics when aggregation-based tools have
failed. For example, trace the open() function in libc when it is slower than
1 microsecond (us):

# ./funcslower c:open -u 1
Tracing function calls slower than 1 us... Ctrl+C to quit.
COMM           PID    LAT(us)             RVAL FUNC
less           27074    33.77                3 c:open
less           27074     9.96 ffffffffffffffff c:open
less           27074     5.92 ffffffffffffffff c:open
less           27074    15.88 ffffffffffffffff c:open
less           27074     8.89                3 c:open
less           27074    15.89                3 c:open
sh             27075    20.97                4 c:open
bash           27075    20.14                4 c:open
lesspipe.sh    27075    18.77                4 c:open
lesspipe.sh    27075    11.21                4 c:open
lesspipe.sh    27075    13.68                4 c:open
file           27076    14.83 ffffffffffffffff c:open
file           27076     8.02                4 c:open
file           27076    10.26                4 c:open
file           27076     6.55                4 c:open
less           27074    11.67                4 c:open
^C

This shows several open operations performed by less and some helpers it invoked
in the process. The latency (in microseconds) is shown, as well as the return
value from the open() function, which helps indicate if there is a correlation
between failures and slow invocations. Most open() calls seemed to have
completed successfully (returning a valid file descriptor), but some have failed
and returned -1.

You can also trace kernel functions:

# ./funcslower -m 10 vfs_read
Tracing function calls slower than 10 ms... Ctrl+C to quit.
COMM           PID    LAT(ms)             RVAL FUNC
bash           11527    78.97                1 vfs_read
bash           11527   101.26                1 vfs_read
bash           11527  1053.60                1 vfs_read
bash           11527    44.21                1 vfs_read
bash           11527    79.50                1 vfs_read
bash           11527    33.37                1 vfs_read
bash           11527   112.17                1 vfs_read
bash           11527   101.49                1 vfs_read
^C

Occasionally, it is also useful to see the arguments passed to the functions.
The raw hex values of the arguments are available when using the -a switch:

# ./funcslower __kmalloc -a 2 -u 1
Tracing function calls slower than 1 us... Ctrl+C to quit.
COMM           PID    LAT(us)             RVAL FUNC ARGS
kworker/0:2    27077     7.46 ffff90054f9f8e40 __kmalloc 0x98 0x1400000
kworker/0:2    27077     6.84 ffff90054f9f8e40 __kmalloc 0x98 0x1400000
bash           11527     6.87 ffff90054f9f8e40 __kmalloc 0x90 0x1408240
bash           11527     1.15 ffff90054f9f8e40 __kmalloc 0x90 0x1408240
bash           11527     1.15 ffff90055a1b8c00 __kmalloc 0x2c 0x1400240
bash           11527     1.18 ffff90054b87d240 __kmalloc 0x1c 0x1400040
bash           11527    10.59 ffff900546d60000 __kmalloc 0x10000 0x14082c0
bash           11527     1.49 ffff90054fbd4c00 __kmalloc 0x280 0x15080c0
bash           11527     1.00 ffff90054789b000 __kmalloc 0x800 0x15012c0
bash           27128     3.47 ffff90057ca1a200 __kmalloc 0x150 0x1400240
bash           27128     1.82 ffff90054fbd4c00 __kmalloc 0x230 0x14000c0
bash           27128     1.17 ffff90054b87d5a0 __kmalloc 0x1c 0x14000c0
perf           27128     4.81 ffff90054f9f8e40 __kmalloc 0x90 0x1408240
perf           27128    24.71 ffff900566990000 __kmalloc 0x10000 0x14082c0
^C

This shows the first two arguments to __kmalloc -- the first one is the size
of the requested allocation. The return value is also shown (null return values
would indicate a failure).

# ./funcslower -U -m 30 '/usr/sbin/nginx:database_write'
Tracing function calls slower than 30 ms... Ctrl+C to quit.
COMM           PID    LAT(ms)             RVAL FUNC
nginx          1617     30.15                9 /usr/sbin/nginx:database_write
    DataBaseProvider::setData(std::string const&, record_s&)
    UserDataProvider::saveRecordData(RecordData const&)
    RequestProcessor::writeResponse(int)
    RequestProcessor::processRequest()
    RequestRouter::processRequest(RequestWrapper*, ResponseWrapper*)
    ngx_http_core_content_phase
    ngx_http_core_run_phases
    ngx_http_process_request
    ngx_process_events_and_timers
    ngx_spawn_process
    ngx_master_process_cycle
    main
    __libc_start_main
    [unknown]
nginx          1629     30.14                9 /usr/sbin/nginx:database_write
    DataBaseProvider::setData(std::string const&, record_s&)
    UserDataProvider::saveRecordData(RecordData const&)
    RequestProcessor::writeResponse(int)
    RequestProcessor::processRequest()
    RequestRouter::processRequest(RequestWrapper*, ResponseWrapper*)
    ngx_http_core_content_phase
    ngx_http_core_run_phases
    ngx_http_process_request
    ngx_process_events_and_timers
    ngx_spawn_process
    ngx_master_process_cycle
    main
    __libc_start_main
    [unknown]
^C

Shows the user space stack trace of calls to the user space function call open taking longer than 30 ms.

USAGE message:

usage: funcslower.py [-hf] [-p PID] [-U | -K] [-m MIN_MS] [-u MIN_US] [-a ARGUMENTS] [-T]
                     [-t] [-v]
                     function [function ...]

Trace slow kernel or user function calls.

positional arguments:
  function              function(s) to trace

optional arguments:
  -h, --help            show this help message and exit
  -p PID, --pid PID     trace this PID only
  -m MIN_MS, --min-ms MIN_MS
                        minimum duration to trace (ms)
  -u MIN_US, --min-us MIN_US
                        minimum duration to trace (us)
  -U, --user-stack
                        show stacks from user space
  -K, --kernel-stack
                        show stacks from kernel space
  -f                    print output in folded stack format.
  -a ARGUMENTS, --arguments ARGUMENTS
                        print this many entry arguments, as hex
  -T, --time            show HH:MM:SS timestamp
  -t, --timestamp       show timestamp in seconds at us resolution
  -v, --verbose         print the BPF program for debugging purposes

examples:
  ./funcslower vfs_write       # trace vfs_write calls slower than 1ms
  ./funcslower -m 10 vfs_write # same, but slower than 10ms
  ./funcslower -u 10 c:open    # trace open calls slower than 10us
  ./funcslower -p 135 c:open   # trace pid 135 only
  ./funcslower c:malloc c:free # trace both malloc and free slower than 1ms
  ./funcslower -a 2 c:open     # show first two arguments to open