Demonstrations of btrfsslower, the Linux eBPF/bcc version.
btrfsslower shows btrfs reads, writes, opens, and fsyncs, slower than a
threshold. For example:
# ./btrfsslower
Tracing btrfs operations slower than 10 ms
TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME
01:22:03 randread.pl 13602 R 8192 391384 10.40 data1
01:22:03 randread.pl 13602 R 8192 92632 10.41 data1
01:22:06 randread.pl 13602 R 8192 199800 17.33 data1
01:22:06 randread.pl 13602 R 8192 415160 17.21 data1
01:22:07 randread.pl 13602 R 8192 729984 11.93 data1
01:22:09 randread.pl 13602 R 8192 342784 11.90 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:
# ./btrfsslower 1
Tracing btrfs operations slower than 1 ms
TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME
03:26:54 randread.pl 30578 R 8192 214864 1.87 data1
03:26:54 randread.pl 30578 R 8192 267600 1.48 data1
03:26:54 randread.pl 30578 R 8192 704200 1.30 data1
03:26:54 randread.pl 30578 R 8192 492352 3.09 data1
03:26:55 randread.pl 30578 R 8192 319448 1.34 data1
03:26:55 randread.pl 30578 R 8192 676032 1.88 data1
03:26:55 randread.pl 30578 R 8192 646712 2.24 data1
03:26:55 randread.pl 30578 R 8192 124376 1.02 data1
03:26:55 randread.pl 30578 R 8192 223064 2.64 data1
03:26:55 randread.pl 30578 R 8192 521280 1.55 data1
03:26:55 randread.pl 30578 R 8192 272992 2.48 data1
03:26:55 randread.pl 30578 R 8192 450112 2.67 data1
03:26:55 randread.pl 30578 R 8192 361808 1.78 data1
03:26:55 randread.pl 30578 R 8192 41088 1.46 data1
03:26:55 randread.pl 30578 R 8192 756576 1.67 data1
03:26:55 randread.pl 30578 R 8192 711776 2.74 data1
03:26:55 randread.pl 30578 R 8192 129472 1.34 data1
03:26:55 randread.pl 30578 R 8192 526928 1.82 data1
03:26:56 randread.pl 30578 R 8192 312768 1.44 data1
03:26:56 randread.pl 30578 R 8192 34720 1.14 data1
03:26:56 randread.pl 30578 R 8192 258376 1.13 data1
03:26:56 randread.pl 30578 R 8192 308456 1.44 data1
03:26:56 randread.pl 30578 R 8192 759656 1.27 data1
03:26:56 randread.pl 30578 R 8192 387424 3.24 data1
03:26:56 randread.pl 30578 R 8192 168864 3.38 data1
03:26:56 randread.pl 30578 R 8192 699296 1.38 data1
03:26:56 randread.pl 30578 R 8192 405688 2.37 data1
03:26:56 randread.pl 30578 R 8192 559064 1.18 data1
03:26:56 randread.pl 30578 R 8192 264808 1.13 data1
03:26:56 randread.pl 30578 R 8192 369240 2.20 data1
[...]
There's now much more output (this spans less than 3 seconds, the previous output
spanned 6 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.
# ./btrfsslower 0
Tracing btrfs operations
TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME
03:28:17 bash 32597 O 0 0 0.00 date.txt
03:28:17 date 32597 W 29 0 0.02 date.txt
03:28:23 cksum 32743 O 0 0 0.00 date.txt
03:28:23 cksum 32743 R 29 0 0.01 date.txt
03:28:23 cksum 32743 R 0 0 0.00 date.txt
While tracing, the following commands were run in another window:
# date > date.txt
# cksum date.txt
The output of btrfsslower now includes open operations ("O"), and writes ("W").
The first read from cksum(1) returned 29 bytes, and the second returned 0:
causing cksum(1) to stop reading.
A -j option will print just the fields (parsable output, csv):
# ./btrfsslower -j 1
ENDTIME_us,TASK,PID,TYPE,BYTES,OFFSET_b,LATENCY_us,FILE
8930665366,randread.pl,2717,R,8192,230391808,4312,data1
8930670746,randread.pl,2717,R,8192,347832320,1296,data1
8930675995,randread.pl,2717,R,8192,409812992,4207,data1
8930680213,randread.pl,2717,R,8192,498204672,3104,data1
8930685970,randread.pl,2717,R,8192,553164800,1843,data1
8930687568,randread.pl,2717,R,8192,339492864,1475,data1
8930694108,randread.pl,2717,R,8192,500711424,6276,data1
8930697139,randread.pl,2717,R,8192,485801984,2180,data1
8930705755,randread.pl,2717,R,8192,376922112,7535,data1
8930711340,randread.pl,2717,R,8192,380084224,3314,data1
8930740964,randread.pl,2717,R,8192,226091008,24762,data1
8930743169,randread.pl,2717,R,8192,361570304,1809,data1
8930748789,randread.pl,2717,R,8192,346931200,1530,data1
8930763514,randread.pl,2717,R,8192,59719680,13938,data1
8930764870,randread.pl,2717,R,8192,406511616,1313,data1
8930774327,randread.pl,2717,R,8192,661430272,7361,data1
8930780360,randread.pl,2717,R,8192,406904832,2220,data1
8930785736,randread.pl,2717,R,8192,523419648,2005,data1
8930794560,randread.pl,2717,R,8192,342974464,8388,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:
# ./btrfsslower -h
usage: btrfsslower [-h] [-j] [-p PID] [min_ms] [-d DURATION]
Trace common btrfs 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
-d DURATION, --duration DURATION
total duration of trace in seconds
examples:
./btrfsslower # trace operations slower than 10 ms (default)
./btrfsslower 1 # trace operations slower than 1 ms
./btrfsslower -j 1 # ... 1 ms, parsable output (csv)
./btrfsslower 0 # trace all operations (warning: verbose)
./btrfsslower -p 185 # trace PID 185 only
./btrfsslower -d 10 # trace for 10 seconds only