1Demonstrations of xfsslower, the Linux eBPF/bcc version. 2 3 4xfsslower shows XFS reads, writes, opens, and fsyncs, slower than a threshold. 5For example: 6 7# ./xfsslower 8Tracing XFS operations slower than 10 ms 9TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME 1006:23:06 randread.pl 32497 R 8192 24938024 17.93 data1 1106:23:06 randread.pl 32521 R 8192 13431528 18.27 data1 1206:23:08 randread.pl 32497 R 8192 5070904 16.37 data1 1306:23:08 randread.pl 32521 R 8192 12693016 16.06 data1 1406:23:18 randread.pl 32521 R 8192 27049136 21.68 data1 1506:23:18 randread.pl 32497 R 8192 257864 21.74 data1 1606:23:20 randread.pl 32497 R 8192 17797208 13.37 data1 1706:23:20 randread.pl 32497 R 8192 6088224 19.74 data1 18 19This shows several reads from a "randread.pl" program, each 8 Kbytes in size, 20and from a "data1" file. These all had over 10 ms latency. 21 22This "latency" is measured from when the operation was issued from the VFS 23interface to the file system, to when it completed. This spans everything: 24block device I/O (disk I/O), file system CPU cycles, file system locks, run 25queue latency, etc. This is a better measure of the latency suffered by 26applications reading from the file system than measuring this down at the 27block device interface. 28 29Note that this only traces the common file system operations previously 30listed: other file system operations (eg, inode operations including 31getattr()) are not traced. 32 33 34The threshold can be provided as an argument. Eg, I/O slower than 1 ms: 35 36# ./xfsslower 1 37Tracing XFS operations slower than 1 ms 38TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME 3906:26:59 randread.pl 5394 R 8192 9045728 1.24 data1 4006:26:59 randread.pl 5394 R 8192 23532136 1.17 data1 4106:26:59 randread.pl 5442 R 8192 2192376 2.06 data1 4206:27:00 randread.pl 5394 R 8192 3535176 1.27 data1 4306:27:00 randread.pl 5442 R 8192 21361784 3.18 data1 4406:27:00 randread.pl 5394 R 8192 2556336 3.23 data1 4506:27:00 randread.pl 5394 R 8192 20020880 2.87 data1 4606:27:00 randread.pl 5442 R 8192 20708888 3.32 data1 4706:27:00 randread.pl 5394 R 8192 4654680 2.00 data1 4806:27:00 randread.pl 5442 R 8192 5591744 1.98 data1 4906:27:00 randread.pl 5394 R 8192 2431056 1.22 data1 5006:27:00 randread.pl 5394 R 8192 384288 2.95 data1 5106:27:00 randread.pl 5442 R 8192 29277672 3.07 data1 5206:27:00 randread.pl 5442 R 8192 29508216 3.23 data1 5306:27:00 randread.pl 5394 R 8192 17200008 2.86 data1 5406:27:00 randread.pl 5442 R 8192 20693088 1.06 data1 5506:27:00 randread.pl 5394 R 8192 28124192 1.38 data1 5606:27:00 randread.pl 5442 R 8192 23821184 1.28 data1 5706:27:00 randread.pl 5394 R 8192 1623200 1.47 data1 58[...] 59 60There's now much more output (this spans only 2 seconds, the previous output 61spanned 14 seconds), as the lower threshold is catching more I/O. 62 63 64A threshold of 0 will trace all operations. Warning: the output will be 65verbose, as it will include all file system cache hits. 66 67# ./xfsslower 0 68Tracing XFS operations 69TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME 7006:29:43 ls 9291 O 0 0 0.00 bench 7106:29:47 cat 9361 O 0 0 0.00 date.txt 7206:29:47 cat 9361 R 29 0 0.01 date.txt 7306:29:47 cat 9361 R 0 0 0.00 date.txt 7406:29:50 bash 20500 O 0 0 0.00 bench 7506:29:50 bash 20500 O 0 0 0.00 bench 7606:29:50 bash 20500 O 0 0 0.00 bench 7706:29:50 bash 9431 O 0 0 0.00 bench 7806:29:50 bash 9432 O 0 0 0.00 bench 7906:29:50 bash 9456 O 0 0 0.00 newdate.txt 8006:29:50 date 9456 W 29 0 0.01 newdate.txt 8106:29:53 cksum 9503 O 0 0 0.00 data1 8206:29:53 cksum 9503 R 65536 0 0.06 data1 8306:29:53 cksum 9503 R 65536 64 0.01 data1 8406:29:53 cksum 9503 R 65536 128 0.02 data1 8506:29:53 cksum 9503 R 65536 192 0.01 data1 8606:29:53 cksum 9503 R 65536 256 0.01 data1 8706:29:53 cksum 9503 R 65536 320 0.01 data1 8806:29:53 cksum 9503 R 65536 384 0.01 data1 8906:29:53 cksum 9503 R 65536 448 0.04 data1 9006:29:53 cksum 9503 R 65536 512 0.01 data1 9106:29:53 cksum 9503 R 65536 576 0.02 data1 9206:29:53 cksum 9503 R 65536 640 0.01 data1 9306:29:53 cksum 9503 R 65536 704 0.01 data1 9406:29:53 cksum 9503 R 65536 768 0.01 data1 9506:29:53 cksum 9503 R 65536 832 0.01 data1 9606:29:53 cksum 9503 R 65536 896 0.01 data1 9706:29:53 cksum 9503 R 65536 960 0.01 data1 9806:29:53 cksum 9503 R 65536 1024 0.01 data1 9906:29:53 cksum 9503 R 65536 1088 0.02 data1 10006:29:53 cksum 9503 R 65536 1152 0.01 data1 10106:29:53 cksum 9503 R 65536 1216 0.01 data1 102[...] 103 104The output now includes open operations ("O"), and writes ("W"). A cksum(1) 105command can be seen reading from a data1 file, from progressively increasing 106offsets: a sequential workload. 107 108 109A -j option will print just the fields (parsable output, csv): 110 111# ./xfsslower -j 1 112ENDTIME_us,TASK,PID,TYPE,BYTES,OFFSET_b,LATENCY_us,FILE 113125563830632,randread.pl,12155,R,8192,27824193536,1057,data1 114125565050578,randread.pl,12155,R,8192,16908525568,1969,data1 115125566331140,randread.pl,12202,R,8192,16310689792,1738,data1 116125566427955,randread.pl,12155,R,8192,11127439360,1058,data1 117125567223494,randread.pl,12202,R,8192,8422031360,1131,data1 118125567331145,randread.pl,12155,R,8192,9233088512,1230,data1 119125567331220,randread.pl,12202,R,8192,12716326912,1148,data1 120125567334983,randread.pl,12155,R,8192,24545206272,2182,data1 121[...] 122 123This may be useful for visualizing with another tool, for example, for 124producing a scatter plot of ENDTIME vs LATENCY, to look for time-based 125patterns. 126 127 128USAGE message: 129 130# ./xfsslower -h 131usage: xfsslower [-h] [-j] [-p PID] [min_ms] 132 133Trace common XFS file operations slower than a threshold 134 135positional arguments: 136 min_ms minimum I/O duration to trace, in ms (default 10) 137 138optional arguments: 139 -h, --help show this help message and exit 140 -j, --csv just print fields: comma-separated values 141 -p PID, --pid PID trace this PID only 142 143examples: 144 ./xfsslower # trace operations slower than 10 ms (default) 145 ./xfsslower 1 # trace operations slower than 1 ms 146 ./xfsslower -j 1 # ... 1 ms, parsable output (csv) 147 ./xfsslower 0 # trace all operations (warning: verbose) 148 ./xfsslower -p 185 # trace PID 185 only 149