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