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