From 7d45d18ecba6f1f3fe114fb5e8a7022f2db3da93 Mon Sep 17 00:00:00 2001 From: Costa Shulyupin Date: Sun, 10 Dec 2023 20:50:14 +0200 Subject: [PATCH] biosnoop.bt: use block tracepoints because since v5.17-rc1~116^2~83 functions blk_account_io_start and blk_account_io_done became static and can't be used as kprobes. Using major and minor because unfortunately disk_name is not exported to tracepoints. Tested on linux-6.5 and linux-4.18 --- CHANGELOG.md | 4 ++++ tools/biosnoop.bt | 41 +++++++++++++++++------------------ tools/biosnoop_example.txt | 44 +++++++++++++++++++------------------- 3 files changed, 46 insertions(+), 43 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 942440316909..1e9fe63dd3bc 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -43,6 +43,10 @@ and this project adheres to - [#2790](https://github.com/iovisor/bpftrace/pull/2790) - Update mdflush.bt to use blkdev.h instead of genhd.h for non-BTF builds. - [#2849](https://github.com/iovisor/bpftrace/pull/2849) +- Update biosnoop.bt for kernels >=5.17 and >=4.18 + - [#2875](https://github.com/iovisor/bpftrace/pull/2875) +- biosnoop.bt: replace disk name field with major:minor. + - [#2875](https://github.com/iovisor/bpftrace/pull/2875) ## [0.19.0] 2023-09-19 diff --git a/tools/biosnoop.bt b/tools/biosnoop.bt index 65e302fc6b94..cf12ba087174 100755 --- a/tools/biosnoop.bt +++ b/tools/biosnoop.bt @@ -3,10 +3,11 @@ * biosnoop.bt Block I/O tracing tool, showing per I/O latency. * For Linux, uses bpftrace, eBPF. * - * TODO: switch to block tracepoints. Add offset and size columns. + * TODO: Add offset and size columns. * * This is a bpftrace version of the bcc tool of the same name. * + * 10-Dec-2023 Costa Shulyupin Switched to block tracepoints. * 15-Nov-2017 Brendan Gregg Created this. */ @@ -17,32 +18,31 @@ BEGIN { - printf("%-12s %-7s %-16s %-6s %7s\n", "TIME(ms)", "DISK", "COMM", "PID", "LAT(ms)"); + printf("%-12s %-7s %-16s %-6s %7s\n", "TIME(ms)", "DEVICE", "COMM", "PID", "LAT(ms)"); } -kprobe:blk_account_io_start, -kprobe:__blk_account_io_start +tracepoint:block:block_bio_queue { - @start[arg0] = nsecs; - @iopid[arg0] = pid; - @iocomm[arg0] = comm; - @disk[arg0] = ((struct request *)arg0)->q->disk->disk_name; + @start[args.dev, args.sector] = nsecs; + @iopid[args.dev, args.sector] = pid; + @iocomm[args.dev, args.sector] = comm; } -kprobe:blk_account_io_done, -kprobe:__blk_account_io_done -/@start[arg0] != 0 && @iopid[arg0] != 0 && @iocomm[arg0] != ""/ - +tracepoint:block:block_rq_complete, +tracepoint:block:block_bio_complete +/@start[args.dev, args.sector]/ { - $now = nsecs; - printf("%-12u %-7s %-16s %-6d %7d\n", - elapsed / 1e6, @disk[arg0], @iocomm[arg0], @iopid[arg0], - ($now - @start[arg0]) / 1e6); + printf("%-12u %4d:%-2d %-16s %-6d %7d\n", + elapsed / 1e6, + // like MAJOR(dev), MINOR(dev): + args.dev >> 20, args.dev && 0xfffff, + @iocomm[args.dev, args.sector], + @iopid[args.dev, args.sector], + (nsecs - @start[args.dev, args.sector]) / 1e6); - delete(@start[arg0]); - delete(@iopid[arg0]); - delete(@iocomm[arg0]); - delete(@disk[arg0]); + delete(@start[args.dev, args.sector]); + delete(@iopid[args.dev, args.sector]); + delete(@iocomm[args.dev, args.sector]); } END @@ -50,5 +50,4 @@ END clear(@start); clear(@iopid); clear(@iocomm); - clear(@disk); } diff --git a/tools/biosnoop_example.txt b/tools/biosnoop_example.txt index ab71b24a4339..04fe4e4c7a60 100644 --- a/tools/biosnoop_example.txt +++ b/tools/biosnoop_example.txt @@ -6,25 +6,25 @@ that was on-CPU at the time of queue insert) and the latency of the I/O: # ./biosnoop.bt Attaching 4 probes... -TIME(ms) DISK COMM PID LAT(ms) -611 nvme0n1 bash 4179 10 -611 nvme0n1 cksum 4179 0 -627 nvme0n1 cksum 4179 15 -641 nvme0n1 cksum 4179 13 -644 nvme0n1 cksum 4179 3 -658 nvme0n1 cksum 4179 13 -673 nvme0n1 cksum 4179 14 -686 nvme0n1 cksum 4179 13 -701 nvme0n1 cksum 4179 14 -710 nvme0n1 cksum 4179 8 -717 nvme0n1 cksum 4179 6 -728 nvme0n1 cksum 4179 10 -735 nvme0n1 cksum 4179 6 -751 nvme0n1 cksum 4179 10 -758 nvme0n1 cksum 4179 17 -783 nvme0n1 cksum 4179 12 -796 nvme0n1 cksum 4179 25 -802 nvme0n1 cksum 4179 32 +TIME(ms) DEVICE COMM PID LAT(ms) +611 259:1 bash 4179 10 +611 259:1 cksum 4179 0 +627 259:1 cksum 4179 15 +641 259:1 cksum 4179 13 +644 259:1 cksum 4179 3 +658 259:1 cksum 4179 13 +673 259:1 cksum 4179 14 +686 259:1 cksum 4179 13 +701 259:1 cksum 4179 14 +710 259:1 cksum 4179 8 +717 259:1 cksum 4179 6 +728 259:1 cksum 4179 10 +735 259:1 cksum 4179 6 +751 259:1 cksum 4179 10 +758 259:1 cksum 4179 17 +783 259:1 cksum 4179 12 +796 259:1 cksum 4179 25 +802 259:1 cksum 4179 32 [...] This output shows the cksum process was issuing block I/O, which were @@ -37,9 +37,9 @@ An example of some background flushing: # ./biosnoop.bt Attaching 4 probes... -TIME(ms) DISK COMM PID LAT(ms) -2966 nvme0n1 jbd2/nvme0n1-8 615 0 -2967 nvme0n1 jbd2/nvme0n1-8 615 0 +TIME(ms) DEVICE COMM PID LAT(ms) +2966 259:1 jbd2/nvme0n1-8 615 0 +2967 259:1 jbd2/nvme0n1-8 615 0 [...]