Sasha Goldshtein | 4eace76 | 2017-03-30 05:06:22 -0400 | [diff] [blame] | 1 | Demonstrations of funcslower, the Linux eBPF/bcc version. |
| 2 | |
| 3 | |
| 4 | funcslower shows kernel or user function invocations slower than a threshold. |
| 5 | This can be used for last-resort diagnostics when aggregation-based tools have |
| 6 | failed. For example, trace the open() function in libc when it is slower than |
| 7 | 1 microsecond (us): |
| 8 | |
| 9 | # ./funcslower c:open -u 1 |
| 10 | Tracing function calls slower than 1 us... Ctrl+C to quit. |
| 11 | COMM PID LAT(us) RVAL FUNC |
| 12 | less 27074 33.77 3 c:open |
| 13 | less 27074 9.96 ffffffffffffffff c:open |
| 14 | less 27074 5.92 ffffffffffffffff c:open |
| 15 | less 27074 15.88 ffffffffffffffff c:open |
| 16 | less 27074 8.89 3 c:open |
| 17 | less 27074 15.89 3 c:open |
| 18 | sh 27075 20.97 4 c:open |
| 19 | bash 27075 20.14 4 c:open |
| 20 | lesspipe.sh 27075 18.77 4 c:open |
| 21 | lesspipe.sh 27075 11.21 4 c:open |
| 22 | lesspipe.sh 27075 13.68 4 c:open |
| 23 | file 27076 14.83 ffffffffffffffff c:open |
| 24 | file 27076 8.02 4 c:open |
| 25 | file 27076 10.26 4 c:open |
| 26 | file 27076 6.55 4 c:open |
| 27 | less 27074 11.67 4 c:open |
| 28 | ^C |
| 29 | |
| 30 | This shows several open operations performed by less and some helpers it invoked |
| 31 | in the process. The latency (in microseconds) is shown, as well as the return |
| 32 | value from the open() function, which helps indicate if there is a correlation |
| 33 | between failures and slow invocations. Most open() calls seemed to have |
| 34 | completed successfully (returning a valid file descriptor), but some have failed |
| 35 | and returned -1. |
| 36 | |
| 37 | You can also trace kernel functions: |
| 38 | |
| 39 | # ./funcslower -m 10 vfs_read |
| 40 | Tracing function calls slower than 10 ms... Ctrl+C to quit. |
| 41 | COMM PID LAT(ms) RVAL FUNC |
| 42 | bash 11527 78.97 1 vfs_read |
| 43 | bash 11527 101.26 1 vfs_read |
| 44 | bash 11527 1053.60 1 vfs_read |
| 45 | bash 11527 44.21 1 vfs_read |
| 46 | bash 11527 79.50 1 vfs_read |
| 47 | bash 11527 33.37 1 vfs_read |
| 48 | bash 11527 112.17 1 vfs_read |
| 49 | bash 11527 101.49 1 vfs_read |
| 50 | ^C |
| 51 | |
| 52 | Occasionally, it is also useful to see the arguments passed to the functions. |
| 53 | The raw hex values of the arguments are available when using the -a switch: |
| 54 | |
| 55 | # ./funcslower __kmalloc -a 2 -u 1 |
| 56 | Tracing function calls slower than 1 us... Ctrl+C to quit. |
| 57 | COMM PID LAT(us) RVAL FUNC ARGS |
| 58 | kworker/0:2 27077 7.46 ffff90054f9f8e40 __kmalloc 0x98 0x1400000 |
| 59 | kworker/0:2 27077 6.84 ffff90054f9f8e40 __kmalloc 0x98 0x1400000 |
| 60 | bash 11527 6.87 ffff90054f9f8e40 __kmalloc 0x90 0x1408240 |
| 61 | bash 11527 1.15 ffff90054f9f8e40 __kmalloc 0x90 0x1408240 |
| 62 | bash 11527 1.15 ffff90055a1b8c00 __kmalloc 0x2c 0x1400240 |
| 63 | bash 11527 1.18 ffff90054b87d240 __kmalloc 0x1c 0x1400040 |
| 64 | bash 11527 10.59 ffff900546d60000 __kmalloc 0x10000 0x14082c0 |
| 65 | bash 11527 1.49 ffff90054fbd4c00 __kmalloc 0x280 0x15080c0 |
| 66 | bash 11527 1.00 ffff90054789b000 __kmalloc 0x800 0x15012c0 |
| 67 | bash 27128 3.47 ffff90057ca1a200 __kmalloc 0x150 0x1400240 |
| 68 | bash 27128 1.82 ffff90054fbd4c00 __kmalloc 0x230 0x14000c0 |
| 69 | bash 27128 1.17 ffff90054b87d5a0 __kmalloc 0x1c 0x14000c0 |
| 70 | perf 27128 4.81 ffff90054f9f8e40 __kmalloc 0x90 0x1408240 |
| 71 | perf 27128 24.71 ffff900566990000 __kmalloc 0x10000 0x14082c0 |
| 72 | ^C |
| 73 | |
| 74 | This shows the first two arguments to __kmalloc -- the first one is the size |
| 75 | of the requested allocation. The return value is also shown (null return values |
| 76 | would indicate a failure). |
| 77 | |
| 78 | USAGE message: |
| 79 | |
| 80 | usage: funcslower.py [-h] [-p PID] [-m MIN_MS] [-u MIN_US] [-a ARGUMENTS] [-T] |
| 81 | [-t] [-v] |
| 82 | function [function ...] |
| 83 | |
| 84 | Trace slow kernel or user function calls. |
| 85 | |
| 86 | positional arguments: |
| 87 | function function(s) to trace |
| 88 | |
| 89 | optional arguments: |
| 90 | -h, --help show this help message and exit |
| 91 | -p PID, --pid PID trace this PID only |
| 92 | -m MIN_MS, --min-ms MIN_MS |
| 93 | minimum duration to trace (ms) |
| 94 | -u MIN_US, --min-us MIN_US |
| 95 | minimum duration to trace (us) |
| 96 | -a ARGUMENTS, --arguments ARGUMENTS |
| 97 | print this many entry arguments, as hex |
| 98 | -T, --time show HH:MM:SS timestamp |
| 99 | -t, --timestamp show timestamp in seconds at us resolution |
| 100 | -v, --verbose print the BPF program for debugging purposes |
| 101 | |
| 102 | examples: |
| 103 | ./funcslower vfs_write # trace vfs_write calls slower than 1ms |
| 104 | ./funcslower -m 10 vfs_write # same, but slower than 10ms |
| 105 | ./funcslower -u 10 c:open # trace open calls slower than 10us |
| 106 | ./funcslower -p 135 c:open # trace pid 135 only |
| 107 | ./funcslower c:malloc c:free # trace both malloc and free slower than 1ms |
| 108 | ./funcslower -a 2 c:open # show first two arguments to open |