1Demonstrations of funcslower, the Linux eBPF/bcc version.
2
3
4funcslower shows kernel or user function invocations slower than a threshold.
5This can be used for last-resort diagnostics when aggregation-based tools have
6failed. For example, trace the open() function in libc when it is slower than
71 microsecond (us):
8
9# ./funcslower c:open -u 1
10Tracing function calls slower than 1 us... Ctrl+C to quit.
11COMM           PID    LAT(us)             RVAL FUNC
12less           27074    33.77                3 c:open
13less           27074     9.96 ffffffffffffffff c:open
14less           27074     5.92 ffffffffffffffff c:open
15less           27074    15.88 ffffffffffffffff c:open
16less           27074     8.89                3 c:open
17less           27074    15.89                3 c:open
18sh             27075    20.97                4 c:open
19bash           27075    20.14                4 c:open
20lesspipe.sh    27075    18.77                4 c:open
21lesspipe.sh    27075    11.21                4 c:open
22lesspipe.sh    27075    13.68                4 c:open
23file           27076    14.83 ffffffffffffffff c:open
24file           27076     8.02                4 c:open
25file           27076    10.26                4 c:open
26file           27076     6.55                4 c:open
27less           27074    11.67                4 c:open
28^C
29
30This shows several open operations performed by less and some helpers it invoked
31in the process. The latency (in microseconds) is shown, as well as the return
32value from the open() function, which helps indicate if there is a correlation
33between failures and slow invocations. Most open() calls seemed to have
34completed successfully (returning a valid file descriptor), but some have failed
35and returned -1.
36
37You can also trace kernel functions:
38
39# ./funcslower -m 10 vfs_read
40Tracing function calls slower than 10 ms... Ctrl+C to quit.
41COMM           PID    LAT(ms)             RVAL FUNC
42bash           11527    78.97                1 vfs_read
43bash           11527   101.26                1 vfs_read
44bash           11527  1053.60                1 vfs_read
45bash           11527    44.21                1 vfs_read
46bash           11527    79.50                1 vfs_read
47bash           11527    33.37                1 vfs_read
48bash           11527   112.17                1 vfs_read
49bash           11527   101.49                1 vfs_read
50^C
51
52Occasionally, it is also useful to see the arguments passed to the functions.
53The raw hex values of the arguments are available when using the -a switch:
54
55# ./funcslower __kmalloc -a 2 -u 1
56Tracing function calls slower than 1 us... Ctrl+C to quit.
57COMM           PID    LAT(us)             RVAL FUNC ARGS
58kworker/0:2    27077     7.46 ffff90054f9f8e40 __kmalloc 0x98 0x1400000
59kworker/0:2    27077     6.84 ffff90054f9f8e40 __kmalloc 0x98 0x1400000
60bash           11527     6.87 ffff90054f9f8e40 __kmalloc 0x90 0x1408240
61bash           11527     1.15 ffff90054f9f8e40 __kmalloc 0x90 0x1408240
62bash           11527     1.15 ffff90055a1b8c00 __kmalloc 0x2c 0x1400240
63bash           11527     1.18 ffff90054b87d240 __kmalloc 0x1c 0x1400040
64bash           11527    10.59 ffff900546d60000 __kmalloc 0x10000 0x14082c0
65bash           11527     1.49 ffff90054fbd4c00 __kmalloc 0x280 0x15080c0
66bash           11527     1.00 ffff90054789b000 __kmalloc 0x800 0x15012c0
67bash           27128     3.47 ffff90057ca1a200 __kmalloc 0x150 0x1400240
68bash           27128     1.82 ffff90054fbd4c00 __kmalloc 0x230 0x14000c0
69bash           27128     1.17 ffff90054b87d5a0 __kmalloc 0x1c 0x14000c0
70perf           27128     4.81 ffff90054f9f8e40 __kmalloc 0x90 0x1408240
71perf           27128    24.71 ffff900566990000 __kmalloc 0x10000 0x14082c0
72^C
73
74This shows the first two arguments to __kmalloc -- the first one is the size
75of the requested allocation. The return value is also shown (null return values
76would indicate a failure).
77
78# ./funcslower -U -m 30 '/usr/sbin/nginx:database_write'
79Tracing function calls slower than 30 ms... Ctrl+C to quit.
80COMM           PID    LAT(ms)             RVAL FUNC
81nginx          1617     30.15                9 /usr/sbin/nginx:database_write
82    DataBaseProvider::setData(std::string const&, record_s&)
83    UserDataProvider::saveRecordData(RecordData const&)
84    RequestProcessor::writeResponse(int)
85    RequestProcessor::processRequest()
86    RequestRouter::processRequest(RequestWrapper*, ResponseWrapper*)
87    ngx_http_core_content_phase
88    ngx_http_core_run_phases
89    ngx_http_process_request
90    ngx_process_events_and_timers
91    ngx_spawn_process
92    ngx_master_process_cycle
93    main
94    __libc_start_main
95    [unknown]
96nginx          1629     30.14                9 /usr/sbin/nginx:database_write
97    DataBaseProvider::setData(std::string const&, record_s&)
98    UserDataProvider::saveRecordData(RecordData const&)
99    RequestProcessor::writeResponse(int)
100    RequestProcessor::processRequest()
101    RequestRouter::processRequest(RequestWrapper*, ResponseWrapper*)
102    ngx_http_core_content_phase
103    ngx_http_core_run_phases
104    ngx_http_process_request
105    ngx_process_events_and_timers
106    ngx_spawn_process
107    ngx_master_process_cycle
108    main
109    __libc_start_main
110    [unknown]
111^C
112
113Shows the user space stack trace of calls to the user space function call open taking longer than 30 ms.
114
115USAGE message:
116
117usage: funcslower.py [-hf] [-p PID] [-U | -K] [-m MIN_MS] [-u MIN_US] [-a ARGUMENTS] [-T]
118                     [-t] [-v]
119                     function [function ...]
120
121Trace slow kernel or user function calls.
122
123positional arguments:
124  function              function(s) to trace
125
126optional arguments:
127  -h, --help            show this help message and exit
128  -p PID, --pid PID     trace this PID only
129  -m MIN_MS, --min-ms MIN_MS
130                        minimum duration to trace (ms)
131  -u MIN_US, --min-us MIN_US
132                        minimum duration to trace (us)
133  -U, --user-stack
134                        show stacks from user space
135  -K, --kernel-stack
136                        show stacks from kernel space
137  -f                    print output in folded stack format.
138  -a ARGUMENTS, --arguments ARGUMENTS
139                        print this many entry arguments, as hex
140  -T, --time            show HH:MM:SS timestamp
141  -t, --timestamp       show timestamp in seconds at us resolution
142  -v, --verbose         print the BPF program for debugging purposes
143
144examples:
145  ./funcslower vfs_write       # trace vfs_write calls slower than 1ms
146  ./funcslower -m 10 vfs_write # same, but slower than 10ms
147  ./funcslower -u 10 c:open    # trace open calls slower than 10us
148  ./funcslower -p 135 c:open   # trace pid 135 only
149  ./funcslower c:malloc c:free # trace both malloc and free slower than 1ms
150  ./funcslower -a 2 c:open     # show first two arguments to open
151