| Demonstrations of funclatency, the Linux eBPF/bcc version. |
| |
| |
| Timing the do_sys_open() kernel function until Ctrl-C: |
| |
| # ./funclatency do_sys_open |
| Tracing do_sys_open... Hit Ctrl-C to end. |
| ^C |
| nsecs : count distribution |
| 0 -> 1 : 0 | | |
| 2 -> 3 : 0 | | |
| 4 -> 7 : 0 | | |
| 8 -> 15 : 0 | | |
| 16 -> 31 : 0 | | |
| 32 -> 63 : 0 | | |
| 64 -> 127 : 0 | | |
| 128 -> 255 : 0 | | |
| 256 -> 511 : 0 | | |
| 512 -> 1023 : 0 | | |
| 1024 -> 2047 : 0 | | |
| 2048 -> 4095 : 124 |**************** | |
| 4096 -> 8191 : 291 |**************************************| |
| 8192 -> 16383 : 36 |**** | |
| 16384 -> 32767 : 16 |** | |
| 32768 -> 65535 : 8 |* | |
| 65536 -> 131071 : 0 | | |
| 131072 -> 262143 : 0 | | |
| 262144 -> 524287 : 0 | | |
| 524288 -> 1048575 : 0 | | |
| 1048576 -> 2097151 : 0 | | |
| 2097152 -> 4194303 : 1 | | |
| |
| avg = 13746 nsecs, total: 6543360 nsecs, count: 476 |
| |
| Detaching... |
| |
| The output shows a histogram of function latency (call time), measured from when |
| the function began executing (was called) to when it finished (returned). |
| |
| This example output shows that most of the time, do_sys_open() took between |
| 2048 and 65536 nanoseconds (2 to 65 microseconds). The peak of this distribution |
| shows 291 calls of between 4096 and 8191 nanoseconds. There was also one |
| occurrence, an outlier, in the 2 to 4 millisecond range. |
| |
| How this works: the function entry and return are traced using the kernel kprobe |
| and kretprobe tracer. Timestamps are collected, the delta time calculated, which |
| is the bucketized and stored as an in-kernel histogram for efficiency. The |
| histogram is visible in the output: it's the "count" column; everything else is |
| decoration. Only the count column is copied to user-level on output. This is an |
| efficient way to time kernel functions and examine their latency distribution. |
| |
| |
| Now trace a user function, pthread_mutex_lock in libpthread, to determine if |
| there is considerable lock contention: |
| |
| # ./funclatency pthread:pthread_mutex_lock -p $(pidof contentions) |
| Tracing 1 function for "pthread:pthread_mutex_lock"... Hit Ctrl-C to end. |
| nsecs : count distribution |
| 0 -> 1 : 0 | | |
| 2 -> 3 : 0 | | |
| 4 -> 7 : 0 | | |
| 8 -> 15 : 0 | | |
| 16 -> 31 : 0 | | |
| 32 -> 63 : 0 | | |
| 64 -> 127 : 0 | | |
| 128 -> 255 : 0 | | |
| 256 -> 511 : 0 | | |
| 512 -> 1023 : 0 | | |
| 1024 -> 2047 : 0 | | |
| 2048 -> 4095 : 508967 |****************************************| |
| 4096 -> 8191 : 70072 |***** | |
| 8192 -> 16383 : 27686 |** | |
| 16384 -> 32767 : 5075 | | |
| 32768 -> 65535 : 2318 | | |
| 65536 -> 131071 : 581 | | |
| 131072 -> 262143 : 38 | | |
| 262144 -> 524287 : 5 | | |
| 524288 -> 1048575 : 1 | | |
| 1048576 -> 2097151 : 9 | | |
| |
| avg = 4317 nsecs, total: 2654426112 nsecs, count: 614752 |
| |
| Detaching... |
| |
| It seems that most calls to pthread_mutex_lock completed rather quickly (in |
| under 4us), but there were some cases of considerable contention, sometimes |
| over a full millisecond. |
| |
| |
| Run a quick-and-dirty profiler over all the functions in an executable: |
| # ./funclatency /home/user/primes:* -p $(pidof primes) -F |
| Tracing 15 functions for "/home/user/primes:*"... Hit Ctrl-C to end. |
| ^C |
| |
| Function = is_prime [6556] |
| nsecs : count distribution |
| 0 -> 1 : 0 | | |
| 2 -> 3 : 0 | | |
| 4 -> 7 : 0 | | |
| 8 -> 15 : 0 | | |
| 16 -> 31 : 0 | | |
| 32 -> 63 : 0 | | |
| 64 -> 127 : 0 | | |
| 128 -> 255 : 0 | | |
| 256 -> 511 : 0 | | |
| 512 -> 1023 : 0 | | |
| 1024 -> 2047 : 0 | | |
| 2048 -> 4095 : 1495322 |****************************************| |
| 4096 -> 8191 : 95744 |** | |
| 8192 -> 16383 : 9926 | | |
| 16384 -> 32767 : 3070 | | |
| 32768 -> 65535 : 1415 | | |
| 65536 -> 131071 : 112 | | |
| 131072 -> 262143 : 9 | | |
| 262144 -> 524287 : 3 | | |
| 524288 -> 1048575 : 0 | | |
| 1048576 -> 2097151 : 8 | | |
| |
| Function = insert_result [6556] |
| nsecs : count distribution |
| 0 -> 1 : 0 | | |
| 2 -> 3 : 0 | | |
| 4 -> 7 : 0 | | |
| 8 -> 15 : 0 | | |
| 16 -> 31 : 0 | | |
| 32 -> 63 : 0 | | |
| 64 -> 127 : 0 | | |
| 128 -> 255 : 0 | | |
| 256 -> 511 : 0 | | |
| 512 -> 1023 : 0 | | |
| 1024 -> 2047 : 0 | | |
| 2048 -> 4095 : 111047 |****************************************| |
| 4096 -> 8191 : 3998 |* | |
| 8192 -> 16383 : 720 | | |
| 16384 -> 32767 : 238 | | |
| 32768 -> 65535 : 106 | | |
| 65536 -> 131071 : 5 | | |
| 131072 -> 262143 : 4 | | |
| |
| avg = 3404 nsecs, total: 5862276096 nsecs, count: 1721727 |
| |
| Detaching... |
| |
| From the results, we can see that the is_prime function has something resembling |
| an exponential distribution -- very few primes take a very long time to test, |
| while most numbers are verified as prime or composite in less than 4us. The |
| insert_result function exhibits a similar phenomenon, likely due to contention |
| over a shared results container. |
| |
| |
| Now vfs_read() is traced, and a microseconds histogram printed: |
| |
| # ./funclatency -u vfs_read |
| Tracing vfs_read... Hit Ctrl-C to end. |
| ^C |
| usecs : count distribution |
| 0 -> 1 : 1143 |**************************************| |
| 2 -> 3 : 420 |************* | |
| 4 -> 7 : 159 |***** | |
| 8 -> 15 : 295 |********* | |
| 16 -> 31 : 25 | | |
| 32 -> 63 : 5 | | |
| 64 -> 127 : 1 | | |
| 128 -> 255 : 0 | | |
| 256 -> 511 : 0 | | |
| 512 -> 1023 : 0 | | |
| 1024 -> 2047 : 1 | | |
| 2048 -> 4095 : 0 | | |
| 4096 -> 8191 : 5 | | |
| 8192 -> 16383 : 0 | | |
| 16384 -> 32767 : 0 | | |
| 32768 -> 65535 : 0 | | |
| 65536 -> 131071 : 7 | | |
| 131072 -> 262143 : 7 | | |
| 262144 -> 524287 : 3 | | |
| 524288 -> 1048575 : 7 | | |
| |
| avg = 4229 nsecs, total: 8789145 nsecs, count: 2078 |
| |
| Detaching... |
| |
| This shows a bimodal distribution. Many vfs_read() calls were faster than 15 |
| microseconds, however, there was also a small handful between 65 milliseconds |
| and 1 second, seen at the bottom of the table. These are likely network reads |
| from SSH, waiting on interactive keystrokes. |
| |
| |
| Tracing do_nanosleep() in milliseconds: |
| |
| # ./funclatency -m do_nanosleep |
| Tracing do_nanosleep... Hit Ctrl-C to end. |
| ^C |
| msecs : count distribution |
| 0 -> 1 : 0 | | |
| 2 -> 3 : 0 | | |
| 4 -> 7 : 0 | | |
| 8 -> 15 : 0 | | |
| 16 -> 31 : 0 | | |
| 32 -> 63 : 0 | | |
| 64 -> 127 : 0 | | |
| 128 -> 255 : 0 | | |
| 256 -> 511 : 0 | | |
| 512 -> 1023 : 328 |**************************************| |
| 1024 -> 2047 : 0 | | |
| 2048 -> 4095 : 0 | | |
| 4096 -> 8191 : 32 |*** | |
| 8192 -> 16383 : 0 | | |
| 16384 -> 32767 : 0 | | |
| 32768 -> 65535 : 2 | | |
| |
| avg = 1510 nsecs, total: 546816 nsecs, count: 326 |
| |
| Detaching... |
| |
| This looks like it has found threads that are sleeping every 1, 5, and 60 |
| seconds. |
| |
| |
| An interval can be provided using -i, and timestamps added using -T. For |
| example, tracing vfs_read() latency in milliseconds and printing output |
| every 5 seconds: |
| |
| # ./funclatency -mTi 5 vfs_read |
| Tracing vfs_read... Hit Ctrl-C to end. |
| |
| 20:10:08 |
| msecs : count distribution |
| 0 -> 1 : 1500 |*************************************+| |
| 2 -> 3 : 3 | | |
| 4 -> 7 : 1 | | |
| 8 -> 15 : 2 | | |
| 16 -> 31 : 0 | | |
| 32 -> 63 : 0 | | |
| 64 -> 127 : 4 | | |
| 128 -> 255 : 3 | | |
| 256 -> 511 : 1 | | |
| 512 -> 1023 : 7 | | |
| |
| avg = 5 nsecs, total: 8259 nsecs, count: 1521 |
| |
| 20:10:13 |
| msecs : count distribution |
| 0 -> 1 : 1251 |*************************************+| |
| 2 -> 3 : 3 | | |
| 4 -> 7 : 2 | | |
| 8 -> 15 : 0 | | |
| 16 -> 31 : 2 | | |
| 32 -> 63 : 3 | | |
| 64 -> 127 : 5 | | |
| 128 -> 255 : 5 | | |
| 256 -> 511 : 3 | | |
| 512 -> 1023 : 6 | | |
| 1024 -> 2047 : 2 | | |
| |
| avg = 9 nsecs, total: 11736 nsecs, count: 1282 |
| |
| 20:10:18 |
| msecs : count distribution |
| 0 -> 1 : 1265 |*************************************+| |
| 2 -> 3 : 0 | | |
| 4 -> 7 : 5 | | |
| 8 -> 15 : 9 | | |
| 16 -> 31 : 7 | | |
| 32 -> 63 : 1 | | |
| 64 -> 127 : 2 | | |
| 128 -> 255 : 3 | | |
| 256 -> 511 : 5 | | |
| 512 -> 1023 : 5 | | |
| 1024 -> 2047 : 0 | | |
| 2048 -> 4095 : 1 | | |
| |
| avg = 8 nsecs, total: 11219 nsecs, count: 1303 |
| |
| ^C |
| 20:10:20 |
| msecs : count distribution |
| 0 -> 1 : 249 |*************************************+| |
| 2 -> 3 : 0 | | |
| 4 -> 7 : 0 | | |
| 8 -> 15 : 1 | | |
| 16 -> 31 : 0 | | |
| 32 -> 63 : 0 | | |
| 64 -> 127 : 0 | | |
| 128 -> 255 : 0 | | |
| 256 -> 511 : 0 | | |
| 512 -> 1023 : 1 | | |
| |
| avg = 4 nsecs, total: 1029 nsecs, count: 251 |
| |
| Detaching... |
| |
| |
| A single process can be traced, which filters in-kernel for efficiency. Here, |
| the vfs_read() function is timed as milliseconds for PID 17064, which is a |
| bash shell: |
| |
| # ./funclatency -mp 17064 vfs_read |
| Tracing vfs_read... Hit Ctrl-C to end. |
| ^C |
| msecs : count distribution |
| 0 -> 1 : 1 |** | |
| 2 -> 3 : 0 | | |
| 4 -> 7 : 0 | | |
| 8 -> 15 : 1 |** | |
| 16 -> 31 : 2 |***** | |
| 32 -> 63 : 0 | | |
| 64 -> 127 : 13 |**************************************| |
| 128 -> 255 : 10 |***************************** | |
| 256 -> 511 : 4 |*********** | |
| |
| avg = 153 nsecs, total: 4765 nsecs, count: 31 |
| |
| Detaching... |
| |
| The distribution between 64 and 511 milliseconds shows keystroke latency. |
| |
| |
| The -F option can be used to print a histogram per function. Eg: |
| |
| # ./funclatency -uF 'vfs_r*' |
| Tracing 5 functions for "vfs_r*"... Hit Ctrl-C to end. |
| ^C |
| |
| Function = vfs_read |
| usecs : count distribution |
| 0 -> 1 : 1044 |****************************************| |
| 2 -> 3 : 383 |************** | |
| 4 -> 7 : 76 |** | |
| 8 -> 15 : 41 |* | |
| 16 -> 31 : 26 | | |
| 32 -> 63 : 0 | | |
| 64 -> 127 : 1 | | |
| 128 -> 255 : 0 | | |
| 256 -> 511 : 0 | | |
| 512 -> 1023 : 0 | | |
| 1024 -> 2047 : 0 | | |
| 2048 -> 4095 : 4 | | |
| 4096 -> 8191 : 2 | | |
| 8192 -> 16383 : 0 | | |
| 16384 -> 32767 : 0 | | |
| 32768 -> 65535 : 2 | | |
| 65536 -> 131071 : 5 | | |
| 131072 -> 262143 : 5 | | |
| 262144 -> 524287 : 3 | | |
| 524288 -> 1048575 : 7 | | |
| |
| Function = vfs_rename |
| usecs : count distribution |
| 0 -> 1 : 2 |**** | |
| 2 -> 3 : 2 |**** | |
| 4 -> 7 : 2 |**** | |
| 8 -> 15 : 0 | | |
| 16 -> 31 : 6 |************* | |
| 32 -> 63 : 18 |****************************************| |
| |
| avg = 5087 nsecs, total: 8287001 nsecs, count: 1629 |
| |
| Detaching... |
| |
| |
| |
| USAGE message: |
| |
| # ./funclatency -h |
| usage: funclatency [-h] [-p PID] [-i INTERVAL] [-T] [-u] [-m] [-F] [-r] [-v] |
| pattern |
| |
| Time functions and print latency as a histogram |
| |
| positional arguments: |
| pattern search expression for functions |
| |
| optional arguments: |
| -h, --help show this help message and exit |
| -p PID, --pid PID trace this PID only |
| -i INTERVAL, --interval INTERVAL |
| summary interval, in seconds |
| -d DURATION, --duration DURATION |
| total duration of trace, in seconds |
| -T, --timestamp include timestamp on output |
| -u, --microseconds microsecond histogram |
| -m, --milliseconds millisecond histogram |
| -F, --function show a separate histogram per function |
| -r, --regexp use regular expressions. Default is "*" wildcards |
| only. |
| -l LEVEL, --level LEVEL |
| set the level of nested or recursive functions |
| -v, --verbose print the BPF program (for debugging purposes) |
| |
| examples: |
| ./funclatency do_sys_open # time the do_sys_open() kernel function |
| ./funclatency c:read # time the read() C library function |
| ./funclatency -u vfs_read # time vfs_read(), in microseconds |
| ./funclatency -m do_nanosleep # time do_nanosleep(), in milliseconds |
| ./funclatency -i 2 -d 10 c:open # output every 2 seconds, for duration 10s |
| ./funclatency -mTi 5 vfs_read # output every 5 seconds, with timestamps |
| ./funclatency -p 181 vfs_read # time process 181 only |
| ./funclatency 'vfs_fstat*' # time both vfs_fstat() and vfs_fstatat() |
| ./funclatency 'c:*printf' # time the *printf family of functions |
| ./funclatency -F 'vfs_r*' # show one histogram per matched function |
