The following bug has been logged on the website:
Bug reference: 16517
Logged by: Евтушок Максим
Email address: max.evtushok@gmail.com
PostgreSQL version: 11.8
Operating system: Linux
Description:
I use a logical decoding feature (pgoutput plugin on the sender's side and
pgjdbc with Debezium on the receiver's side).
After insert + commit I wait for some time, watching in Postgres debug log
for values of write+flush+apply LSN positions (walsender.c).
Write position of walsender continues to grow because new data arrives into
WAL. But flush and apply positions freeze because no new data transferred to
the receiver.
It blocks fast shutdown of Postgres because there is a check that the write
position should be equal to the flush position in WalSndDone procedure
(https://github.com/postgres/postgres/blob/REL_11_STABLE/src/backend/replication/walsender.c#L2852)
I think that the write position should not be incremented if no data sent to
a receiver.
Example:
Postgres log some time after insert:
2020-06-26 10:28:26.526 UTC [767983] PostgreSQL JDBC Driver
185.193.196.40(2838) DEBUG: write 0/1B1959E0 flush 0/1B1958C8 apply
0/1B1958C8
Waldump:
/usr/local/pgsql/data$ pg_waldump -s 0/1B1935C8
rmgr: Sequence len (rec/tot): 99/ 99, tx: 752659, lsn:
0/1B1935C8, prev 0/1B193590, desc: LOG rel 1663/16384/32801, blkref #0: rel
1663/16384/32801 blk 0
rmgr: Heap len (rec/tot): 75/ 583, tx: 752659, lsn:
0/1B193630, prev 0/1B1935C8, desc: INSERT off 11, blkref #0: rel
1663/16384/32803 blk 2119 FPW
rmgr: Btree len (rec/tot): 53/ 8193, tx: 752659, lsn:
0/1B193878, prev 0/1B193630, desc: INSERT_LEAF off 405, blkref #0: rel
1663/16384/32807 blk 1076 FPW
rmgr: Transaction len (rec/tot): 46/ 46, tx: 752659, lsn:
0/1B195898, prev 0/1B193878, desc: COMMIT 2020-06-26 10:23:59.694483 UTC
rmgr: Standby len (rec/tot): 50/ 50, tx: 0, lsn:
0/1B1958C8, prev 0/1B195898, desc: RUNNING_XACTS nextXid 752660
latestCompletedXid 752659 oldestRunningXid 752660
rmgr: Standby len (rec/tot): 50/ 50, tx: 0, lsn:
0/1B195900, prev 0/1B1958C8, desc: RUNNING_XACTS nextXid 752660
latestCompletedXid 752659 oldestRunningXid 752660
rmgr: XLOG len (rec/tot): 106/ 106, tx: 0, lsn:
0/1B195938, prev 0/1B195900, desc: CHECKPOINT_ONLINE redo 0/1B195900; tli 1;
prev tli 1; fpw true; xid 0:752660; oid 32811; multi 1; offset 0; oldest xid
561 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid:
0/0; oldest running xid 752660; online
rmgr: Standby len (rec/tot): 50/ 50, tx: 0, lsn:
0/1B1959A8, prev 0/1B195938, desc: RUNNING_XACTS nextXid 752660
latestCompletedXid 752659 oldestRunningXid 752660
pg_waldump: FATAL: error in WAL record at 0/1B1959A8: invalid record
length at 0/1B1959E0: wanted 24, got 0
Last message on network with WAL data is a commit message (XLogData (B)
https://www.postgresql.org/docs/11/protocol-replication.html):
0040 64 00 00 00 37 77 00 00 00 00 1b 19 58 c8
d...7w......XÈ
0050 00 00 00 00 1b 19 58 c8 00 02 4b f8 e0 40 2d ab
......XÈ..Køà@-«
0060 43 00 00 00 00 00 1b 19 58 98 00 00 00 00 1b 19
C.......X.......
0070 58 c8 00 02 4b f8 e0 40 26 93 XÈ..Køà@&.
Write position here - 0/1B1958C8
No new XLogData arrived, but keepalive LSN keep incrementing after the last
commit message:
0040 64 00 00 00 16 6b 00 00 00 00 1b 19 59 e0
d....k......Yà
0050 00 02 4b f8 ef 22 6c d6 00 ..Køï"lÖ.
Write position here - 0/1B1959E0
So there are increments of LSN not visible to receiver that couldn't be
flushed.
Because of that there is big probability that during fast shutdown keep
alive will have bigger LSN in keep-alive than flushed LSN on a receiver and
fast shutdown won't be possible.
