1Demonstrations of biosnoop, the Linux eBPF/bcc version. 2 3 4biosnoop traces block device I/O (disk I/O), and prints a line of output 5per I/O. Example: 6 7# ./biosnoop 8TIME(s) COMM PID DISK T SECTOR BYTES LAT(ms) 90.000004 supervise 1950 xvda1 W 13092560 4096 0.74 100.000178 supervise 1950 xvda1 W 13092432 4096 0.61 110.001469 supervise 1956 xvda1 W 13092440 4096 1.24 120.001588 supervise 1956 xvda1 W 13115128 4096 1.09 131.022346 supervise 1950 xvda1 W 13115272 4096 0.98 141.022568 supervise 1950 xvda1 W 13188496 4096 0.93 151.023534 supervise 1956 xvda1 W 13188520 4096 0.79 161.023585 supervise 1956 xvda1 W 13189512 4096 0.60 172.003920 xfsaild/md0 456 xvdc W 62901512 8192 0.23 182.003931 xfsaild/md0 456 xvdb W 62901513 512 0.25 192.004034 xfsaild/md0 456 xvdb W 62901520 8192 0.35 202.004042 xfsaild/md0 456 xvdb W 63542016 4096 0.36 212.004204 kworker/0:3 26040 xvdb W 41950344 65536 0.34 222.044352 supervise 1950 xvda1 W 13192672 4096 0.65 232.044574 supervise 1950 xvda1 W 13189072 4096 0.58 24 25This includes the PID and comm (process name) that were on-CPU at the time of 26issue (which usually means the process responsible). 27 28The latency of the disk I/O, measured from the issue to the device to its 29completion, is included as the last column. 30 31This example output is from what should be an idle system, however, the 32following is visible in iostat: 33 34$ iostat -x 1 35[...] 36avg-cpu: %user %nice %system %iowait %steal %idle 37 0.12 0.00 0.12 0.00 0.00 99.75 38 39Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s await svctm %util 40xvda 0.00 0.00 0.00 4.00 0.00 16.00 0.00 0.00 0.00 41xvdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 42xvdc 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 43md0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 44 45There are 4 write IOPS. 46 47The output of biosnoop identifies the reason: multiple supervise processes are 48issuing writes to the xvda1 disk. I can now drill down on supervise using other 49tools to understand its file system workload. 50 51 52The -Q option includes a column to show the time spent queued in the OS: 53 54# biosnoop.py -Q 55TIME(s) COMM PID DISK T SECTOR BYTES QUE(ms) LAT(ms) 560.000000 kworker/u72:1 13379 nvme1n1 W 1142400 4096 0.01 0.55 570.000771 sync 22177 nvme1n1 W 41963894 3072 0.11 0.47 585.332998 xfsaild/nvme1n 1061 nvme1n1 W 545728 16384 0.01 0.61 595.333044 xfsaild/nvme1n 1061 nvme1n1 W 2349728 16384 0.02 0.64 605.333065 xfsaild/nvme1n 1061 nvme1n1 W 20971521 512 0.02 0.65 615.333067 xfsaild/nvme1n 1061 nvme1n1 W 20971528 8192 0.00 0.65 62[...] 63 64 65USAGE message: 66 67usage: biosnoop.py [-h] [-Q] [-d DISK] [-P] 68 69Trace block I/O 70 71optional arguments: 72 -h, --help show this help message and exit 73 -Q, --queue include OS queued time 74 -d DISK, --disk DISK trace this disk only 75 -P, --pattern display block I/O pattern (sequential or random) 76 77examples: 78 ./biosnoop # trace all block I/O 79 ./biosnoop -Q # include OS queued time 80 ./biosnoop -d sdc # trace sdc only 81 ./biosnoop -P # display block I/O pattern 82