blob: ccb9369ddb9d9b51bceb57f54116279ba7d8aa8a [file] [log] [blame]
Brendan Greggee74c372016-02-15 22:22:19 -08001Demonstrations 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