Demonstrations of alibiolatency.

Alibiolatency can trace every io request's life cycle and do data filter and statistics
accordingly. With this tool, we can clearly know io request's different stage's latency
proportion, for example, if io request D2C(see blktrace) time take majority in total io
request process time, it's most likely disk bottleneck has been reached.

Usage:
alibiolatency [-h] [-d DEVICE] [-i [DIS_INTERVAL]] [-t [AVG_THRESHOLD_TIME]] [-T [THRESHOLD_TIME]] [-r]

Summarize block device I/O latency

optional arguments:
  -h, --help            show this help message and exit
  -d DEVICE, --device DEVICE
                        inspect specified device
  -i [DIS_INTERVAL], --dis_interval [DIS_INTERVAL]
                        specify display interval
  -t [AVG_THRESHOLD_TIME], --avg_threshold_time [AVG_THRESHOLD_TIME]
                        display only when average request process time is
                        greater than this value
  -T [THRESHOLD_TIME], --threshold_time [THRESHOLD_TIME]
                        dump request life cycle when single request process
                        time is greater than this value
  -r, --dump_raw        dump every io request life cycle

examples:
    ./alibiolatency          # summarize block I/O latency(default display interval is 2s)
    ./alibiolatency -d sda3  # inspect specified device /dev/sda3
    ./alibiolatency -i 2     # specify display interval, 2s
    ./alibiolatency -t 10    # display only when average request process time is greater than 10ms
    ./alibiolatency -T 20    # dump request life cycle when single request process time is greater than 20ms
    ./alibiolatency -T 20    # dump request life cycle when single request process time is greater than 20ms
    ./alibiolatency -r       # dump every io request life cycle


Output example:

Example 1:
# Summarize block device I/O latency periodically.
python alibiolatency.py

Wed Aug 28 19:13:00 2019
dev: sda
  READ iops:32 avg:15.36 min:0.02 max:143.51 speed:0.00MB/s avgrq-sz:4KB
  [i2d_avg: 0.00 percent:0 min:0.00 max:0.01
  [d2c_avg: 15.26 percent:99 min:0.02 max:143.51
  WRITE iops:2 avg:0.06 min:0.04 max:0.09 speed:0.00MB/s avgrq-sz:24KB
  [i2d_avg: 0.00 percent:2 min:0.00 max:0.00
  [d2c_avg: 0.05 percent:76 min:0.03 max:0.06


Wed Aug 28 19:13:03 2019
dev: sda
  READ iops:62 avg:2.03 min:0.03 max:16.08 speed:0.68MB/s avgrq-sz:14KB
  [i2d_avg: 0.00 percent:0 min:0.00 max:0.00
  [d2c_avg: 1.99 percent:97 min:0.03 max:16.07
  WRITE iops:6 avg:0.06 min:0.03 max:0.12 speed:0.00MB/s avgrq-sz:10KB
  [i2d_avg: 0.00 percent:5 min:0.00 max:0.01
  [d2c_avg: 0.04 percent:76 min:0.03 max:0.07

Example 2:
# Summarize block device I/O latency periodically, and will print io request's
# complete life cycle when this io request's process time is greater than 20ms.
python alibiolatency.py  -T 20 # Summarize block device I/O latency periodically.

timeouted request sector:269555712 bytes:1024 req time:379
sda Q 3102021522 sector:269555712 bytes:1024 act:W
sda G 3102021522 sector:269555712 bytes:1024 act:W
sda I 3102021522 sector:269555712 bytes:1024 act:W
sda D 3102021522 sector:269555712 bytes:1024 act:W
sda C 3102021902 sector:269555712 bytes:1024 act:W
Wed Aug 28 19:28:44 2019
timeouted request sector:269556736 bytes:1024 req time:381
sda Q 3102021522 sector:269556736 bytes:1024 act:W
sda G 3102021522 sector:269556736 bytes:1024 act:W
sda I 3102021522 sector:269556736 bytes:1024 act:W
sda D 3102021522 sector:269556736 bytes:1024 act:W
sda C 3102021904 sector:269556736 bytes:1024 act:W
Wed Aug 28 19:28:45 2019
dev: sda
  READ iops:0 avg:0.07 min:0.07 max:0.07 speed:0.00MB/s avgrq-sz:4KB
  [i2d_avg: 0.01 percent:17 min:0.01 max:0.01
  [d2c_avg: 0.05 percent:73 min:0.05 max:0.05
  WRITE iops:173 avg:339.79 min:0.04 max:501.72 speed:69.09MB/s avgrq-sz:408KB
  [i2d_avg: 0.02 percent:0 min:0.00 max:0.06
  [d2c_avg: 339.16 percent:99 min:0.04 max:501.67

Example 3:
# Summarize block device I/O latency periodically, and will print every io
# request's complete life cycle.
python alibiolatency.py  -r

Wed Aug 28 19:36:40 2019
raw request event sector:52903080 bytes:8 req time:0
sda Q 3102498371 sector:52903080 bytes:8 act:WS
sda G 3102498371 sector:52903080 bytes:8 act:WS
sda I 3102498371 sector:52903080 bytes:8 act:WS
sda D 3102498371 sector:52903080 bytes:8 act:WS
sda C 3102498371 sector:52903080 bytes:8 act:WS
Wed Aug 28 19:36:40 2019
raw request event sector:2157826760 bytes:8 req time:0
sda Q 3102498785 sector:2157826760 bytes:8 act:W
sda G 3102498785 sector:2157826760 bytes:8 act:W
sda I 3102498785 sector:2157826760 bytes:8 act:W
sda D 3102498785 sector:2157826760 bytes:8 act:W
sda C 3102498785 sector:2157826760 bytes:8 act:W
Wed Aug 28 19:36:42 2019
raw request event sector:208390056 bytes:8 req time:0
sda Q 3102500593 sector:208390056 bytes:8 act:W
sda G 3102500593 sector:208390056 bytes:8 act:W
sda I 3102500593 sector:208390056 bytes:8 act:W
sda D 3102500593 sector:208390056 bytes:8 act:W
sda C 3102500593 sector:208390056 bytes:8 act:W
Wed Aug 28 19:36:42 2019
dev: sda
  WRITE iops:42 avg:0.13 min:0.04 max:0.24 speed:0.00MB/s avgrq-sz:5KB
  [i2d_avg: 0.01 percent:8 min:0.00 max:0.03
  [d2c_avg: 0.06 percent:48 min:0.03 max:0.10
