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