Re: Race conditions in logical decoding

Hi,

v3 applies to master (3a3524e9ac) and builds warning-free here. I think
the wait can go somewhere cheaper, and that makes the questions about the
cache go away. Three patches attached: 0001 replaces v3, 0002 and 0003
are tests that fail on master and pass with 0001.

1. The wait belongs in SnapBuildInitialSnapshot() and nowhere else:
SnapBuildBuildSnapshot() does not need it, and in
SnapBuildInitialSnapshot() it can be a wait on the transaction lock.
0001 does that.

SnapBuildInitialSnapshot() is the only place where the builder's list of
committed transactions turns into a regular MVCC snapshot, and it is
HeapTupleSatisfiesMVCC() on that snapshot that asks CLOG about a
transaction between xmin and xmax. The historic snapshots that
SnapBuildBuildSnapshot() hands to the reorder buffer never do:
HeapTupleSatisfiesHistoricMVCC() decides the range [xmin, xmax) by the
xip array alone and consults CLOG only below xmin, and builder->xmin is
always the oldestRunningXid of an xl_running_xacts record, so a
transaction below it had left the procarray, and so updated CLOG, before
that record was written. The streaming walsender therefore needs no
check at all: no CLOG read per snapshot build, no cache of tested xids
and no question of where it lives or what XID wraparound does to it, and
nothing to sort.

What is left is one read of the running transactions and a wait on the
transaction lock of those among snap->xip that are still running, the
same wait SnapBuildWaitSnapshot() does earlier in the same slot creation;
the others have left the procarray and so have updated CLOG. The two
callers, CREATE_REPLICATION_SLOT before START_REPLICATION and the
REPACK worker, stream to nobody, so the synchronous replication deadlock
of the streaming walsender does not apply to them. Waiting on the lock
rather than polling CLOG also settles Hou's point: once the wait returns,
the transaction has left the procarray, and the exported snapshot agrees
with any snapshot another backend takes afterwards.

A transaction stuck in its synchronous commit is already waited for
today: with a subscription as the synchronous standby, the subscription
disabled and an INSERT waiting in SyncRepWaitForLSN(), a slot creation
with USE_SNAPSHOT on master sits in SnapBuildWaitSnapshot() on that
transaction's lock, since the xl_running_xacts record lists it, and comes
back with the row visible once the subscription is enabled again. Same
with 0001. make check-world passes with the three patches, including
010_truncate.pl, which runs synchronous logical replication.

Before settling on 0001 I went through the side effects I could think
of. Here is the list, so you can see what was considered.

(a) The wait gets wider. Slot creation and REPACK (CONCURRENTLY) now also
wait for transactions whose commit record is decoded but which have not
left the procarray. Normally that is microseconds. Under synchronous
replication with a slow or missing standby it is as long as the commit's
own wait, and in one position where today's code does not wait at all: a
transaction listed in the xl_running_xacts record that takes the builder
to CONSISTENT, since that transition does not call
SnapBuildWaitSnapshot(). Today the snapshot then shows the rows of a
transaction that no other session can see yet; with 0001 it waits like
everybody else.

(b) The cost is one GetRunningTransactionData(), that is one acquisition
of ProcArrayLock and XidGenLock, the same call LogStandbySnapshot() makes
in SnapBuildWaitSnapshot(), and a bsearch() in snap->xip per running
xid. snap->xip itself can be large: while an exportable snapshot is being
built every commit is tracked, not only the catalog-changing ones, so it
holds every commit since the oldest transaction still running at the
last xl_running_xacts record started. Its size hardly enters the cost:
with 100000 and 1000000 such commits in the list, and one transaction
running, the read and the loop took 1 and 3 microseconds here. The wait
shows up as Lock/transactionid, so no new wait event is needed.

(c) Concerns that turned out not to apply. Deadlock: the transactions
waited for have written their commit record, so the only thing they can
still wait for is a synchronous standby's confirmation; confirmations
come from walsenders in STREAMING state, a walsender creating a slot is
in STARTUP, also when it streamed on the same connection before, and the
REPACK worker is no walsender. The worker is in its leader's lock group,
so the deadlock detector sees its wait as the leader's. Two-phase commit:
a prepared transaction's xid lock is held by its dummy PGPROC, and
FinishPreparedTransaction() removes it from the procarray before
releasing the locks. Standby: GetRunningTransactionData() is not made for
recovery, and nothing is needed there: a slot created on a standby
decodes only replayed WAL, and replaying a commit record updates CLOG
before the transaction stops being known as running, so 0001 skips the
wait during recovery; 056_standby_snapshot_export.pl passes. Waiting for
ourselves: USE_SNAPSHOT requires that no query ran in the transaction
yet, the REPACK worker asserts it has no xid, and our own xid cannot be
in the committed list anyway. Cancellation: the lock wait is
interruptible, and lock_timeout applies to it as it already does to
SnapBuildWaitSnapshot(); an error in the loop happens before
MyProc->xmin is set, so nothing is left half done. Asynchronous commit:
the walsender cannot read the commit record before it is flushed, and
CLOG is set by then, so there is no window in the first place.

(d) What I did not do. The standby case rests on 056 and the reasoning
above, not on a test of the race there.

All in all I think 0001 is light enough, and its side effects small
enough, for a fix that is to be backpatched.

2. 0002 is a test that fails on master and passes with 0001: an injection
point in RecordTransactionCommit() between the flush of the commit record
and the CLOG update, and an isolation spec in src/test/modules/
injection_points that runs REPACK (CONCURRENTLY) against it.

The table has two columns and starts with the rows 1|1 and 2|2. Two
sessions hold an XID so that the builder goes through BUILDING_SNAPSHOT
and FULL_SNAPSHOT; while the REPACK worker waits for the second one, a
third session inserts 3|3, changes row 1 to 1|2 and deletes row 2, and
stops at the injection point; then the second session rolls back. On
master the repacked table still has 1|1 and 2|2, that is, none of the
three changes, although the transaction commits fine afterwards. With
0001 REPACK waits for it and the table has 1|2 and 3|3. This is
the same scenario as Antonin's startup_race.spec from January, without
the hook in SET TRANSACTION SNAPSHOT; the 'snapbuild-full-snapshot'
injection point is not needed either, the builder's own wait for the
second session leaves the window open.

The isolation tester sees waits on heavyweight locks and injection
points, nothing else. With v3 in place of 0001 the REPACK step sits in
the latch loop, the tester waits for it and cancels it after 360
seconds. That is the problem Antonin ran into with the isolation tester
in January, and the lock wait of 0001 is what makes the test possible.

One change to the injection_points module is needed: injection_wait()
attaches to the module's shared memory before checking whether the point
is meant for this process, and the attach allocates memory. With the
point attached locally to one session, every other backend that commits
meanwhile, REPACK's own transaction and autovacuum in this test, fails
the allocation assertion inside the critical section. 0002 checks the
condition first.

3. 0003 is the same test through the replication protocol, as a TAP test
in src/test/recovery, since that is the path released branches have:
CREATE_REPLICATION_SLOT ... USE_SNAPSHOT on a database connection takes
the place of REPACK, the table and the other sessions are as in 2.

On master the slot comes back while the transaction still sits before its
CLOG update, a SELECT through the slot's snapshot shows 1|1 and 2|2, and
so does every later session: heap_page_items() shows that this one scan
set HEAP_XMAX_INVALID on the two old row versions and HEAP_XMIN_INVALID
on the inserted row, as if the transaction had aborted. That is the
publisher-side damage Antonin described. With 0001 the walsender waits
on the transaction's lock, and the snapshot and later sessions show 1|2
and 3|3.

Regards,
Rui