diff mbox series

[v2] btrfs: add trace events for bio split at storage layer

Message ID ea5134ee9965fbfe870b4fb62054de92adb94ced.1687152779.git.wqu@suse.com (mailing list archive)
State New, archived
Headers show
Series [v2] btrfs: add trace events for bio split at storage layer | expand

Commit Message

Qu Wenruo June 19, 2023, 5:33 a.m. UTC 
[BACKGROUND]
David recently reported some weird RAID56 errors where huge btrfs bio
(tens of MiBs) is directly passed to RAID56 path, without proper bio
split.

To my surprise, there is no trace events around the bio split code of
storage layer.

[NEW TRACE EVENTS]
This patch would add 3 new trace events:

- trace_initial_bbio()
- trace_before_split_bbio()
- trace_after_split_bbio()

The example output would look like the following (headers and uuid
removed):

   initial_bbio: root=5(FS_TREE) ino=257 logical=389152768 length=524288 opf=0x1 mirror_num=0 map_length=-1
   before_split_bbio: root=5(FS_TREE) ino=257 logical=389152768 length=524288 opf=0x1 mirror_num=0 map_length=131072
   after_split_bbio: root=5(FS_TREE) ino=257 logical=389152768 length=131072 opf=0x1 mirror_num=0 map_length=131072
   before_split_bbio: root=5(FS_TREE) ino=257 logical=389283840 length=393216 opf=0x1 mirror_num=0 map_length=131072
   after_split_bbio: root=5(FS_TREE) ino=257 logical=389283840 length=131072 opf=0x1 mirror_num=0 map_length=131072
   before_split_bbio: root=5(FS_TREE) ino=257 logical=389414912 length=262144 opf=0x1 mirror_num=0 map_length=131072
   after_split_bbio: root=5(FS_TREE) ino=257 logical=389414912 length=131072 opf=0x1 mirror_num=0 map_length=131072
   before_split_bbio: root=5(FS_TREE) ino=257 logical=389545984 length=131072 opf=0x1 mirror_num=0 map_length=131072
   initial_bbio: root=1(ROOT_TREE) ino=1 logical=30441472 length=16384 opf=0x1 mirror_num=0 map_length=-1

The above lines show a 512K bbio submitted, then it got split by each
128K boundary (this is a 3 disks RAID5).

   initial_bbio: root=1(ROOT_TREE) ino=1 logical=30441472 length=16384 opf=0x1 mirror_num=0 map_length=-1
   before_split_bbio: root=1(ROOT_TREE) ino=1 logical=30441472 length=16384 opf=0x1 mirror_num=0 map_length=16384

And the above lines are metadata writes which didn't need to be split at
all.

These new events should allow us to debug bio split related problems
easier.

Reviewed-by: Naohiro Aota <naohiro.aota@wdc.com>
Signed-off-by: Qu Wenruo <wqu@suse.com>
---
Changelog:
v2:
- Use show_root_type() for root objectid
---
 fs/btrfs/bio.c               |  4 +++
 include/trace/events/btrfs.h | 51 ++++++++++++++++++++++++++++++++++++
 2 files changed, 55 insertions(+)

Comments

Johannes Thumshirn June 19, 2023, 7:53 a.m. UTC | #1 
Oh this one is really handy, Thanks!

Looks good,
Reviewed-by: Johannes Thumshirn <johannes.thumshirn@wdc.com>
David Sterba June 19, 2023, 4:53 p.m. UTC | #2 
On Mon, Jun 19, 2023 at 01:33:39PM +0800, Qu Wenruo wrote:
> [BACKGROUND]
> David recently reported some weird RAID56 errors where huge btrfs bio
> (tens of MiBs) is directly passed to RAID56 path, without proper bio
> split.
> 
> To my surprise, there is no trace events around the bio split code of
> storage layer.
> 
> [NEW TRACE EVENTS]
> This patch would add 3 new trace events:
> 
> - trace_initial_bbio()
> - trace_before_split_bbio()
> - trace_after_split_bbio()

We need a better naming scheme, btrfs_ prefix and then the type of
object the tracepoint describes.

Otherwise ok.
diff mbox series

Patch

diff --git a/fs/btrfs/bio.c b/fs/btrfs/bio.c
index 12b12443efaa..204c30391086 100644
--- a/fs/btrfs/bio.c
+++ b/fs/btrfs/bio.c
@@ -669,9 +669,12 @@  static bool btrfs_submit_chunk(struct btrfs_bio *bbio, int mirror_num)
 	if (use_append)
 		map_length = min(map_length, fs_info->max_zone_append_size);
 
+	trace_before_split_bbio(bbio, mirror_num, map_length);
+
 	if (map_length < length) {
 		bbio = btrfs_split_bio(fs_info, bbio, map_length, use_append);
 		bio = &bbio->bio;
+		trace_after_split_bbio(bbio, mirror_num, map_length);
 	}
 
 	/*
@@ -731,6 +734,7 @@  void btrfs_submit_bio(struct btrfs_bio *bbio, int mirror_num)
 	/* If bbio->inode is not populated, its file_offset must be 0. */
 	ASSERT(bbio->inode || bbio->file_offset == 0);
 
+	trace_initial_bbio(bbio, mirror_num, -1);
 	while (!btrfs_submit_chunk(bbio, mirror_num))
 		;
 }
diff --git a/include/trace/events/btrfs.h b/include/trace/events/btrfs.h
index c6eee9b414cf..9b99b32683be 100644
--- a/include/trace/events/btrfs.h
+++ b/include/trace/events/btrfs.h
@@ -31,6 +31,7 @@  struct extent_io_tree;
 struct prelim_ref;
 struct btrfs_space_info;
 struct btrfs_raid_bio;
+struct btrfs_bio;
 struct raid56_bio_trace_info;
 struct find_free_extent_ctl;
 
@@ -2521,6 +2522,56 @@  DEFINE_EVENT(btrfs_raid56_bio, raid56_scrub_read_recover,
 	TP_ARGS(rbio, bio, trace_info)
 );
 
+DECLARE_EVENT_CLASS(btrfs_bio,
+
+	TP_PROTO(const struct btrfs_bio *bbio, int mirror_num, u64 map_length),
+
+	TP_ARGS(bbio, mirror_num, map_length),
+
+	TP_STRUCT__entry_btrfs(
+		__field(	u64,	logical		)
+		__field(	u64,	root		)
+		__field(	u64,	ino		)
+		__field(	s64,	map_length	)
+		__field(	u32,	length		)
+		__field(	int,	mirror_num	)
+		__field(	u8,	opf		)
+	),
+
+	TP_fast_assign_btrfs(bbio->fs_info,
+		__entry->logical	= bbio->bio.bi_iter.bi_sector << SECTOR_SHIFT;
+		__entry->length		= bbio->bio.bi_iter.bi_size;
+		__entry->map_length	= map_length;
+		__entry->mirror_num	= mirror_num;
+		__entry->opf		= bio_op(&bbio->bio);
+		__entry->root		= bbio->inode ?
+					  bbio->inode->root->root_key.objectid : 0;
+		__entry->ino		= bbio->inode ? btrfs_ino(bbio->inode) : 0;
+	),
+	TP_printk_btrfs(
+"root=%lld(%s) ino=%llu logical=%llu length=%u opf=0x%x mirror_num=%d map_length=%lld",
+		show_root_type(__entry->root), __entry->ino,
+		__entry->logical, __entry->length, __entry->opf,
+		__entry->mirror_num, __entry->map_length)
+);
+
+DEFINE_EVENT(btrfs_bio, initial_bbio,
+	TP_PROTO(const struct btrfs_bio *bbio, int mirror_num, u64 map_length),
+
+	TP_ARGS(bbio, mirror_num, map_length)
+);
+
+DEFINE_EVENT(btrfs_bio, before_split_bbio,
+	TP_PROTO(const struct btrfs_bio *bbio, int mirror_num, u64 map_length),
+
+	TP_ARGS(bbio, mirror_num, map_length)
+);
+
+DEFINE_EVENT(btrfs_bio, after_split_bbio,
+	TP_PROTO(const struct btrfs_bio *bbio, int mirror_num, u64 map_length),
+
+	TP_ARGS(bbio, mirror_num, map_length)
+);
 #endif /* _TRACE_BTRFS_H */
 
 /* This part must be outside protection */