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