| Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame^] | 1 | Demonstrations of funclatency, the Linux eBPF/bcc version. |
| 2 | |
| 3 | |
| 4 | Timing the do_sys_open() kernel function until Ctrl-C: |
| 5 | |
| 6 | # ./funclatency do_sys_open |
| 7 | Tracing do_sys_open... Hit Ctrl-C to end. |
| 8 | ^C |
| 9 | nsecs : count distribution |
| 10 | 0 -> 1 : 0 | | |
| 11 | 2 -> 3 : 0 | | |
| 12 | 4 -> 7 : 0 | | |
| 13 | 8 -> 15 : 0 | | |
| 14 | 16 -> 31 : 0 | | |
| 15 | 32 -> 63 : 0 | | |
| 16 | 64 -> 127 : 0 | | |
| 17 | 128 -> 255 : 0 | | |
| 18 | 256 -> 511 : 0 | | |
| 19 | 512 -> 1023 : 0 | | |
| 20 | 1024 -> 2047 : 0 | | |
| 21 | 2048 -> 4095 : 124 |**************** | |
| 22 | 4096 -> 8191 : 291 |**************************************| |
| 23 | 8192 -> 16383 : 36 |**** | |
| 24 | 16384 -> 32767 : 16 |** | |
| 25 | 32768 -> 65535 : 8 |* | |
| 26 | 65536 -> 131071 : 0 | | |
| 27 | 131072 -> 262143 : 0 | | |
| 28 | 262144 -> 524287 : 0 | | |
| 29 | 524288 -> 1048575 : 0 | | |
| 30 | 1048576 -> 2097151 : 0 | | |
| 31 | 2097152 -> 4194303 : 1 | | |
| 32 | Detaching... |
| 33 | |
| 34 | The output shows a histogram of function latency (call time), measured from when |
| 35 | the function began executing (was called) to when it finished (returned). |
| 36 | |
| 37 | This example output shows that most of the time, do_sys_open() took between |
| 38 | 2048 and 65536 nanoseconds (2 to 65 microseconds). The peak of this distribution |
| 39 | shows 291 calls of between 4096 and 8191 nanoseconds. There was also one |
| 40 | occurrance, an outlier, in the 2 to 4 millisecond range. |
| 41 | |
| 42 | How this works: the function entry and return are traced using the kernel kprobe |
| 43 | and kretprobe tracer. Timestamps are collected, the delta time calculated, which |
| 44 | is the bucketized and stored as an in-kernel histogram for efficiency. The |
| 45 | histgram is visible in the output: it's the "count" column; everything else is |
| 46 | decoration. Only the count column is copied to user-level on output. This is an |
| 47 | efficient way to time kernel functions and examine their latency distribution. |
| 48 | |
| 49 | |
| 50 | Now vfs_read() is traced, and a microseconds histogram printed: |
| 51 | |
| 52 | # ./funclatency -u vfs_read |
| 53 | Tracing vfs_read... Hit Ctrl-C to end. |
| 54 | ^C |
| 55 | usecs : count distribution |
| 56 | 0 -> 1 : 1143 |**************************************| |
| 57 | 2 -> 3 : 420 |************* | |
| 58 | 4 -> 7 : 159 |***** | |
| 59 | 8 -> 15 : 295 |********* | |
| 60 | 16 -> 31 : 25 | | |
| 61 | 32 -> 63 : 5 | | |
| 62 | 64 -> 127 : 1 | | |
| 63 | 128 -> 255 : 0 | | |
| 64 | 256 -> 511 : 0 | | |
| 65 | 512 -> 1023 : 0 | | |
| 66 | 1024 -> 2047 : 1 | | |
| 67 | 2048 -> 4095 : 0 | | |
| 68 | 4096 -> 8191 : 5 | | |
| 69 | 8192 -> 16383 : 0 | | |
| 70 | 16384 -> 32767 : 0 | | |
| 71 | 32768 -> 65535 : 0 | | |
| 72 | 65536 -> 131071 : 7 | | |
| 73 | 131072 -> 262143 : 7 | | |
| 74 | 262144 -> 524287 : 3 | | |
| 75 | 524288 -> 1048575 : 7 | | |
| 76 | Detaching... |
| 77 | |
| 78 | This shows a bimodal distribution. Many vfs_read() calls were faster than 15 |
| 79 | microseconds, however, there was also a small handful between 65 milliseconds |
| 80 | and 1 second, seen at the bottom of the table. These are likely network reads |
| 81 | from SSH, waiting on interactive keystrokes. |
| 82 | |
| 83 | |
| 84 | Tracing do_nanosleep() in milliseconds: |
| 85 | |
| 86 | # ./funclatency -m do_nanosleep |
| 87 | Tracing do_nanosleep... Hit Ctrl-C to end. |
| 88 | ^C |
| 89 | msecs : count distribution |
| 90 | 0 -> 1 : 0 | | |
| 91 | 2 -> 3 : 0 | | |
| 92 | 4 -> 7 : 0 | | |
| 93 | 8 -> 15 : 0 | | |
| 94 | 16 -> 31 : 0 | | |
| 95 | 32 -> 63 : 0 | | |
| 96 | 64 -> 127 : 0 | | |
| 97 | 128 -> 255 : 0 | | |
| 98 | 256 -> 511 : 0 | | |
| 99 | 512 -> 1023 : 328 |**************************************| |
| 100 | 1024 -> 2047 : 0 | | |
| 101 | 2048 -> 4095 : 0 | | |
| 102 | 4096 -> 8191 : 32 |*** | |
| 103 | 8192 -> 16383 : 0 | | |
| 104 | 16384 -> 32767 : 0 | | |
| 105 | 32768 -> 65535 : 2 | | |
| 106 | Detaching... |
| 107 | |
| 108 | This looks like it has found threads that are sleeping every 1, 5, and 60 |
| 109 | seconds. |
| 110 | |
| 111 | |
| 112 | An interval can be provided using -i, and timestamps added using -T. For |
| 113 | example, tracing vfs_read() latency in milliseconds and printing output |
| 114 | every 5 seconds: |
| 115 | |
| 116 | # ./funclatency -mTi 5 vfs_read |
| 117 | Tracing vfs_read... Hit Ctrl-C to end. |
| 118 | |
| 119 | 20:10:08 |
| 120 | msecs : count distribution |
| 121 | 0 -> 1 : 1500 |*************************************+| |
| 122 | 2 -> 3 : 3 | | |
| 123 | 4 -> 7 : 1 | | |
| 124 | 8 -> 15 : 2 | | |
| 125 | 16 -> 31 : 0 | | |
| 126 | 32 -> 63 : 0 | | |
| 127 | 64 -> 127 : 4 | | |
| 128 | 128 -> 255 : 3 | | |
| 129 | 256 -> 511 : 1 | | |
| 130 | 512 -> 1023 : 7 | | |
| 131 | |
| 132 | 20:10:13 |
| 133 | msecs : count distribution |
| 134 | 0 -> 1 : 1251 |*************************************+| |
| 135 | 2 -> 3 : 3 | | |
| 136 | 4 -> 7 : 2 | | |
| 137 | 8 -> 15 : 0 | | |
| 138 | 16 -> 31 : 2 | | |
| 139 | 32 -> 63 : 3 | | |
| 140 | 64 -> 127 : 5 | | |
| 141 | 128 -> 255 : 5 | | |
| 142 | 256 -> 511 : 3 | | |
| 143 | 512 -> 1023 : 6 | | |
| 144 | 1024 -> 2047 : 2 | | |
| 145 | |
| 146 | 20:10:18 |
| 147 | msecs : count distribution |
| 148 | 0 -> 1 : 1265 |*************************************+| |
| 149 | 2 -> 3 : 0 | | |
| 150 | 4 -> 7 : 5 | | |
| 151 | 8 -> 15 : 9 | | |
| 152 | 16 -> 31 : 7 | | |
| 153 | 32 -> 63 : 1 | | |
| 154 | 64 -> 127 : 2 | | |
| 155 | 128 -> 255 : 3 | | |
| 156 | 256 -> 511 : 5 | | |
| 157 | 512 -> 1023 : 5 | | |
| 158 | 1024 -> 2047 : 0 | | |
| 159 | 2048 -> 4095 : 1 | | |
| 160 | ^C |
| 161 | 20:10:20 |
| 162 | msecs : count distribution |
| 163 | 0 -> 1 : 249 |*************************************+| |
| 164 | 2 -> 3 : 0 | | |
| 165 | 4 -> 7 : 0 | | |
| 166 | 8 -> 15 : 1 | | |
| 167 | 16 -> 31 : 0 | | |
| 168 | 32 -> 63 : 0 | | |
| 169 | 64 -> 127 : 0 | | |
| 170 | 128 -> 255 : 0 | | |
| 171 | 256 -> 511 : 0 | | |
| 172 | 512 -> 1023 : 1 | | |
| 173 | Detaching... |
| 174 | |
| 175 | |
| 176 | A single process can be traced, which filters in-kernel for efficiency. Here, |
| 177 | the vfs_read() function is timed as milliseconds for PID 17064, which is a |
| 178 | bash shell: |
| 179 | |
| 180 | # ./funclatency -mp 17064 vfs_read |
| 181 | Tracing vfs_read... Hit Ctrl-C to end. |
| 182 | ^C |
| 183 | msecs : count distribution |
| 184 | 0 -> 1 : 1 |** | |
| 185 | 2 -> 3 : 0 | | |
| 186 | 4 -> 7 : 0 | | |
| 187 | 8 -> 15 : 1 |** | |
| 188 | 16 -> 31 : 2 |***** | |
| 189 | 32 -> 63 : 0 | | |
| 190 | 64 -> 127 : 13 |**************************************| |
| 191 | 128 -> 255 : 10 |***************************** | |
| 192 | 256 -> 511 : 4 |*********** | |
| 193 | Detaching... |
| 194 | |
| 195 | The distribution between 64 and 511 milliseconds shows keystroke latency. |
| 196 | |
| 197 | |
| 198 | USAGE message: |
| 199 | |
| 200 | # ./funclatency -h |
| 201 | usage: funclatency [-h] [-p PID] [-i INTERVAL] [-T] [-u] [-m] [-r] pattern |
| 202 | |
| 203 | Time kernel funcitons and print latency as a histogram |
| 204 | |
| 205 | positional arguments: |
| 206 | pattern search expression for kernel functions |
| 207 | |
| 208 | optional arguments: |
| 209 | -h, --help show this help message and exit |
| 210 | -p PID, --pid PID trace this PID only |
| 211 | -i INTERVAL, --interval INTERVAL |
| 212 | summary interval, seconds |
| 213 | -T, --timestamp include timestamp on output |
| 214 | -u, --microseconds microsecond histogram |
| 215 | -m, --milliseconds millisecond histogram |
| 216 | -r, --regexp use regular expressions. Default is "*" wildcards |
| 217 | only. |
| 218 | |
| 219 | examples: |
| 220 | ./funclatency do_sys_open # time the do_sys_open() kenel function |
| 221 | ./funclatency -u vfs_read # time vfs_read(), in microseconds |
| 222 | ./funclatency -m do_nanosleep # time do_nanosleep(), in milliseconds |
| 223 | ./funclatency -mTi 5 vfs_read # output every 5 seconds, with timestamps |
| 224 | ./funclatency -p 181 vfs_read # time process 181 only |
| 225 | ./funclatency 'vfs_fstat*' # time both vfs_fstat() and vfs_fstatat() |