Re: Debugging abysmal write performance with 100% cpu kworker/u16:X+flush-btrfs-2

[Chris Murphy <lists@colorremedies.com>]

On Sat, Jul 25, 2020 at 8:25 AM Hans van Kranenburg <hans@knorrie.org> wrote:
>
> Hi,
>
> I have a filesystem here that I'm filling up with data from elsewhere.
> Most of it is done by rsync, and part by send/receive. So, receiving
> data over the network, and then writing the files to disk. There can be
> a dozen of these processes running in parallel.

Each receive goes into its own subvolume. What about the rsyncs? How
many concurrent and how many per subvolume?



> Now, when doing so, the kworker/u16:X+flush-btrfs-2 process (with
> varying X) often is using nearly 100% cpu, while enormously slowing down
> disk writes. This shows as disk IO wait for the rsync and btrfs receive
> processes.
>
> The underlying storage (iSCSI connected over 10Gb/s network) can easily
> eat a few hundred MiB/s. When looking at actual disk business on the
> storage device, percentages <5% utilization are reported for the actual
> disks.
>
> It's clearly kworker/u16:X+flush-btrfs-2 which is the bottleneck here.


>
> I just did a 'perf record -g -a sleep 60' while disk writes were down to
> under 1MiB (!) per second and then 'perf report'. Attached some 'screen
> shot' of it. Also attached an example of what nmon shows to give an idea
> about the situation.

Why is swapper involved in this?

+   80.53%     0.00%  swapper          [kernel.kallsyms]     [k]
secondary_startup_64
+   80.53%     0.00%  swapper          [kernel.kallsyms]     [k]
cpu_startup_entry
+   80.53%     0.00%  swapper          [kernel.kallsyms]     [k] do_idle
+   80.52%     0.00%  swapper          [kernel.kallsyms]     [k] default_idle
+   80.52%    80.51%  swapper          [kernel.kallsyms]     [k]
native_safe_halt
+   63.42%     0.00%  swapper          [kernel.kallsyms]     [k] start_secondary

What's PSI look like while this problem is happening?

# grep . /proc/pressure/*
# cat /proc/meminfo

>
> So, what I'm looking for is:
> * Does anyone else see this happen when doing a lot of concurrent writes?
> * What does this flush thing do?
> * Why is it using 100% cpu all the time?
> * How can I debug this more?
> * Ultimately, of course... how can we improve this?
>
> I can recompile the kernel image to e.g. put more trace points in, in
> different places.

What about using bcc-tools to check for high latencies? I'd maybe
start with fileslower, syncsnoop, btrfsslower, biolatency. This is a
bit of a firehose at first, but not near as much as perf. Strategy
wise you could start either at the top with fileslower or at the
bottom with biolatency, fileslower may not tell you anything you don't
already know which is that everything is f'n slow and waiting on
something. So OK is there something hammering on sync()? Try that
next. And so on. There's a bunch of these tools:

https://github.com/iovisor/bcc/blob/master/images/bcc_tracing_tools_2019.png


--
Chris Murphy