Gitiles
Code Review Sign In
gerrit-public.fairphone.software / platform / external / bcc / refs/tags/rel/13/fp3/6.A.018.0 / . / tools / biolatency_example.txt
blob: a88136b8a65595313e720a6dd5d0987869271fd2 [file] [log] [blame]
Brendan Gregg9fa15622015-09-21 15:51:11 -0700[diff] [blame]1Demonstrations of biolatency, the Linux eBPF/bcc version.
2
3
4biolatency traces block device I/O (disk I/O), and records the distribution
5of I/O latency (time), printing this as a histogram when Ctrl-C is hit.
6For example:
7
Alexei Starovoitovbdf07732016-01-14 10:09:20 -0800[diff] [blame]8# ./biolatency
Brendan Gregg9fa15622015-09-21 15:51:11 -0700[diff] [blame]9Tracing block device I/O... Hit Ctrl-C to end.
10^C
11 usecs : count distribution
12 0 -> 1 : 0 | |
13 2 -> 3 : 0 | |
14 4 -> 7 : 0 | |
15 8 -> 15 : 0 | |
16 16 -> 31 : 0 | |
17 32 -> 63 : 0 | |
18 64 -> 127 : 1 | |
19 128 -> 255 : 12 |******** |
20 256 -> 511 : 15 |********** |
21 512 -> 1023 : 43 |******************************* |
22 1024 -> 2047 : 52 |**************************************|
23 2048 -> 4095 : 47 |********************************** |
24 4096 -> 8191 : 52 |**************************************|
25 8192 -> 16383 : 36 |************************** |
26 16384 -> 32767 : 15 |********** |
27 32768 -> 65535 : 2 |* |
28 65536 -> 131071 : 2 |* |
29
30The latency of the disk I/O is measured from the issue to the device to its
31completion. A -Q option can be used to include time queued in the kernel.
32
33This example output shows a large mode of latency from about 128 microseconds
34to about 32767 microseconds (33 milliseconds). The bulk of the I/O was
35between 1 and 8 ms, which is the expected block device latency for
36rotational storage devices.
37
38The highest latency seen while tracing was between 65 and 131 milliseconds:
39the last row printed, for which there were 2 I/O.
40
41For efficiency, biolatency uses an in-kernel eBPF map to store timestamps
42with requests, and another in-kernel map to store the histogram (the "count")
43column, which is copied to user-space only when output is printed. These
Alex Bagehot3b9679a2016-02-06 16:01:02 +0000[diff] [blame]44methods lower the performance overhead when tracing is performed.
Brendan Gregg9fa15622015-09-21 15:51:11 -0700[diff] [blame]45
46
47In the following example, the -m option is used to print a histogram using
48milliseconds as the units (which eliminates the first several rows), -T to
49print timestamps with the output, and to print 1 second summaries 5 times:
50
51# ./biolatency -mT 1 5
52Tracing block device I/O... Hit Ctrl-C to end.
53
5406:20:16
55 msecs : count distribution
56 0 -> 1 : 36 |**************************************|
57 2 -> 3 : 1 |* |
58 4 -> 7 : 3 |*** |
59 8 -> 15 : 17 |***************** |
60 16 -> 31 : 33 |********************************** |
61 32 -> 63 : 7 |******* |
62 64 -> 127 : 6 |****** |
63
6406:20:17
65 msecs : count distribution
66 0 -> 1 : 96 |************************************ |
67 2 -> 3 : 25 |********* |
68 4 -> 7 : 29 |*********** |
69 8 -> 15 : 62 |*********************** |
70 16 -> 31 : 100 |**************************************|
71 32 -> 63 : 62 |*********************** |
72 64 -> 127 : 18 |****** |
73
7406:20:18
75 msecs : count distribution
76 0 -> 1 : 68 |************************* |
77 2 -> 3 : 76 |**************************** |
78 4 -> 7 : 20 |******* |
79 8 -> 15 : 48 |***************** |
80 16 -> 31 : 103 |**************************************|
81 32 -> 63 : 49 |****************** |
82 64 -> 127 : 17 |****** |
83
8406:20:19
85 msecs : count distribution
86 0 -> 1 : 522 |*************************************+|
87 2 -> 3 : 225 |**************** |
88 4 -> 7 : 38 |** |
89 8 -> 15 : 8 | |
90 16 -> 31 : 1 | |
91
9206:20:20
93 msecs : count distribution
94 0 -> 1 : 436 |**************************************|
95 2 -> 3 : 106 |********* |
96 4 -> 7 : 34 |** |
97 8 -> 15 : 19 |* |
98 16 -> 31 : 1 | |
99
100How the I/O latency distribution changes over time can be seen.
101
102
103
104The -Q option begins measuring I/O latency from when the request was first
105queued in the kernel, and includes queuing latency:
106
107# ./biolatency -Q
108Tracing block device I/O... Hit Ctrl-C to end.
109^C
110 usecs : count distribution
111 0 -> 1 : 0 | |
112 2 -> 3 : 0 | |
113 4 -> 7 : 0 | |
114 8 -> 15 : 0 | |
115 16 -> 31 : 0 | |
116 32 -> 63 : 0 | |
117 64 -> 127 : 0 | |
118 128 -> 255 : 3 |* |
119 256 -> 511 : 37 |************** |
120 512 -> 1023 : 30 |*********** |
121 1024 -> 2047 : 18 |******* |
122 2048 -> 4095 : 22 |******** |
123 4096 -> 8191 : 14 |***** |
124 8192 -> 16383 : 48 |******************* |
125 16384 -> 32767 : 96 |**************************************|
126 32768 -> 65535 : 31 |************ |
127 65536 -> 131071 : 26 |********** |
128 131072 -> 262143 : 12 |**** |
129
130This better reflects the latency suffered by the application (if it is
131synchronous I/O), whereas the default mode without kernel queueing better
132reflects the performance of the device.
133
134Note that the storage device (and storage device controller) usually have
135queues of their own, which are always included in the latency, with or
136without -Q.
137
138
Brendan Gregg44e68772015-09-25 13:20:16 -0700[diff] [blame]139The -D option will print a histogram per disk. Eg:
140
141# ./biolatency -D
142Tracing block device I/O... Hit Ctrl-C to end.
143^C
144
145Bucket disk = 'xvdb'
146 usecs : count distribution
147 0 -> 1 : 0 | |
148 2 -> 3 : 0 | |
149 4 -> 7 : 0 | |
150 8 -> 15 : 0 | |
151 16 -> 31 : 0 | |
152 32 -> 63 : 0 | |
153 64 -> 127 : 0 | |
154 128 -> 255 : 1 | |
155 256 -> 511 : 33 |********************** |
156 512 -> 1023 : 36 |************************ |
157 1024 -> 2047 : 58 |****************************************|
158 2048 -> 4095 : 51 |*********************************** |
159 4096 -> 8191 : 21 |************** |
160 8192 -> 16383 : 2 |* |
161
162Bucket disk = 'xvdc'
163 usecs : count distribution
164 0 -> 1 : 0 | |
165 2 -> 3 : 0 | |
166 4 -> 7 : 0 | |
167 8 -> 15 : 0 | |
168 16 -> 31 : 0 | |
169 32 -> 63 : 0 | |
170 64 -> 127 : 0 | |
171 128 -> 255 : 1 | |
172 256 -> 511 : 38 |*********************** |
173 512 -> 1023 : 42 |************************* |
174 1024 -> 2047 : 66 |****************************************|
175 2048 -> 4095 : 40 |************************ |
176 4096 -> 8191 : 14 |******** |
177
178Bucket disk = 'xvda1'
179 usecs : count distribution
180 0 -> 1 : 0 | |
181 2 -> 3 : 0 | |
182 4 -> 7 : 0 | |
183 8 -> 15 : 0 | |
184 16 -> 31 : 0 | |
185 32 -> 63 : 0 | |
186 64 -> 127 : 0 | |
187 128 -> 255 : 0 | |
188 256 -> 511 : 18 |********** |
189 512 -> 1023 : 67 |************************************* |
190 1024 -> 2047 : 35 |******************* |
191 2048 -> 4095 : 71 |****************************************|
192 4096 -> 8191 : 65 |************************************ |
193 8192 -> 16383 : 65 |************************************ |
194 16384 -> 32767 : 20 |*********** |
195 32768 -> 65535 : 7 |*** |
196
197This output sows that xvda1 has much higher latency, usually between 0.5 ms
198and 32 ms, whereas xvdc is usually between 0.2 ms and 4 ms.
199
200
Brendan Greggc6cded42019-03-20 09:32:20 -0700[diff] [blame]201The -F option prints a separate histogram for each unique set of request
202flags. For example:
203
204./biolatency.py -Fm
205Tracing block device I/O... Hit Ctrl-C to end.
206^C
207
208flags = Read
209 msecs : count distribution
210 0 -> 1 : 180 |************* |
211 2 -> 3 : 519 |****************************************|
212 4 -> 7 : 60 |**** |
213 8 -> 15 : 123 |********* |
214 16 -> 31 : 68 |***** |
215 32 -> 63 : 0 | |
216 64 -> 127 : 2 | |
217 128 -> 255 : 12 | |
218 256 -> 511 : 0 | |
219 512 -> 1023 : 1 | |
220
221flags = Sync-Write
222 msecs : count distribution
223 0 -> 1 : 5 |****************************************|
224
225flags = Flush
226 msecs : count distribution
227 0 -> 1 : 2 |****************************************|
228
229flags = Metadata-Read
230 msecs : count distribution
231 0 -> 1 : 3 |****************************************|
232 2 -> 3 : 2 |************************** |
233 4 -> 7 : 0 | |
234 8 -> 15 : 1 |************* |
235 16 -> 31 : 1 |************* |
236
237flags = Write
238 msecs : count distribution
239 0 -> 1 : 103 |******************************* |
240 2 -> 3 : 106 |******************************** |
241 4 -> 7 : 130 |****************************************|
242 8 -> 15 : 79 |************************ |
243 16 -> 31 : 5 |* |
244 32 -> 63 : 0 | |
245 64 -> 127 : 0 | |
246 128 -> 255 : 0 | |
247 256 -> 511 : 1 | |
248
249flags = NoMerge-Read
250 msecs : count distribution
251 0 -> 1 : 0 | |
252 2 -> 3 : 5 |****************************************|
253 4 -> 7 : 0 | |
254 8 -> 15 : 0 | |
255 16 -> 31 : 1 |******** |
256
257flags = NoMerge-Write
258 msecs : count distribution
259 0 -> 1 : 30 |** |
260 2 -> 3 : 293 |******************** |
261 4 -> 7 : 564 |****************************************|
262 8 -> 15 : 463 |******************************** |
263 16 -> 31 : 21 |* |
264 32 -> 63 : 0 | |
265 64 -> 127 : 0 | |
266 128 -> 255 : 0 | |
267 256 -> 511 : 5 | |
268
269flags = Priority-Metadata-Read
270 msecs : count distribution
271 0 -> 1 : 1 |****************************************|
272 2 -> 3 : 0 | |
273 4 -> 7 : 1 |****************************************|
274 8 -> 15 : 1 |****************************************|
275
276flags = ForcedUnitAccess-Metadata-Sync-Write
277 msecs : count distribution
278 0 -> 1 : 2 |****************************************|
279
280flags = ReadAhead-Read
281 msecs : count distribution
282 0 -> 1 : 15 |*************************** |
283 2 -> 3 : 22 |****************************************|
284 4 -> 7 : 14 |************************* |
285 8 -> 15 : 8 |************** |
286 16 -> 31 : 1 |* |
287
288flags = Priority-Metadata-Write
289 msecs : count distribution
290 0 -> 1 : 9 |****************************************|
291
292These can be handled differently by the storage device, and this mode lets us
293examine their performance in isolation.
294
edwardwuf41f3782021-04-28 18:22:48 +0800[diff] [blame]295
296The -e option shows extension summary(total, average)
297For example:
298# ./biolatency.py -e
299^C
300 usecs : count distribution
301 0 -> 1 : 0 | |
302 2 -> 3 : 0 | |
303 4 -> 7 : 0 | |
304 8 -> 15 : 0 | |
305 16 -> 31 : 0 | |
306 32 -> 63 : 0 | |
307 64 -> 127 : 4 |*********** |
308 128 -> 255 : 2 |***** |
309 256 -> 511 : 4 |*********** |
310 512 -> 1023 : 14 |****************************************|
311 1024 -> 2047 : 0 | |
312 2048 -> 4095 : 1 |** |
313
314avg = 663 usecs, total: 16575 usecs, count: 25
315
316Sometimes 512 -> 1023 usecs is not enough for throughput tuning.
317Especially a little difference in performance downgrade.
318By this extension, we know the value in log2 range is about 663 usecs.
319
320
Omkar Desaiaec53a82020-12-31 11:30:31 -0500[diff] [blame]321The -j option prints a dictionary of the histogram.
322For example:
323
324# ./biolatency.py -j
325^C
326{'ts': '2020-12-30 14:33:03', 'val_type': 'usecs', 'data': [{'interval-start': 0, 'interval-end': 1, 'count': 0}, {'interval-start': 2, 'interval-end': 3, 'count': 0}, {'interval-start': 4, 'interval-end': 7, 'count': 0}, {'interval-start': 8, 'interval-end': 15, 'count': 0}, {'interval-start': 16, 'interval-end': 31, 'count': 0}, {'interval-start': 32, 'interval-end': 63, 'count': 2}, {'interval-start': 64, 'interval-end': 127, 'count': 75}, {'interval-start': 128, 'interval-end': 255, 'count': 7}, {'interval-start': 256, 'interval-end': 511, 'count': 0}, {'interval-start': 512, 'interval-end': 1023, 'count': 6}, {'interval-start': 1024, 'interval-end': 2047, 'count': 3}, {'interval-start': 2048, 'interval-end': 4095, 'count': 31}]}
327
328the key `data` is the list of the log2 histogram intervals. The `interval-start` and `interval-end` define the
329latency bucket and `count` is the number of I/O's that lie in that latency range.
330
331# ./biolatency.py -jF
332^C
333{'ts': '2020-12-30 14:37:59', 'val_type': 'usecs', 'data': [{'interval-start': 0, 'interval-end': 1, 'count': 0}, {'interval-start': 2, 'interval-end': 3, 'count': 0}, {'interval-start': 4, 'interval-end': 7, 'count': 0}, {'interval-start': 8, 'interval-end': 15, 'count': 0}, {'interval-start': 16, 'interval-end': 31, 'count': 1}, {'interval-start': 32, 'interval-end': 63, 'count': 1}, {'interval-start': 64, 'interval-end': 127, 'count': 0}, {'interval-start': 128, 'interval-end': 255, 'count': 0}, {'interval-start': 256, 'interval-end': 511, 'count': 0}, {'interval-start': 512, 'interval-end': 1023, 'count': 0}, {'interval-start': 1024, 'interval-end': 2047, 'count': 2}], 'flags': 'Sync-Write'}
334{'ts': '2020-12-30 14:37:59', 'val_type': 'usecs', 'data': [{'interval-start': 0, 'interval-end': 1, 'count': 0}, {'interval-start': 2, 'interval-end': 3, 'count': 0}, {'interval-start': 4, 'interval-end': 7, 'count': 0}, {'interval-start': 8, 'interval-end': 15, 'count': 0}, {'interval-start': 16, 'interval-end': 31, 'count': 0}, {'interval-start': 32, 'interval-end': 63, 'count': 0}, {'interval-start': 64, 'interval-end': 127, 'count': 0}, {'interval-start': 128, 'interval-end': 255, 'count': 2}, {'interval-start': 256, 'interval-end': 511, 'count': 0}, {'interval-start': 512, 'interval-end': 1023, 'count': 2}, {'interval-start': 1024, 'interval-end': 2047, 'count': 1}], 'flags': 'Unknown'}
335{'ts': '2020-12-30 14:37:59', 'val_type': 'usecs', 'data': [{'interval-start': 0, 'interval-end': 1, 'count': 0}, {'interval-start': 2, 'interval-end': 3, 'count': 0}, {'interval-start': 4, 'interval-end': 7, 'count': 0}, {'interval-start': 8, 'interval-end': 15, 'count': 0}, {'interval-start': 16, 'interval-end': 31, 'count': 0}, {'interval-start': 32, 'interval-end': 63, 'count': 0}, {'interval-start': 64, 'interval-end': 127, 'count': 0}, {'interval-start': 128, 'interval-end': 255, 'count': 0}, {'interval-start': 256, 'interval-end': 511, 'count': 0}, {'interval-start': 512, 'interval-end': 1023, 'count': 0}, {'interval-start': 1024, 'interval-end': 2047, 'count': 1}], 'flags': 'Write'}
336{'ts': '2020-12-30 14:37:59', 'val_type': 'usecs', 'data': [{'interval-start': 0, 'interval-end': 1, 'count': 0}, {'interval-start': 2, 'interval-end': 3, 'count': 0}, {'interval-start': 4, 'interval-end': 7, 'count': 0}, {'interval-start': 8, 'interval-end': 15, 'count': 0}, {'interval-start': 16, 'interval-end': 31, 'count': 0}, {'interval-start': 32, 'interval-end': 63, 'count': 0}, {'interval-start': 64, 'interval-end': 127, 'count': 0}, {'interval-start': 128, 'interval-end': 255, 'count': 0}, {'interval-start': 256, 'interval-end': 511, 'count': 0}, {'interval-start': 512, 'interval-end': 1023, 'count': 4}], 'flags': 'Flush'}
337
338The -j option used with -F prints a histogram dictionary per set of I/O flags.
339
340# ./biolatency.py -jD
341^C
342{'ts': '2020-12-30 14:40:00', 'val_type': 'usecs', 'data': [{'interval-start': 0, 'interval-end': 1, 'count': 0}, {'interval-start': 2, 'interval-end': 3, 'count': 0}, {'interval-start': 4, 'interval-end': 7, 'count': 0}, {'interval-start': 8, 'interval-end': 15, 'count': 0}, {'interval-start': 16, 'interval-end': 31, 'count': 0}, {'interval-start': 32, 'interval-end': 63, 'count': 1}, {'interval-start': 64, 'interval-end': 127, 'count': 1}, {'interval-start': 128, 'interval-end': 255, 'count': 1}, {'interval-start': 256, 'interval-end': 511, 'count': 1}, {'interval-start': 512, 'interval-end': 1023, 'count': 6}, {'interval-start': 1024, 'interval-end': 2047, 'count': 1}, {'interval-start': 2048, 'interval-end': 4095, 'count': 3}], 'Bucket ptr': b'sda'}
343
344The -j option used with -D prints a histogram dictionary per disk device.
345
346# ./biolatency.py -jm
347^C
348{'ts': '2020-12-30 14:42:03', 'val_type': 'msecs', 'data': [{'interval-start': 0, 'interval-end': 1, 'count': 11}, {'interval-start': 2, 'interval-end': 3, 'count': 3}]}
349
350The -j with -m prints a millisecond histogram dictionary. The `value_type` key is set to msecs.
Brendan Greggc6cded42019-03-20 09:32:20 -0700[diff] [blame]351
Brendan Gregg9fa15622015-09-21 15:51:11 -0700[diff] [blame]352USAGE message:
353
354# ./biolatency -h
Omkar Desaiaec53a82020-12-31 11:30:31 -0500[diff] [blame]355usage: biolatency.py [-h] [-T] [-Q] [-m] [-D] [-F] [-j]
356 [interval] [count]
Brendan Gregg9fa15622015-09-21 15:51:11 -0700[diff] [blame]357
358Summarize block device I/O latency as a histogram
359
360positional arguments:
361 interval output interval, in seconds
362 count number of outputs
363
364optional arguments:
365 -h, --help show this help message and exit
366 -T, --timestamp include timestamp on output
367 -Q, --queued include OS queued time in I/O time
368 -m, --milliseconds millisecond histogram
Brendan Gregg44e68772015-09-25 13:20:16 -0700[diff] [blame]369 -D, --disks print a histogram per disk device
Brendan Greggc6cded42019-03-20 09:32:20 -0700[diff] [blame]370 -F, --flags print a histogram per set of I/O flags
edwardwuf41f3782021-04-28 18:22:48 +0800[diff] [blame]371 -e, --extension also show extension summary(total, average)
Omkar Desaiaec53a82020-12-31 11:30:31 -0500[diff] [blame]372 -j, --json json output
Brendan Gregg9fa15622015-09-21 15:51:11 -0700[diff] [blame]373
374examples:
Omkar Desaiaec53a82020-12-31 11:30:31 -0500[diff] [blame]375 ./biolatency # summarize block I/O latency as a histogram
376 ./biolatency 1 10 # print 1 second summaries, 10 times
377 ./biolatency -mT 1 # 1s summaries, milliseconds, and timestamps
378 ./biolatency -Q # include OS queued time in I/O time
379 ./biolatency -D # show each disk device separately
380 ./biolatency -F # show I/O flags separately
381 ./biolatency -j # print a dictionary
edwardwuf41f3782021-04-28 18:22:48 +0800[diff] [blame]382 ./biolatency -e # show extension summary(total, average)