AdvanceXLInsertBuffers() vs wal_sync_method=open_datasync

Hi,

I just created a primary with wal_segment_size=512. Then tried to create a
standby via pg_basebackup. The pg_basebackup appeared to just hang, for quite
a while, but did eventually complete. Over a minute for an empty cluster, when
using -c fast.

In this case I had used wal_sync_method=open_datasync - it's often faster and
if we want to scale WAL writes more we'll have to use it more widely (you
can't have multiple fdatasyncs in progress and reason about which one affects
what, but you can have multiple DSYNC writes in progress at the same time).

After a bit of confused staring and debugging I figured out that the problem
is that the RequestXLogSwitch() within the code for starting a basebackup was
triggering writing back the WAL in individual 8kB writes via
GetXLogBuffer()->AdvanceXLInsertBuffer(). With open_datasync each of these
writes is durable - on this drive each take about 1ms.

Normally we write out WAL in bigger chunks - but as it turns out, we don't
have any logic for doing larger writes when AdvanceXLInsertBuffers() is called
from within GetXLogBuffer(). We just try to make enough space so that one
buffer can be replaced.

The time for a single SELECT pg_switch_wal() on this system, when using
open_datasync and a 512MB segment, are:

wal_buffers time for pg_switch_xlog()
16 64s
100 53s
400 13s
600 1.3s

That's pretty bad. We don't really benefit from more buffering here, it just
avoids flushing in tiny increments. With a smaller wal_buffers, the large
record by pg_switch_xlog() needs to replace buffers it inself inserted, and
does so one-by-one. If we never re-encounter an buffer we inserted ourself
earlier due to a larger wal_buffers, the problem isn't present.

This can bit with smaller segments too, it doesn't require large ones ones.

The reason this doesn't constantly become an issue is that walwriter normally
tries to write out WAL, and if it does, the AdvanceXLInsertBuffers() called in
backends doesn't need to (walsender also calls AdvanceXLInsertBuffers(), but
it won't ever write out data).

In my case, walsender is actually trying to do something - but it never gets
WALWriteLock. The semaphore does get set after AdvanceXLInsertBuffers()
releases WALWriteLock, but on this system walwriter never succeeds taking the
lwlock before AdvanceXLInsertBuffers() succeeds re-acquiring it.

I think it might be a lucky accident that the problem was visible this
blatantly in this one case - I suspect that this behaviour is encountered
during normal operation in the wild, but much harder to pinpoint, because it
doesn't happen "exclusively".

E.g. I see a lot higher throughput bulk-loading data with larger wal_buffers
when using open_datasync, but basically no difference when using
fdatasync. And there are a lot of wal_buffers_full writes.

To fix this, I suspect we need to make
GetXLogBuffer()->AdvanceXLInsertBuffer() flush more aggressively. In this
specific case, we even know for sure that we are going to fill a lot more
buffers, so no heuristic would be needed. In other cases however we need some
heuristic to know how much to write out.

Given how *extremely* aggressive we are about flushing out nearly all pending
WAL in XLogFlush(), I'm not sure there's much point in not also being somewhat
aggressive in GetXLogBuffer()->AdvanceXLInsertBuffer().

Greetings,

Andres Freund