Demonstrations of aliext4writeslower.

This script traces key steps of write(2) which maybe time-consuming,
here trace 4 key steps: jbd2 handle start(it may need jbd2 transaction
checkpoint or commit), page cache allocation, block allocation and
balance dirty pages, and we also take into account sched delay.
With this tool, we can clearly know write(2)'s latency proportion.

Usage:
usage: aliext4writeslower [-h] [-p PID] [-d DEVICE] [min_ms]

Trace common ext4 write(2) slower than a threshold

positional arguments:
  min_ms                minimum I/O duration to trace, in ms (default 10)

optional arguments:
  -h, --help            show this help message and exit
  -p PID, --pid PID     trace this PID only
  -d DEVICE, --device DEVICE
                        inspect specified device

examples:
    ./aliext4writeslower             # trace write(2) slower than 10 ms (default)
    ./aliext4writeslower 1           # trace write(2) slower than 1 ms
    ./aliext4writeslower 0           # trace all operations (warning: verbose)
    ./aliext4writeslower -d sda5     # inspect specified device /dev/sda5 containing ext4 fs
    ./aliext4writeslower -p 185      # trace PID 185 only


Output example:

Example 1:
# Trace write(2) slower than 5 ms
python aliext4writeslower.py 5

Tracing ext4 operations slower than 5 ms
TIME     DEVICE   COMM           PID    BYTES   OFF_KB   LAT(ms) pg_alloc jbd2_start block_alloc balance_dirty write_begin write_end sched_delay FILENAME
17:14:07 sda5     dd             31149  1048576 473088      5.15     1.02       0.68        0.25          0.54        2.50      1.57        0.00 testfile
17:14:07 sda5     dd             31149  1048576 474112      5.27     1.07       0.68        0.27          0.54        2.58      1.59        0.00 testfile
17:14:07 sda5     dd             31149  1048576 475136      5.09     1.01       0.69        0.30          0.53        2.52      1.49        0.00 testfile
17:14:07 sda5     dd             31149  1048576 607232      5.12     1.09       0.67        0.21          0.54        2.52      1.50        0.00 testfile
17:14:07 sda5     dd             31149  1048576 637952      6.88     1.20       1.15        0.34          0.75        3.38      1.97        0.00 testfile
17:14:07 sda5     dd             31149  1048576 674816      5.29     1.17       0.68        0.20          0.55        2.60      1.58        0.00 testfile
17:14:08 sda5     dd             31149  1048576 738304      5.08     0.99       0.69        0.27          0.54        2.46      1.54        0.00 testfile
17:14:08 sda5     dd             31149  1048576 790528      5.03     0.94       0.69        0.25          0.54        2.42      1.50        0.00 testfile
17:14:08 sda5     dd             31149  1048576 803840      5.04     0.96       0.67        0.29          0.54        2.45      1.51        0.00 testfile
17:14:08 sda5     dd             31149  1048576 870400      5.15     1.10       0.68        0.19          0.55        2.52      1.53        0.00 testfile
17:14:09 sda5     dd             31149  1048576 986112      5.08     1.00       0.69        0.27          0.54        2.48      1.51        0.00 testfile


Example 2:
# Inspect specified device /dev/sda5 containing ext4 fs
python aliext4writeslower.py -d sda5

Tracing ext4 operations
TIME     DEVICE   COMM           PID    BYTES   OFF_KB   LAT(ms) pg_alloc jbd2_start block_alloc balance_dirty write_begin write_end sched_delay FILENAME
17:16:24 sda3     su             32894  292     0           0.03     0.00       0.00        0.00          0.00        0.01      0.00        0.00 lastlog
17:16:24 sda3     syslog-ng      990    67      456973      0.07     0.01       0.01        0.00          0.00        0.02      0.01        0.00 secure-20190805
17:16:24 sda3     syslog-ng      990    106     456973      0.02     0.00       0.00        0.00          0.00        0.01      0.01        0.00 secure-20190805
17:16:24 sda3     syslog-ng      990    67      475637      0.02     0.00       0.00        0.00          0.00        0.01      0.01        0.00 messages-20190805
17:16:24 sda3     syslog-ng      990    106     475637      0.02     0.00       0.00        0.00          0.00        0.01      0.01        0.00 messages-20190805
17:16:24 sda3     ilogtail       56674  199     3296        0.04     0.00       0.01        0.00          0.00        0.01      0.01        0.00 000147.log
17:16:24 sda3     syslog-ng      990    95      456974      0.04     0.01       0.01        0.00          0.00        0.01      0.01        0.00 secure-20190805
17:16:24 sda3     syslog-ng      990    95      475637      0.02     0.00       0.00        0.00          0.00        0.01      0.01        0.00 messages-20190805
17:16:24 sda3     xperf          2558   874     403         0.03     0.00       0.01        0.00          0.00        0.01      0.01        0.00 xperf.pmu.data.0
17:16:25 sda3     xperf          2558   819     403         0.06     0.01       0.01        0.00          0.01        0.02      0.01        0.00 xperf.pmu.data.0
17:16:25 sda3     syslog-ng      990    175     456974      0.05     0.01       0.01        0.00          0.00        0.01      0.01        0.00 secure-20190805
