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