You can not select more than 25 topics
Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.
150 lines
6.6 KiB
150 lines
6.6 KiB
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
|
|
|