Re: [PATCH 0/1] bcache: reduce front IO latency during GC

Hi Coly,

Please disregard the test results I shared over a week ago. After digging
deeper into the recent latency spikes with various workloads and by
instrumenting the garbage collector, I realized that the earlier GC latency
patch, "bcache: allow allocator to invalidate bucket in gc" [1], wasn't
backported to the Linux 6.6 branch I tested my patch against. This omission
explains the much higher latency observed during the extended test because the
allocator was blocked for the entire GC. My sincere apologies for the
inconsistent results and any confusion this has caused.

With patch [1] back-patched and after a 24-hour re-test, the fio results clearly
demonstrate that this patch effectively reduces front IO latency during GC due
to the smaller incremental GC cycles, while the GC duration increase is still
well within bounds.

Here's a summary of the improved latency:

Before:

Median latency (P50): 210 ms
Max latency (P100): 3.5 sec

btree_gc_average_duration_ms:381138
btree_gc_average_frequency_sec:3834
btree_gc_last_sec:60668
btree_gc_max_duration_ms:825228
bset_tree_stats:
btree nodes: 144330
written sets: 283733
unwritten sets: 144329
written key bytes: 24993783392
unwritten key bytes: 11777400
floats: 30936844345385
failed: 5776

After:

Median latency (P50): 25 ms
Max latency (P100): 0.8 sec

btree_gc_average_duration_ms:622274
btree_gc_average_frequency_sec:3518
btree_gc_last_sec:8931
btree_gc_max_duration_ms:953146
bset_tree_stats:
btree nodes: 175491
written sets: 339078
unwritten sets: 175488
written key bytes: 29821314856
unwritten key bytes: 14076504
floats: 90520963280544
failed: 6462

The complete latency data is available at [2].

I will be glad to run further tests to solidify these findings for the inclusion
of this patch in the coming merge window. Let me know if you'd like me to
conduct any specific tests.

Best regards
Robert Pang

[1] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=a14a68b76954e73031ca6399abace17dcb77c17a
[2[ https://gist.github.com/robert-pang/cc7c88f356293ea6d43103e6e5f9180f

On Mon, Apr 21, 2025 at 6:44 PM Robert Pang <[email protected]> wrote:
>
> I conducted a 24-hour fio random write test on a 6TB local SSD cache using
> 256kb buckets and the following parameters:
>
> ioengine=libaio
> direct=1
> bs=4k
> size=12T
> iodepth=128
> readwrite=randwrite
> log_avg_msec=10
>
> The results show some improvement in average write latency, resulting in
> increased IOPS (from 11.8k to 17.1k) and throughput (from 45.9MiB/s to
> 66.7MiB/s). However, the maximum write latency exhibited a considerable
> degradation.
>
> Before:
>
> latency_test: (groupid=0, jobs=1): err= 0: pid=14917: Mon Apr 21 06:50:45 2025
>   write: IOPS=11.8k, BW=45.9MiB/s (48.1MB/s)(4035GiB/90000002msec); 0
> zone resets
>     slat (usec): min=9, max=4003.9k, avg=74.37, stdev=3734.09
>     clat (usec): min=2, max=5319.2k, avg=10815.66, stdev=46998.95
>      lat (usec): min=239, max=5319.3k, avg=10890.15, stdev=47167.41
>
> /sys/block/bcache0/bcache/cache/internal/btree_gc_average_duration_ms:381138
> /sys/block/bcache0/bcache/cache/internal/btree_gc_average_frequency_sec:3834
> /sys/block/bcache0/bcache/cache/internal/btree_gc_last_sec:60668
> /sys/block/bcache0/bcache/cache/internal/btree_gc_max_duration_ms:825228
> /sys/block/bcache0/bcache/cache/internal/bset_tree_stats:
> btree nodes: 144330
> written sets: 283733
> unwritten sets: 144329
> written key bytes: 24993783392
> unwritten key bytes: 11777400
> floats: 30936844345385
> failed: 5776
>
>
> After:
>
> latency_test: (groupid=0, jobs=1): err= 0: pid=15158: Mon Apr 21 17:22:13 2025
>   write: IOPS=17.1k, BW=66.7MiB/s (69.9MB/s)(5859GiB/90000004msec); 0
> zone resets
>     slat (usec): min=7, max=469348k, avg=46.71, stdev=20576.47
>     clat (usec): min=3, max=560660k, avg=7453.04, stdev=458965.53
>      lat (usec): min=313, max=560660k, avg=7499.88, stdev=459426.83
>
> /sys/block/bcache0/bcache/cache/internal/btree_gc_average_duration_ms:540350
> /sys/block/bcache0/bcache/cache/internal/btree_gc_average_frequency_sec:3235
> /sys/block/bcache0/bcache/cache/internal/btree_gc_last_sec:22304
> /sys/block/bcache0/bcache/cache/internal/btree_gc_max_duration_ms:719097
> /sys/block/bcache0/bcache/cache/internal/bset_tree_stats:
> btree nodes: 239590
> written sets: 466470
> unwritten sets: 239587
> written key bytes: 36120573032
> unwritten key bytes: 16776624
> floats: 95606253613657
> failed: 4522
>
> Further investigation pointed to the 10ms sleep time being too restrictive for
> this intensive workload. Examining tail latency percentiles outside garbage
> collection revealed that a significant number of I/O requests remained in the
> queue for extended periods. The observed percentiles are:
>
> Percentile Latency (ms)
> P85 10
> P86 11
> P87 13
> P88 16
> P89 22
> P90 36
> P91 60
> P92 104
> P93 174
> P94 231
> P95 257
> P96 282
> P97 308
> P98 337
> P99 377
> P100 472
>
> This data suggests that while a 10ms sleep time might be suitable for lighter
> workloads, it becomes a bottleneck under heavier stress.
>
> In consideration of the test results, I propose the feasibility of keeping the
> original sleep time and min nodes per cycle, but also exposing them as
> configurable attributes through sysfs so users can tune according to their
> workload and latency SLO. I would appreciate your insights on this potential
> enhancement.
>
> On Mon, Apr 14, 2025 at 6:57 PM Coly Li <[email protected]> wrote:
> >
> > Hi Robert,
> >
> > Thanks for the fix up :-)
> >
> > > 2025年4月15日 06:44，Robert Pang <[email protected]> 写道：
> > >
> > > In performance benchmarks on disks with bcache using the Linux 6.6 kernel, we
> > > observe noticeable IO latency increase during btree garbage collection. The
> > > increase ranges from high tens to hundreds of milliseconds, depending on the
> > > size of the cache device. Further investigation reveals that it is the same
> > > issue reported in [1], where the large number of nodes processed in each
> > > incremental GC cycle causes the front IO latency.
> > >
> > > Building upon the approach suggested in [1], this patch decomposes the
> > > incremental GC process into more but smaller cycles. In contrast to [1], this
> > > implementation adopts a simpler strategy by setting a lower limit of 10 nodes
> > > per cycle to reduce front IO delay and introducing a fixed 10ms sleep per cycle
> > > when front IO is in progress. Furthermore, when garbage collection statistics
> > > are available, the number of nodes processed per cycle is dynamically rescaled
> > > based on the average GC frequency to ensure GC completes well within the next
> > > subsequent scheduled interval.
> > >
> > > Testing with a 750GB NVMe cache and 256KB bucket size using the following fio
> > > configuration demonstrates that our patch reduces front IO latency during GC
> > > without significantly increasing GC duration.
> > >
> > > ioengine=libaio
> > > direct=1
> > > bs=4k
> > > size=900G
> > > iodepth=10
> > > readwrite=randwrite
> > > log_avg_msec=10
> > >
> > > Before:
> > >
> > > time-ms,latency-ns,,,
> > >
> > > 12170, 285016, 1, 0, 0
> > > 12183, 296581, 1, 0, 0
> > > 12207, 6542725, 1, 0, 0
> > > 12242, 24483604, 1, 0, 0
> > > 12250, 1895628, 1, 0, 0
> > > 12260, 284854, 1, 0, 0
> > > 12270, 275513, 1, 0, 0
> > >
> > > /sys/block/bcache0/bcache/cache/internal/btree_gc_average_duration_ms:2880
> > > /sys/block/bcache0/bcache/cache/internal/btree_gc_average_frequency_sec:133
> > > /sys/block/bcache0/bcache/cache/internal/btree_gc_last_sec:121
> > > /sys/block/bcache0/bcache/cache/internal/btree_gc_max_duration_ms:3456
> > >
> > > After:
> > >
> > > 12690, 378494, 1, 0, 0
> > > 12700, 413934, 1, 0, 0
> > > 12710, 661217, 1, 0, 0
> > > 12727, 354510, 1, 0, 0
> > > 12730, 1100768, 1, 0, 0
> > > 12742, 382484, 1, 0, 0
> > > 12750, 532679, 1, 0, 0
> > > 12760, 572758, 1, 0, 0
> > > 12773, 283416, 1, 0, 0
> > >
> > > /sys/block/bcache0/bcache/cache/internal/btree_gc_average_duration_ms:3619
> > > /sys/block/bcache0/bcache/cache/internal/btree_gc_average_frequency_sec:58
> > > /sys/block/bcache0/bcache/cache/internal/btree_gc_last_sec:23
> > > /sys/block/bcache0/bcache/cache/internal/btree_gc_max_duration_ms:3866
> > >
> > > [1] https://lore.kernel.org/all/[email protected]/
> >
> >
> > I see the data, it makes sense. I’d like to see more testing data, e.g.
> > 1) Larger SSD (4T or 8T)
> > 2) Higher I/O pressure (randomwrite)
> > 3) Much longer time with high I/O pressure (24 hours+)
> >
> > Then it can help me to understand the optimization better and make decision easier. Of course it will save a lot of testing time from my side.
> >
> > Thank you in advance.
> >
> > Coly Li
> >