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 8# ./biolatency 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 44methods lower the performance overhead when tracing is performed. 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 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 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 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 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. 351 352USAGE message: 353 354# ./biolatency -h 355usage: biolatency.py [-h] [-T] [-Q] [-m] [-D] [-F] [-j] 356 [interval] [count] 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 369 -D, --disks print a histogram per disk device 370 -F, --flags print a histogram per set of I/O flags 371 -e, --extension also show extension summary(total, average) 372 -j, --json json output 373 374examples: 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 382 ./biolatency -e # show extension summary(total, average) 383