| Demonstrations of funcinterval, the Linux eBPF/bcc version. |
| |
| eBPF/bcc is very suitable for platform performance tuning. |
| By funclatency, we can profile specific functions to know how latency |
| this function costs. However, sometimes performance drop is not about the |
| latency of function but the interval between function calls. |
| funcinterval is born for this purpose. |
| |
| Another story, hardware performance tuning on the platform we will use |
| protocol analyzer to analyze performance, but most protocol analyzers lack |
| the distribution feature. Using a protocol analyzer you need a lot of time |
| to check every detail latency. By funcinterval, we can save a lot of time |
| by distribution feature. |
| |
| For example: |
| |
| # ./funcinterval xhci_ring_ep_doorbell -d 2 -u |
| Tracing 1 functions for "xhci_ring_ep_doorbell"... Hit Ctrl-C to end. |
| |
| usecs : count distribution |
| 0 -> 1 : 0 | | |
| 2 -> 3 : 0 | | |
| 4 -> 7 : 0 | | |
| 8 -> 15 : 0 | | |
| 16 -> 31 : 0 | | |
| 32 -> 63 : 134 | | |
| 64 -> 127 : 2862 |******************** | |
| 128 -> 255 : 5552 |****************************************| |
| 256 -> 511 : 216 |* | |
| 512 -> 1023 : 2 | | |
| Detaching... |
| |
| This example output shows that the interval latency of xhci_ring_ep_doorbell |
| took between 64 and 255 microseconds. USB MAC will start its job after USB |
| doorbell register ringing, above information that can help hardware engineer to |
| analyze, the performance drop is because software rings the doorbell too |
| late or just slowly hardware DMA. |
| |
| # ./funcinterval blk_start_request -i 2 -u |
| Tracing 1 functions for "blk_start_request"... Hit Ctrl-C to end. |
| |
| usecs : count distribution |
| 0 -> 1 : 0 | | |
| 2 -> 3 : 0 | | |
| 4 -> 7 : 0 | | |
| 8 -> 15 : 5 |* | |
| 16 -> 31 : 0 | | |
| 32 -> 63 : 1 | | |
| 64 -> 127 : 2 | | |
| 128 -> 255 : 1 | | |
| 256 -> 511 : 0 | | |
| 512 -> 1023 : 1 | | |
| 1024 -> 2047 : 1 | | |
| 2048 -> 4095 : 117 |****************************************| |
| 4096 -> 8191 : 13 |**** | |
| 8192 -> 16383 : 1 | | |
| |
| If using biolatency tool that has no difference between two platforms. |
| Maybe the problem is related to the interval time instead of block |
| device I/O latency. |
| |
| # ./funcinterval ion_ioctl -i 2 -m |
| Tracing 1 functions for "ion_ioctl"... Hit Ctrl-C to end. |
| |
| msecs : count distribution |
| 0 -> 1 : 215 |****************************************| |
| 2 -> 3 : 0 | | |
| 4 -> 7 : 4 | | |
| 8 -> 15 : 5 | | |
| 16 -> 31 : 29 |***** | |
| |
| You can also check the ion_ioctl. By the above output, we know the activity |
| frequency of ion_ioctl() is high mostly(less than 1 ms), but has 29 times low |
| frequency. |
| |
| # ./funcinterval t:block:block_bio_queue -d 30 -u |
| Tracing tracepoint for "block:block_bio_queue"... Hit Ctrl-C to end. |
| |
| usecs : count distribution |
| 0 -> 1 : 0 | | |
| 2 -> 3 : 0 | | |
| 4 -> 7 : 0 | | |
| 8 -> 15 : 2 | | |
| 16 -> 31 : 262 | | |
| 32 -> 63 : 9075 |******************* | |
| 64 -> 127 : 18668 |****************************************| |
| 128 -> 255 : 1492 |*** | |
| 256 -> 511 : 2616 |***** | |
| 512 -> 1023 : 7226 |*************** | |
| 1024 -> 2047 : 8982 |******************* | |
| 2048 -> 4095 : 2394 |***** | |
| 4096 -> 8191 : 163 | | |
| 8192 -> 16383 : 42 | | |
| 16384 -> 32767 : 2 | | |
| 32768 -> 65535 : 0 | | |
| 65536 -> 131071 : 0 | | |
| 131072 -> 262143 : 0 | | |
| 262144 -> 524287 : 0 | | |
| 524288 -> 1048575 : 1 | | |
| Detaching... |
| |
| # ./funcinterval t:block:block_rq_issue -d 30 -u |
| Tracing tracepoint for "block:block_rq_issue"... Hit Ctrl-C to end. |
| |
| usecs : count distribution |
| 0 -> 1 : 0 | | |
| 2 -> 3 : 0 | | |
| 4 -> 7 : 0 | | |
| 8 -> 15 : 0 | | |
| 16 -> 31 : 5 | | |
| 32 -> 63 : 18 | | |
| 64 -> 127 : 32 | | |
| 128 -> 255 : 95 | | |
| 256 -> 511 : 2194 |****** | |
| 512 -> 1023 : 13830 |****************************************| |
| 1024 -> 2047 : 9001 |************************** | |
| 2048 -> 4095 : 1569 |**** | |
| 4096 -> 8191 : 96 | | |
| 8192 -> 16383 : 17 | | |
| Detaching... |
| |
| funcinterval also supports tracepoint filter. The above two cases are under EMMC |
| throughput testing, by those results you know which layer has a slower interval |
| time. In our case, mmc-cmdqd is slower than block layer. |
| |
| |
| # ./funcinterval -p `pidof -s top` c:malloc -i 3 |
| Tracing uprobe function for "malloc"... 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 : 0 | | |
| 4096 -> 8191 : 7 |************************* | |
| 8192 -> 16383 : 11 |****************************************| |
| 16384 -> 32767 : 4 |************** | |
| 32768 -> 65535 : 1 |*** | |
| 65536 -> 131071 : 1 |*** | |
| 131072 -> 262143 : 1 |*** | |
| 262144 -> 524287 : 0 | | |
| 524288 -> 1048575 : 0 | | |
| 1048576 -> 2097151 : 0 | | |
| 2097152 -> 4194303 : 0 | | |
| 4194304 -> 8388607 : 1 |*** | |
| |
| |
| 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 : 0 | | |
| 4096 -> 8191 : 8 |******************************** | |
| 8192 -> 16383 : 10 |****************************************| |
| 16384 -> 32767 : 4 |**************** | |
| 32768 -> 65535 : 1 |**** | |
| 65536 -> 131071 : 1 |**** | |
| 131072 -> 262143 : 1 |**** | |
| 262144 -> 524287 : 0 | | |
| 524288 -> 1048575 : 0 | | |
| 1048576 -> 2097151 : 0 | | |
| 2097152 -> 4194303 : 0 | | |
| 4194304 -> 8388607 : 1 |**** | |
| |
| Time the interval of libc's malloc for top utility every 3 seconds. |
| |
| # ./funcinterval /usr/local/bin/python:main |
| Tracing uprobe function for "main"... 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 : 0 | | |
| 4096 -> 8191 : 0 | | |
| 8192 -> 16383 : 0 | | |
| 16384 -> 32767 : 0 | | |
| 32768 -> 65535 : 0 | | |
| 65536 -> 131071 : 0 | | |
| 131072 -> 262143 : 0 | | |
| 262144 -> 524287 : 0 | | |
| 524288 -> 1048575 : 0 | | |
| 1048576 -> 2097151 : 0 | | |
| 2097152 -> 4194303 : 0 | | |
| 4194304 -> 8388607 : 0 | | |
| 8388608 -> 16777215 : 0 | | |
| 16777216 -> 33554431 : 0 | | |
| 33554432 -> 67108863 : 0 | | |
| 67108864 -> 134217727 : 0 | | |
| 134217728 -> 268435455 : 0 | | |
| 268435456 -> 536870911 : 1 |****************************************| |
| 536870912 -> 1073741823 : 1 |****************************************| |
| 1073741824 -> 2147483647 : 1 |****************************************| |
| 2147483648 -> 4294967295 : 1 |****************************************| |
| Detaching... |
| |
| Time the interal of python's main function. |
| |
| USAGE message: |
| |
| # ./funcinterval -h |
| usage: funcinterval [-h] [-p PID] [-i INTERVAL] [-d DURATION] [-T] [-u] [-m] |
| [-v] |
| pattern |
| |
| Time interval and print latency as a histogram |
| |
| positional arguments: |
| pattern Function name for tracing |
| |
| 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 |
| -v, --verbose print the BPF program (for debugging purposes) |
| |
| examples: |
| # time the interval of do_sys_open() |
| ./funcinterval do_sys_open |
| # time the interval of xhci_ring_ep_doorbell(), in microseconds |
| ./funcinterval -u xhci_ring_ep_doorbell |
| # time the interval of do_nanosleep(), in milliseconds |
| ./funcinterval -m do_nanosleep |
| # output every 5 seconds, with timestamps |
| ./funcinterval -mTi 5 vfs_read |
| # time process 181 only |
| ./funcinterval -p 181 vfs_read |
| # time the interval of mm_vmscan_direct_reclaim_begin tracepoint |
| ./funcinterval t:vmscan:mm_vmscan_direct_reclaim_begin |
| # time the interval of c:malloc used by top every 3 seconds |
| ./funcinterval -p `pidof -s top` -i 3 c:malloc |
| # time /usr/local/bin/python main function |
| ./funcinterval /usr/local/bin/python:main |
