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