| Demonstrations of wqlat, the Linux eBPF/bcc version. |
| |
| This tool traces work's waiting on workqueue, and records the distribution |
| of work's queuing latency (time), printing this as a histogram when Ctrl-C |
| is hit. |
| |
| For example: |
| |
| ./wqlat |
| Tracing work queue request latency time... Hit Ctrl-C to end. |
| ^C |
| usecs : count distribution |
| 0 -> 1 : 530 |*************************** | |
| 2 -> 3 : 775 |****************************************| |
| 4 -> 7 : 387 |******************* | |
| 8 -> 15 : 194 |********** | |
| 16 -> 31 : 62 |*** | |
| 32 -> 63 : 10 | | |
| 64 -> 127 : 2 | | |
| 128 -> 255 : 0 | | |
| 256 -> 511 : 0 | | |
| 512 -> 1023 : 0 | | |
| 1024 -> 2047 : 0 | | |
| 2048 -> 4095 : 0 | | |
| 4096 -> 8191 : 1 | | |
| |
| This example shows all kernel's work waiting latlency on workqueue. The range |
| of latency is from 1 millisecond to 8192 milliseconds(8ms). The bulk of |
| waiting latency is between 1us and 32us.The highest latency seen while tracing |
| is between 4 and 8 ms:the last row printed, for which there is 1 work |
| |
| We can also specify the per workqueue option (-W), along with interval |
| and count parameters. Eg, printing out every 1 second, and including |
| timestamps(-T): |
| |
| ./wqlat -T -W 1 2 |
| Tracing work queue request latency time... Hit Ctrl-C to end. |
| |
| 06:14:55 |
| |
| wqname = xfs-cil/dm-4 |
| usecs : count distribution |
| 0 -> 1 : 0 | | |
| 2 -> 3 : 1 |****************************************| |
| 4 -> 7 : 1 |****************************************| |
| 8 -> 15 : 1 |****************************************| |
| [...] |
| |
| 06:14:56 |
| |
| wqname = events_power_efficient |
| usecs : count distribution |
| 0 -> 1 : 0 | | |
| 2 -> 3 : 0 | | |
| 4 -> 7 : 2 |************************** | |
| 8 -> 15 : 3 |****************************************| |
| 16 -> 31 : 1 |************* | |
| [...] |
| |
| An tracing one workqueue (-w) can be specified, along with interval |
| and count. Eg, printing output every 1 second, and including Timestamps(-T) |
| and workqueue nvmet_tcp_wq: |
| |
| ./wqlat -T -w nvmet_tcp_wq 1 2 |
| Tracing work queue request latency time... Hit Ctrl-C to end. |
| |
| 06:18:03 |
| usecs : count distribution |
| 0 -> 1 : 245 |************************* | |
| 2 -> 3 : 377 |****************************************| |
| 4 -> 7 : 76 |******** | |
| 8 -> 15 : 29 |*** | |
| 16 -> 31 : 8 | | |
| 32 -> 63 : 5 | | |
| |
| 06:18:04 |
| usecs : count distribution |
| 0 -> 1 : 547 |********************************** | |
| 2 -> 3 : 629 |****************************************| |
| 4 -> 7 : 83 |***** | |
| 8 -> 15 : 23 |* | |
| 16 -> 31 : 5 | | |
| 32 -> 63 : 4 | | |
| |
| USAGE message: |
| |
| ./wqlat -h |
| usage: wqlat [-h] [-T] [-N] [-W] [-w WQNAME] [interval] [count] |
| |
| Summarize workqueue request latency as histograms. |
| |
| positional arguments: |
| interval output interval, in seconds |
| count number of outputs |
| |
| optional arguments: |
| -h, --help show this help message and exit |
| -T, --timestamp include timestamp on output |
| -N, --nanoseconds output in nanoseconds |
| -W, --workqueues print a histogram per work queue |
| -w WQNAME, --wqname WQNAME |
| print this workqueue only |
| |
| examples: |
| ./wqlat # summarize workqueue latency as a histogram |
| ./wqlat 1 10 # print 1 second summaries, 10 times |
| ./wqlat -W 1 10 # print 1 second, 10 times per workqueue |
| ./wqlat -NT 1 # 1s summaries, nanoseconds, and timestamps |
| ./wqlat -w nvmet_tcp_wq 1 # 1s summaries for workqueue nvmet_tcp_wq |
