Re: Apparent walsender bug triggered by logical replication

From: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
To: pgsql-hackers(at)postgreSQL(dot)org
Subject: Re: Apparent walsender bug triggered by logical replication
Date: 2017-06-30 22:18:23
Message-ID: 30864.1498861103@sss.pgh.pa.us
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

I wrote:
> I've been poking into the src/test/subscription TAP tests, thinking
> that they seem a lot slower than they ought to be. The first thing
> I came across was this bit in WaitForReplicationWorkerAttach():

> /*
> * We need timeout because we generally don't get notified via latch
> * about the worker attach.
> */
> rc = WaitLatch(MyLatch,
> WL_LATCH_SET | WL_TIMEOUT | WL_POSTMASTER_DEATH,
> 1000L, WAIT_EVENT_BGWORKER_STARTUP);

> Tracing showed that the worker is generally done attaching within two
> or three milliseconds of the request, making the 1000ms delay in this
> loop a rather serious killer of startup performance. I think the right
> way to fix that is to arrange to have a signal sent back from the worker;
> but just to confirm that this *is* a bottleneck, I tried cutting the
> timeout way back.

I found that logicalrep_worker_stop() has pretty much the identical issue:
it needs to wait for a worker to attach or detach, and it isn't going
to get a latch event for that, and it's using 1-second wait quanta for
events that can be expected to occur within milliseconds.

I still think that the "right" fix would involve adding a way to get
a latch signal for attach/detach, but after some investigation it seemed
like a less-than-trivial change. Since we could do without risky changes
post-beta, I propose that we just reduce these wait parameters to 10ms,
as in the first attached patch. It may not ever be worth working harder
than that, since these waits only occur when starting/stopping/changing
logical replication.

I found another source of one-second-ish delays, which is that when
activity on the master stops, LogicalRepApplyLoop generally goes to sleep
without having ack'd the last bit of activity it replayed, since that
won't have been flushed by the walwriter yet. It will send a feedback
message if it times out --- but that takes a whole second. Maybe longer,
if unrelated wakeups prevent it from seeing WL_TIMEOUT for a few loop
iterations. In reality, we can expect the last WAL to have been flushed
by the walwriter in, more or less, WalWriterDelay msec. Therefore, the
second attached patch tweaks the LogicalRepApplyLoop loop to wait at most
WalWriterDelay if it's got unflushed transactions yet to ack to the
sender, and ensures that we will call send_feedback in the loop even if
no new data arrived.

These two changes cut about 15% off the runtime of the subscription tests
for me (compared to where things stand after 1f201a818). They're probably
less interesting than that for production purposes, but I think it's worth
doing anyway.

regards, tom lane

Attachment Content-Type Size
shorten-worker-attach-detach-waits.patch text/x-diff 4.6 KB
speedup-flush-feedback.patch text/x-diff 2.3 KB

In response to

Browse pgsql-hackers by date

  From Date Subject
Next Message Alvaro Herrera 2017-06-30 22:20:43 Re: Race conditions with WAL sender PID lookups
Previous Message Thomas Munro 2017-06-30 21:45:51 Re: UPDATE of partition key