tools/ext4slower_example.txt

Demonstrations of ext4slower, the Linux eBPF/bcc version.


ext4slower shows ext4 reads, writes, opens, and fsyncs, slower than a threshold.
For example:

# ./ext4slower
Tracing ext4 operations slower than 10 ms
TIME     COMM           PID    T BYTES   OFF_KB   LAT(ms) FILENAME
06:35:01 cron           16464  R 1249    0          16.05 common-auth
06:35:01 cron           16463  R 1249    0          16.04 common-auth
06:35:01 cron           16465  R 1249    0          16.03 common-auth
06:35:01 cron           16465  R 4096    0          10.62 login.defs
06:35:01 cron           16464  R 4096    0          10.61 login.defs
06:35:01 cron           16463  R 4096    0          10.63 login.defs
06:35:01 cron           16465  R 2972    0          18.52 pam_env.conf
06:35:01 cron           16464  R 2972    0          18.51 pam_env.conf
06:35:01 cron           16463  R 2972    0          18.49 pam_env.conf
06:35:01 dumpsystemstat 16473  R 128     0          12.58 date
06:35:01 debian-sa1     16474  R 283     0          12.66 sysstat
06:35:01 debian-sa1     16474  R 128     0          10.39 sa1
06:35:01 dumpsystemstat 16491  R 128     0          13.22 ifconfig
06:35:01 DumpThreads    16534  R 128     0          12.78 cut
06:35:01 cron           16545  R 128     0          14.76 sendmail
06:35:01 sendmail       16545  R 274     0          10.88 dynamicmaps.cf
06:35:02 postdrop       16546  R 118     0          32.94 Universal
06:35:02 pickup         9574   R 118     0          21.02 localtime
[...]

This shows various system tasks reading from ext4. The high latency here is
due to disk I/O, as I had just evicted the file system cache for this example.

This "latency" is measured from when the operation was issued from the VFS
interface to the file system, to when it completed. This spans everything:
block device I/O (disk I/O), file system CPU cycles, file system locks, run
queue latency, etc. This is a better measure of the latency suffered by
applications reading from the file system than measuring this down at the
block device interface.

Note that this only traces the common file system operations previously
listed: other file system operations (eg, inode operations including
getattr()) are not traced.


The threshold can be provided as an argument. Eg, I/O slower than 1 ms:

# ./ext4slower 1
Tracing ext4 operations slower than 1 ms
TIME     COMM           PID    T BYTES   OFF_KB   LAT(ms) FILENAME
06:49:17 bash           3616   R 128     0           7.75 cksum
06:49:17 cksum          3616   R 39552   0           1.34 [
06:49:17 cksum          3616   R 96      0           5.36 2to3-2.7
06:49:17 cksum          3616   R 96      0          14.94 2to3-3.4
06:49:17 cksum          3616   R 10320   0           6.82 411toppm
06:49:17 cksum          3616   R 65536   0           4.01 a2p
06:49:17 cksum          3616   R 55400   0           8.77 ab
06:49:17 cksum          3616   R 36792   0          16.34 aclocal-1.14
06:49:17 cksum          3616   R 15008   0          19.31 acpi_listen
06:49:17 cksum          3616   R 6123    0          17.23 add-apt-repository
06:49:17 cksum          3616   R 6280    0          18.40 addpart
06:49:17 cksum          3616   R 27696   0           2.16 addr2line
06:49:17 cksum          3616   R 58080   0          10.11 ag
06:49:17 cksum          3616   R 906     0           6.30 ec2-meta-data
06:49:17 cksum          3616   R 6320    0          10.00 animate.im6
06:49:17 cksum          3616   R 5680    0          18.69 anytopnm
06:49:17 cksum          3616   R 2671    0          20.27 apport-bug
06:49:17 cksum          3616   R 12566   0          16.72 apport-cli
06:49:17 cksum          3616   R 1622    0           7.95 apport-unpack
06:49:17 cksum          3616   R 10440   0           2.37 appres
06:49:17 cksum          3616   R 48112   0           5.42 whatis
06:49:17 cksum          3616   R 14832   0           6.24 apt
06:49:17 cksum          3616   R 65536   0          24.74 apt-cache
06:49:17 cksum          3616   R 27264   0           1.68 apt-cdrom
06:49:17 cksum          3616   R 23224   0           5.31 apt-extracttemplates
06:49:17 cksum          3616   R 65536   0           8.08 apt-ftparchive
06:49:17 cksum          3616   R 65536   128         2.92 apt-ftparchive
06:49:17 cksum          3616   R 65536   0           9.58 aptitude-curses
06:49:17 cksum          3616   R 65536   128        44.25 aptitude-curses
06:49:17 cksum          3616   R 65536   384         1.69 aptitude-curses
[...]

This time a cksum(1) command can be seen reading various files (from /usr/bin).


A threshold of 0 will trace all operations. Warning: the output will be
verbose, as it will include all file system cache hits.

# ./ext4slower 0
Tracing ext4 operations
TIME     COMM           PID    T BYTES   OFF_KB   LAT(ms) FILENAME
06:58:05 supervise      1884   O 0       0           0.00 status.new
06:58:05 supervise      1884   W 18      0           0.02 status.new
06:58:05 supervise      1884   O 0       0           0.00 status.new
06:58:05 supervise      1884   W 18      0           0.01 status.new
06:58:05 supervise      15817  O 0       0           0.00 run
06:58:05 supervise      15817  R 92      0           0.00 run
06:58:05 supervise      15817  O 0       0           0.00 bash
06:58:05 supervise      15817  R 128     0           0.00 bash
06:58:05 supervise      15817  R 504     0           0.00 bash
06:58:05 supervise      15817  R 28      0           0.00 bash
06:58:05 supervise      15817  O 0       0           0.00 ld-2.19.so
06:58:05 supervise      15817  R 64      0           0.00 ld-2.19.so
06:58:05 supervise      15817  R 392     0           0.00 ld-2.19.so
06:58:05 run            15817  O 0       0           0.00 ld.so.cache
06:58:05 run            15817  O 0       0           0.00 libtinfo.so.5.9
06:58:05 run            15817  R 832     0           0.00 libtinfo.so.5.9
06:58:05 run            15817  O 0       0           0.00 libdl-2.19.so
06:58:05 run            15817  R 832     0           0.00 libdl-2.19.so
06:58:05 run            15817  O 0       0           0.00 libc-2.19.so
06:58:05 run            15817  R 832     0           0.00 libc-2.19.so
06:58:05 supervise      1876   O 0       0           0.00 status.new
06:58:05 supervise      1876   W 18      0           0.01 status.new
06:58:05 supervise      1895   O 0       0           0.00 status.new
06:58:05 supervise      1895   W 18      0           0.02 status.new
06:58:05 supervise      1876   O 0       0           0.00 status.new
06:58:05 supervise      1876   W 18      0           0.01 status.new
06:58:05 supervise      1872   O 0       0           0.00 status.new
06:58:05 supervise      1872   W 18      0           0.02 status.new
06:58:05 supervise      1895   O 0       0           0.00 status.new
06:58:05 supervise      1895   W 18      0           0.01 status.new
06:58:05 supervise      15818  R 92      0           0.00 run
06:58:05 supervise      15818  O 0       0           0.00 bash
06:58:05 supervise      15818  R 128     0           0.00 bash
06:58:05 supervise      15818  R 504     0           0.00 bash
06:58:05 supervise      15818  R 28      0           0.00 bash
06:58:05 supervise      15818  O 0       0           0.00 ld-2.19.so
06:58:05 supervise      15818  R 64      0           0.00 ld-2.19.so
06:58:05 supervise      15818  R 392     0           0.00 ld-2.19.so
06:58:05 supervise      15818  O 0       0           0.00 run
06:58:05 supervise      1888   O 0       0           0.00 status.new
06:58:05 supervise      1888   W 18      0           0.01 status.new
06:58:05 supervise      1888   O 0       0           0.00 status.new
06:58:05 supervise      1888   W 18      0           0.02 status.new
06:58:05 supervise      15822  R 119     0           0.00 run
06:58:05 supervise      15822  O 0       0           0.00 bash
06:58:05 supervise      15822  R 128     0           0.00 bash
06:58:05 supervise      15822  R 504     0           0.00 bash
06:58:05 supervise      15822  R 28      0           0.00 bash
06:58:05 supervise      15822  O 0       0           0.00 ld-2.19.so
06:58:05 supervise      15822  R 64      0           0.00 ld-2.19.so
06:58:05 supervise      15822  R 392     0           0.00 ld-2.19.so
06:58:05 supervise      1892   O 0       0           0.00 status.new
06:58:05 supervise      1892   W 18      0           0.02 status.new
06:58:05 supervise      1892   O 0       0           0.00 status.new
06:58:05 supervise      1892   W 18      0           0.02 status.new
06:58:05 supervise      15820  O 0       0           0.00 run
[...]

The output now includes open operations ("O"), and writes ("W").


A -j option will print just the fields (parsable output, csv):

# ./ext4slower -j 1
ENDTIME_us,TASK,PID,TYPE,BYTES,OFFSET_b,LATENCY_us,FILE
127200712278,bash,17225,R,128,0,14329,cksum
127200722986,cksum,17225,R,3274,0,8368,command-not-found
127200735581,cksum,17225,R,65536,0,10903,libbfd-2.24-system.so
127200738482,cksum,17225,R,65536,131072,2419,libbfd-2.24-system.so
127200749226,cksum,17225,R,65536,655360,8995,libbfd-2.24-system.so
127200776273,cksum,17225,R,55080,0,25297,libbind9.so.90.0.9
127200784688,cksum,17225,R,65536,0,7873,libblas.so.3.0
127200787551,cksum,17225,R,65536,131072,2386,libblas.so.3.0
127200795524,cksum,17225,R,18624,0,4947,libcpupower.so.3.13.0-49
127200802073,cksum,17225,R,65536,0,6410,libcwidget.so.3.0.0
127200808718,cksum,17225,R,65536,131072,6181,libcwidget.so.3.0.0
127200829518,cksum,17225,R,65536,0,14213,libdns.so.100.2.2
127200832916,cksum,17225,R,65536,131072,2911,libdns.so.100.2.2
127200841044,cksum,17225,R,65536,655360,6376,libdns.so.100.2.2
127200853646,cksum,17225,R,956,0,1022,libdumbnet.la
127200857814,cksum,17225,R,61096,0,4111,libdumbnet.so.1.0.1
127200869655,cksum,17225,R,65536,0,11252,libgettextlib-0.18.3.so
127200872985,cksum,17225,R,65536,131072,2882,libgettextlib-0.18.3.so
127200883063,cksum,17225,R,65536,0,9661,libgettextsrc-0.18.3.so
127200884767,cksum,17225,R,65536,131072,1251,libgettextsrc-0.18.3.so
127200904830,cksum,17225,R,65536,0,19571,libgirepository-1.0.so.1.0.0
127200906354,cksum,17225,R,65536,131072,1080,libgirepository-1.0.so.1.0.0
127200936047,cksum,17225,R,65536,0,28674,libGraphicsMagick.a
127200939091,cksum,17225,R,65536,131072,2576,libGraphicsMagick.a
127200947295,cksum,17225,R,65536,655360,6463,libGraphicsMagick.a
127200958793,cksum,17225,R,65536,1966080,7034,libGraphicsMagick.a
[...]

This may be useful for visualizing with another tool, for example, for
producing a scatter plot of ENDTIME vs LATENCY, to look for time-based
patterns.


USAGE message:

# ./ext4slower -h
usage: ext4slower [-h] [-j] [-p PID] [min_ms]

Trace common ext4 file operations 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
  -j, --csv          just print fields: comma-separated values
  -p PID, --pid PID  trace this PID only

examples:
    ./ext4slower             # trace operations slower than 10 ms (default)
    ./ext4slower 1           # trace operations slower than 1 ms
    ./ext4slower -j 1        # ... 1 ms, parsable output (csv)
    ./ext4slower 0           # trace all operations (warning: verbose)
    ./ext4slower -p 185      # trace PID 185 only