You can not select more than 25 topics
Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.
147 lines
6.5 KiB
147 lines
6.5 KiB
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]
|
|
|
|
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
|
|
|
|
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
|