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