1Demonstrations of btrfsslower, the Linux eBPF/bcc version. 2 3 4btrfsslower shows btrfs reads, writes, opens, and fsyncs, slower than a 5threshold. For example: 6 7# ./btrfsslower 8Tracing btrfs operations slower than 10 ms 9TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME 1001:22:03 randread.pl 13602 R 8192 391384 10.40 data1 1101:22:03 randread.pl 13602 R 8192 92632 10.41 data1 1201:22:06 randread.pl 13602 R 8192 199800 17.33 data1 1301:22:06 randread.pl 13602 R 8192 415160 17.21 data1 1401:22:07 randread.pl 13602 R 8192 729984 11.93 data1 1501:22:09 randread.pl 13602 R 8192 342784 11.90 data1 16[...] 17 18This shows several reads from a "randread.pl" program, each 8 Kbytes in size, 19and from a "data1" file. These all had over 10 ms latency. 20 21This "latency" is measured from when the operation was issued from the VFS 22interface to the file system, to when it completed. This spans everything: 23block device I/O (disk I/O), file system CPU cycles, file system locks, run 24queue latency, etc. This is a better measure of the latency suffered by 25applications reading from the file system than measuring this down at the 26block device interface. 27 28Note that this only traces the common file system operations previously 29listed: other file system operations (eg, inode operations including 30getattr()) are not traced. 31 32 33The threshold can be provided as an argument. Eg, I/O slower than 1 ms: 34 35# ./btrfsslower 1 36Tracing btrfs operations slower than 1 ms 37TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME 3803:26:54 randread.pl 30578 R 8192 214864 1.87 data1 3903:26:54 randread.pl 30578 R 8192 267600 1.48 data1 4003:26:54 randread.pl 30578 R 8192 704200 1.30 data1 4103:26:54 randread.pl 30578 R 8192 492352 3.09 data1 4203:26:55 randread.pl 30578 R 8192 319448 1.34 data1 4303:26:55 randread.pl 30578 R 8192 676032 1.88 data1 4403:26:55 randread.pl 30578 R 8192 646712 2.24 data1 4503:26:55 randread.pl 30578 R 8192 124376 1.02 data1 4603:26:55 randread.pl 30578 R 8192 223064 2.64 data1 4703:26:55 randread.pl 30578 R 8192 521280 1.55 data1 4803:26:55 randread.pl 30578 R 8192 272992 2.48 data1 4903:26:55 randread.pl 30578 R 8192 450112 2.67 data1 5003:26:55 randread.pl 30578 R 8192 361808 1.78 data1 5103:26:55 randread.pl 30578 R 8192 41088 1.46 data1 5203:26:55 randread.pl 30578 R 8192 756576 1.67 data1 5303:26:55 randread.pl 30578 R 8192 711776 2.74 data1 5403:26:55 randread.pl 30578 R 8192 129472 1.34 data1 5503:26:55 randread.pl 30578 R 8192 526928 1.82 data1 5603:26:56 randread.pl 30578 R 8192 312768 1.44 data1 5703:26:56 randread.pl 30578 R 8192 34720 1.14 data1 5803:26:56 randread.pl 30578 R 8192 258376 1.13 data1 5903:26:56 randread.pl 30578 R 8192 308456 1.44 data1 6003:26:56 randread.pl 30578 R 8192 759656 1.27 data1 6103:26:56 randread.pl 30578 R 8192 387424 3.24 data1 6203:26:56 randread.pl 30578 R 8192 168864 3.38 data1 6303:26:56 randread.pl 30578 R 8192 699296 1.38 data1 6403:26:56 randread.pl 30578 R 8192 405688 2.37 data1 6503:26:56 randread.pl 30578 R 8192 559064 1.18 data1 6603:26:56 randread.pl 30578 R 8192 264808 1.13 data1 6703:26:56 randread.pl 30578 R 8192 369240 2.20 data1 68[...] 69 70There's now much more output (this spans less than 3 seconds, the previous output 71spanned 6 seconds), as the lower threshold is catching more I/O. 72 73 74A threshold of 0 will trace all operations. Warning: the output will be 75verbose, as it will include all file system cache hits. 76 77# ./btrfsslower 0 78Tracing btrfs operations 79TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME 8003:28:17 bash 32597 O 0 0 0.00 date.txt 8103:28:17 date 32597 W 29 0 0.02 date.txt 8203:28:23 cksum 32743 O 0 0 0.00 date.txt 8303:28:23 cksum 32743 R 29 0 0.01 date.txt 8403:28:23 cksum 32743 R 0 0 0.00 date.txt 85 86While tracing, the following commands were run in another window: 87 88# date > date.txt 89# cksum date.txt 90 91The output of btrfsslower now includes open operations ("O"), and writes ("W"). 92The first read from cksum(1) returned 29 bytes, and the second returned 0: 93causing cksum(1) to stop reading. 94 95 96A -j option will print just the fields (parsable output, csv): 97 98# ./btrfsslower -j 1 99ENDTIME_us,TASK,PID,TYPE,BYTES,OFFSET_b,LATENCY_us,FILE 1008930665366,randread.pl,2717,R,8192,230391808,4312,data1 1018930670746,randread.pl,2717,R,8192,347832320,1296,data1 1028930675995,randread.pl,2717,R,8192,409812992,4207,data1 1038930680213,randread.pl,2717,R,8192,498204672,3104,data1 1048930685970,randread.pl,2717,R,8192,553164800,1843,data1 1058930687568,randread.pl,2717,R,8192,339492864,1475,data1 1068930694108,randread.pl,2717,R,8192,500711424,6276,data1 1078930697139,randread.pl,2717,R,8192,485801984,2180,data1 1088930705755,randread.pl,2717,R,8192,376922112,7535,data1 1098930711340,randread.pl,2717,R,8192,380084224,3314,data1 1108930740964,randread.pl,2717,R,8192,226091008,24762,data1 1118930743169,randread.pl,2717,R,8192,361570304,1809,data1 1128930748789,randread.pl,2717,R,8192,346931200,1530,data1 1138930763514,randread.pl,2717,R,8192,59719680,13938,data1 1148930764870,randread.pl,2717,R,8192,406511616,1313,data1 1158930774327,randread.pl,2717,R,8192,661430272,7361,data1 1168930780360,randread.pl,2717,R,8192,406904832,2220,data1 1178930785736,randread.pl,2717,R,8192,523419648,2005,data1 1188930794560,randread.pl,2717,R,8192,342974464,8388,data1 119[...] 120 121This may be useful for visualizing with another tool, for example, for 122producing a scatter plot of ENDTIME vs LATENCY, to look for time-based 123patterns. 124 125 126USAGE message: 127 128# ./btrfsslower -h 129usage: btrfsslower [-h] [-j] [-p PID] [min_ms] 130 131Trace common btrfs file operations slower than a threshold 132 133positional arguments: 134 min_ms minimum I/O duration to trace, in ms (default 10) 135 136optional arguments: 137 -h, --help show this help message and exit 138 -j, --csv just print fields: comma-separated values 139 -p PID, --pid PID trace this PID only 140 141examples: 142 ./btrfsslower # trace operations slower than 10 ms (default) 143 ./btrfsslower 1 # trace operations slower than 1 ms 144 ./btrfsslower -j 1 # ... 1 ms, parsable output (csv) 145 ./btrfsslower 0 # trace all operations (warning: verbose) 146 ./btrfsslower -p 185 # trace PID 185 only 147