Re: Still seeing high autodefrag IO with kernel 5.16.5

[Qu Wenruo <quwenruo.btrfs@gmx.com>]

[-- Attachment #1: Type: text/plain, Size: 4663 bytes --]



On 2022/2/7 01:43, Jean-Denis Girard wrote:
> Hi list,
>
> I'm also experiencing high IO with autodefrag on 5.16.6 patched
> with: -
> https://patchwork.kernel.org/project/linux-btrfs/list/?series=609387,
>
>
- https://patchwork.kernel.org/project/linux-btrfs/list/?series=611509,
> - btrfs-defrag-bring-back-the-old-file-extent-search-behavior.diff.

OK, btrfs_search_forward() doesn't help in this case I guess.

>
> After about 24 hours uptime, btrfs-cleaner is most of the time at 90
> % CPU usage
>
> %CPU  %MEM     TIME+ COMMAND 77,6   0,0  29:03.25 btrfs-cleaner 19,1
> 0,0   3:40.22 kworker/u24:8-btrfs-endio-write 19,1   0,0   1:50.46
> kworker/u24:27-btrfs-endio-write 18,4   0,0   4:14.82
> kworker/u24:7-btrfs-endio-write 17,4   0,0   4:08.08
> kworker/u24:10-events_unbound 17,4   0,0   4:23.41
> kworker/u24:9-btrfs-delalloc 15,8   0,0   3:41.21
> kworker/u24:3-btrfs-endio-write 15,1   0,0   2:12.61
> kworker/u24:26-blkcg_punt_bio 14,8   0,0   3:40.13
> kworker/u24:18-btrfs-delalloc 12,8   0,0   3:55.70
> kworker/u24:20-btrfs-delalloc 12,5   0,0   4:01.79
> kworker/u24:1-btrfs-delalloc 12,2   0,0   4:04.63
> kworker/u24:22-btrfs-endio-write 11,5   0,0   1:11.90
> kworker/u24:11-btrfs-endio-write 11,2   0,0   1:25.96
> kworker/u24:0-blkcg_punt_bio 10,2   0,0   4:24.17
> kworker/u24:24+events_unbound ...
>
> Load average is 5,56, 6,88, 6,71 while just writing that mail.
>
> And iostat shows:
>
> avg-cpu:  %user   %nice %system %iowait  %steal   %idle 1,5%    0,0%
> 26,8%    6,3%    0,0%   65,4%
>
> tps    kB_read/s    kB_wrtn/s    kB_dscd/s    kB_read    kB_wrtn
> kB_dscd Device 33893,50         0,0k       172,2M        57,8M
> 0,0k       1,7G 577,7M nvme0n1 169,40         0,0k         1,2M
> 0,0k       0,0k      12,5M 0,0k sda 178,90         0,0k         1,3M
> 0,0k       0,0k      12,5M 0,0k sdb
>
> I hope that helps.

And what are the mount options?

 From the CPU usage, it looks like there are some infinite loop, but I
can't find out why by a quick glance.

And since there is no extra read, it looks like it's doing defrag again
and again on the same inode and range.


Mind to apply attached `debug.diff`?

Then you still need to provide `/sys/kernel/debug/tracing/trace`, which
can be very large and full of added debug info.
(This means this can slow down your system)

The example of my local test would result something like this in above
trace file:

# tracer: nop
#
# entries-in-buffer/entries-written: 11/11   #P:16
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
    btrfs-cleaner-1770    [014] .....   961.534329: btrfs_defrag_file:
entry r/i=5/257 start=0 len=131072 newer=7 thres=262144
    btrfs-cleaner-1770    [014] .....   961.534333:
defrag_collect_targets: add target r/i=5/257 start=0 len=16384 em=0
len=16384 gen=7 newer=7
    btrfs-cleaner-1770    [014] .....   961.534335:
defrag_collect_targets: add target r/i=5/257 start=16384 len=16384
em=16384 len=16384 gen=7 newer=7
    btrfs-cleaner-1770    [014] .....   961.534336:
defrag_collect_targets: add target r/i=5/257 start=32768 len=16384
em=32768 len=16384 gen=7 newer=7
    btrfs-cleaner-1770    [014] .....   961.534337:
defrag_collect_targets: add target r/i=5/257 start=49152 len=16384
em=49152 len=16384 gen=7 newer=7
    btrfs-cleaner-1770    [014] .....   961.534564:
defrag_collect_targets: add target r/i=5/257 start=0 len=16384 em=0
len=16384 gen=7 newer=7
    btrfs-cleaner-1770    [014] .....   961.534567:
defrag_collect_targets: add target r/i=5/257 start=16384 len=16384
em=16384 len=16384 gen=7 newer=7
    btrfs-cleaner-1770    [014] .....   961.534568:
defrag_collect_targets: add target r/i=5/257 start=32768 len=16384
em=32768 len=16384 gen=7 newer=7
    btrfs-cleaner-1770    [014] .....   961.534569:
defrag_collect_targets: add target r/i=5/257 start=49152 len=16384
em=49152 len=16384 gen=7 newer=7
    btrfs-cleaner-1770    [014] .....   961.534580: btrfs_defrag_file:
defrag target r/i=5/257 start=0 len=65536
    btrfs-cleaner-1770    [014] .....   961.534681:
btrfs_run_defrag_inodes: defrag finish r/i=5/257 ret=0 defragged=16
last_scanned=131072 last_off=0 cycled=0

Thanks,
Qu


>
>
> Thanks,

[-- Attachment #2: debug.diff --]
[-- Type: text/x-patch, Size: 2457 bytes --]

diff --git a/fs/btrfs/file.c b/fs/btrfs/file.c
index f5de8ab9787e..be2e20d163ef 100644
--- a/fs/btrfs/file.c
+++ b/fs/btrfs/file.c
@@ -304,6 +304,11 @@ static int __btrfs_run_defrag_inode(struct btrfs_fs_info *fs_info,
 	sb_start_write(fs_info->sb);
 	ret = btrfs_defrag_file(inode, NULL, &ctrl);
 	sb_end_write(fs_info->sb);
+	trace_printk("defrag finish r/i=%lld/%llu ret=%d defragged=%llu last_scanned=%llu last_off=%llu cycled=%d\n",
+		     BTRFS_I(inode)->root->root_key.objectid,
+		     btrfs_ino(BTRFS_I(inode)), ret, ctrl.sectors_defragged,
+		     ctrl.last_scanned,
+		     defrag->last_offset, defrag->cycled);
 	/*
 	 * if we filled the whole defrag batch, there
 	 * must be more work to do.  Queue this defrag
diff --git a/fs/btrfs/ioctl.c b/fs/btrfs/ioctl.c
index 133e3e2e2e79..a0501c88922b 100644
--- a/fs/btrfs/ioctl.c
+++ b/fs/btrfs/ioctl.c
@@ -1420,6 +1420,11 @@ static int defrag_collect_targets(struct btrfs_inode *inode,
 add:
 		last_is_target = true;
 		range_len = min(extent_map_end(em), start + len) - cur;
+
+		trace_printk("add target r/i=%lld/%llu start=%llu len=%llu em=%llu len=%llu gen=%lld newer=%llu\n",
+			inode->root->root_key.objectid,
+			btrfs_ino(inode), cur, range_len, em->start, em->len,
+			em->generation, ctrl->newer_than);
 		/*
 		 * This one is a good target, check if it can be merged into
 		 * last range of the target list.
@@ -1520,6 +1525,9 @@ static int defrag_one_locked_target(struct btrfs_inode *inode,
 			 EXTENT_DEFRAG, 0, 0, cached_state);
 	set_extent_defrag(&inode->io_tree, start, start + len - 1, cached_state);
 
+	trace_printk("defrag target r/i=%lld/%llu start=%llu len=%llu\n",
+			inode->root->root_key.objectid,
+			btrfs_ino(inode), start, len);
 	/* Update the page status */
 	for (i = start_index - first_index; i <= last_index - first_index; i++) {
 		ClearPageChecked(pages[i]);
@@ -1786,6 +1794,12 @@ int btrfs_defrag_file(struct inode *inode, struct file_ra_state *ra,
 	if (start_index < inode->i_mapping->writeback_index)
 		inode->i_mapping->writeback_index = start_index;
 
+	trace_printk("entry r/i=%lld/%llu start=%llu len=%llu newer=%llu thres=%u\n",
+		BTRFS_I(inode)->root->root_key.objectid,
+		btrfs_ino(BTRFS_I(inode)),
+		ctrl->last_scanned, last_byte + 1 - ctrl->last_scanned,
+		ctrl->newer_than, ctrl->extent_thresh);
+
 	while (ctrl->last_scanned < last_byte) {
 		const unsigned long prev_sectors_defragged = ctrl->sectors_defragged;
 		u64 cluster_end;