Skip to content

Commit

Permalink
biosnoop.bt: use block tracepoints
Browse files Browse the repository at this point in the history 
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
  • Loading branch information
@makelinux
makelinux committed Dec 11, 2023
1 parent 532d4e9 commit 7d45d18
Show file tree
Hide file tree
Showing 3 changed files with 46 additions and 43 deletions.
4 changes: 4 additions & 0 deletions CHANGELOG.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
41 changes: 20 additions & 21 deletions tools/biosnoop.bt
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*/

Expand All @@ -17,38 +18,36 @@

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
{
clear(@start);
clear(@iopid);
clear(@iocomm);
clear(@disk);
}
44 changes: 22 additions & 22 deletions tools/biosnoop_example.txt
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
[...]


Expand Down

0 comments on commit 7d45d18

Please sign in to comment.