Demonstrations of xfsslower, the Linux eBPF/bcc version.
xfsslower shows XFS reads, writes, opens, and fsyncs, slower than a threshold.
For example:
# ./xfsslower
Tracing XFS operations slower than 10 ms
TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME
06:23:06 randread.pl 32497 R 8192 24938024 17.93 data1
06:23:06 randread.pl 32521 R 8192 13431528 18.27 data1
06:23:08 randread.pl 32497 R 8192 5070904 16.37 data1
06:23:08 randread.pl 32521 R 8192 12693016 16.06 data1
06:23:18 randread.pl 32521 R 8192 27049136 21.68 data1
06:23:18 randread.pl 32497 R 8192 257864 21.74 data1
06:23:20 randread.pl 32497 R 8192 17797208 13.37 data1
06:23:20 randread.pl 32497 R 8192 6088224 19.74 data1
This shows several 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 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:
# ./xfsslower 1
Tracing XFS operations slower than 1 ms
TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME
06:26:59 randread.pl 5394 R 8192 9045728 1.24 data1
06:26:59 randread.pl 5394 R 8192 23532136 1.17 data1
06:26:59 randread.pl 5442 R 8192 2192376 2.06 data1
06:27:00 randread.pl 5394 R 8192 3535176 1.27 data1
06:27:00 randread.pl 5442 R 8192 21361784 3.18 data1
06:27:00 randread.pl 5394 R 8192 2556336 3.23 data1
06:27:00 randread.pl 5394 R 8192 20020880 2.87 data1
06:27:00 randread.pl 5442 R 8192 20708888 3.32 data1
06:27:00 randread.pl 5394 R 8192 4654680 2.00 data1
06:27:00 randread.pl 5442 R 8192 5591744 1.98 data1
06:27:00 randread.pl 5394 R 8192 2431056 1.22 data1
06:27:00 randread.pl 5394 R 8192 384288 2.95 data1
06:27:00 randread.pl 5442 R 8192 29277672 3.07 data1
06:27:00 randread.pl 5442 R 8192 29508216 3.23 data1
06:27:00 randread.pl 5394 R 8192 17200008 2.86 data1
06:27:00 randread.pl 5442 R 8192 20693088 1.06 data1
06:27:00 randread.pl 5394 R 8192 28124192 1.38 data1
06:27:00 randread.pl 5442 R 8192 23821184 1.28 data1
06:27:00 randread.pl 5394 R 8192 1623200 1.47 data1
[...]
There's now much more output (this spans only 2 seconds, the previous output
spanned 14 seconds), as the lower threshold is catching more I/O.
A threshold of 0 will trace all operations. Warning: the output will be
verbose, as it will include all file system cache hits.
# ./xfsslower 0
Tracing XFS operations
TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME
06:29:43 ls 9291 O 0 0 0.00 bench
06:29:47 cat 9361 O 0 0 0.00 date.txt
06:29:47 cat 9361 R 29 0 0.01 date.txt
06:29:47 cat 9361 R 0 0 0.00 date.txt
06:29:50 bash 20500 O 0 0 0.00 bench
06:29:50 bash 20500 O 0 0 0.00 bench
06:29:50 bash 20500 O 0 0 0.00 bench
06:29:50 bash 9431 O 0 0 0.00 bench
06:29:50 bash 9432 O 0 0 0.00 bench
06:29:50 bash 9456 O 0 0 0.00 newdate.txt
06:29:50 date 9456 W 29 0 0.01 newdate.txt
06:29:53 cksum 9503 O 0 0 0.00 data1
06:29:53 cksum 9503 R 65536 0 0.06 data1
06:29:53 cksum 9503 R 65536 64 0.01 data1
06:29:53 cksum 9503 R 65536 128 0.02 data1
06:29:53 cksum 9503 R 65536 192 0.01 data1
06:29:53 cksum 9503 R 65536 256 0.01 data1
06:29:53 cksum 9503 R 65536 320 0.01 data1
06:29:53 cksum 9503 R 65536 384 0.01 data1
06:29:53 cksum 9503 R 65536 448 0.04 data1
06:29:53 cksum 9503 R 65536 512 0.01 data1
06:29:53 cksum 9503 R 65536 576 0.02 data1
06:29:53 cksum 9503 R 65536 640 0.01 data1
06:29:53 cksum 9503 R 65536 704 0.01 data1
06:29:53 cksum 9503 R 65536 768 0.01 data1
06:29:53 cksum 9503 R 65536 832 0.01 data1
06:29:53 cksum 9503 R 65536 896 0.01 data1
06:29:53 cksum 9503 R 65536 960 0.01 data1
06:29:53 cksum 9503 R 65536 1024 0.01 data1
06:29:53 cksum 9503 R 65536 1088 0.02 data1
06:29:53 cksum 9503 R 65536 1152 0.01 data1
06:29:53 cksum 9503 R 65536 1216 0.01 data1
[...]
The output now includes open operations ("O"), and writes ("W"). A cksum(1)
command can be seen reading from a data1 file, from progressively increasing
offsets: a sequential workload.
A -j option will print just the fields (parsable output, csv):
# ./xfsslower -j 1
ENDTIME_us,TASK,PID,TYPE,BYTES,OFFSET_b,LATENCY_us,FILE
125563830632,randread.pl,12155,R,8192,27824193536,1057,data1
125565050578,randread.pl,12155,R,8192,16908525568,1969,data1
125566331140,randread.pl,12202,R,8192,16310689792,1738,data1
125566427955,randread.pl,12155,R,8192,11127439360,1058,data1
125567223494,randread.pl,12202,R,8192,8422031360,1131,data1
125567331145,randread.pl,12155,R,8192,9233088512,1230,data1
125567331220,randread.pl,12202,R,8192,12716326912,1148,data1
125567334983,randread.pl,12155,R,8192,24545206272,2182,data1
[...]
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:
# ./xfsslower -h
usage: xfsslower [-h] [-j] [-p PID] [min_ms]
Trace common XFS 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:
./xfsslower # trace operations slower than 10 ms (default)
./xfsslower 1 # trace operations slower than 1 ms
./xfsslower -j 1 # ... 1 ms, parsable output (csv)
./xfsslower 0 # trace all operations (warning: verbose)
./xfsslower -p 185 # trace PID 185 only