Demonstrations of fileslower, the Linux eBPF/bcc version.


fileslower shows file-based synchronous reads and writes slower than a
threshold. For example:

# ./fileslower 
Tracing sync read/writes slower than 10 ms
TIME(s)  COMM           PID    D BYTES   LAT(ms) FILENAME
0.000    randread.pl    4762   R 8192      12.70 data1
8.850    randread.pl    4762   R 8192      11.26 data1
12.852   randread.pl    4762   R 8192      10.43 data1

This showed a few reads from a "randread.pl" program, each 8 Kbytes in size,
and from a "data1" file. These all had over 10 ms latency.

This "latency" is measured from when the read or write was issued at the VFS
interface, 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 file reads and writes: other file system operations
(eg, directory operations, open(), fflush()) are not traced.


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

# ./fileslower 1
Tracing sync read/writes slower than 1 ms
TIME(s)  COMM           PID    D BYTES   LAT(ms) FILENAME
0.000    randread.pl    6925   R 8192       1.06 data1
0.082    randread.pl    6925   R 8192       2.42 data1
0.116    randread.pl    6925   R 8192       1.78 data1
0.153    randread.pl    6925   R 8192       2.31 data1
0.330    randread.pl    6925   R 8192       1.14 data1
0.345    randread.pl    6925   R 8192       1.52 data1
0.359    randread.pl    6925   R 8192       1.04 data1
0.532    randread.pl    6925   R 8192       2.56 data1
0.609    supervise      1892   W 18         3.65 status.new
0.610    randread.pl    6925   R 8192       1.37 data1
0.614    randread.pl    6925   R 8192       3.04 data1
0.729    randread.pl    6925   R 8192       2.90 data1
0.755    randread.pl    6925   R 8192       1.12 data1
0.762    randread.pl    6925   R 8192       2.62 data1
0.771    randread.pl    6925   R 8192       1.07 data1
0.816    randread.pl    6925   R 8192      10.50 data1
0.983    randread.pl    6925   R 8192       1.73 data1
0.989    randread.pl    6925   R 8192       2.12 data1
0.992    randread.pl    6925   R 8192       2.17 data1
1.001    randread.pl    6925   R 8192       1.93 data1
1.007    randread.pl    6925   R 8192       2.03 data1
1.210    randread.pl    6925   R 8192       1.82 data1
1.213    randread.pl    6925   R 8192       2.58 data1
1.219    randread.pl    6925   R 8192       2.20 data1
1.430    randread.pl    6925   R 8192       1.01 data1
1.448    randread.pl    6925   R 8192       2.22 data1
[...]

There's now much more output (this spans only 1.4 seconds, the previous output
spanned 12 seconds), and the lower threshold is catching more I/O.


In the following example, the file system caches were dropped before running
fileslower, and then in another session a "man ls" was executed. The command
and files read from disk can be seen:

# echo 3 > /proc/sys/vm/drop_caches; ./fileslower 1
Tracing sync read/writes slower than 1 ms
TIME(s)  COMM           PID    D BYTES   LAT(ms) FILENAME
0.000    bash           9647   R 128        5.83 man
0.050    man            9647   R 832       19.52 libmandb-2.6.7.1.so
0.066    man            9647   R 832       15.79 libman-2.6.7.1.so
0.123    man            9647   R 832       56.36 libpipeline.so.1.3.0
0.135    man            9647   R 832        9.79 libgdbm.so.3.0.0
0.323    man            9647   R 4096      59.52 locale.alias
0.540    man            9648   R 8192      11.11 ls.1.gz
0.558    man            9647   R 72         6.97 index.db
0.563    man            9647   R 4096       5.12 index.db
0.723    man            9658   R 128       12.06 less
0.725    man            9656   R 128       14.52 nroff
0.779    man            9655   R 128       68.86 tbl
0.814    nroff          9660   R 128       14.55 locale
0.830    pager          9658   R 4096      28.27 .lesshst
0.866    man            9654   R 128      163.12 preconv
0.980    nroff          9684   R 128       13.80 groff
0.999    groff          9684   R 4096      14.29 DESC
1.036    groff          9685   R 128        5.94 troff
1.038    groff          9686   R 128        7.76 grotty
1.065    troff          9685   R 4096       6.33 R
1.082    troff          9685   R 4096      10.52 BI
1.096    troff          9685   R 4096       8.70 troffrc
1.176    troff          9685   R 4096      80.12 composite.tmac
1.195    troff          9685   R 4096      19.20 fallbacks.tmac
1.202    troff          9685   R 4096       6.79 tty.tmac
1.221    troff          9685   R 4096       7.87 man.local
2.977    supervise      1876   W 18         4.23 status.new

This caught an individual I/O reaching 163.12 ms, for the "preconv" file. While
the file system cache was flushed, causing these to need to be read from disk,
the duration here may not be entirely disk I/O: it can include file system
locks, run queue latency, etc. These can be explored using other commands.


USAGE message:

# ./fileslower -h
usage: fileslower.py [-h] [-p PID] [-a] [min_ms]

Trace slow synchronous file reads and writes

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
  -a, --all-files    include non-regular file types

examples:
    ./fileslower             # trace sync file I/O slower than 10 ms (default)
    ./fileslower 1           # trace sync file I/O slower than 1 ms
    ./fileslower -p 185      # trace PID 185 only