Hello Tomas,
06.06.2023 12:56, Tomas Vondra wrote:
On 6/6/23 11:00, Alexander Lakhin wrote:
Hello,
...> With the debug logging added inside AssertTXNLsnOrder() I see:
ctx->snapshot_builder->start_decoding_at: 209807224,
ctx->reader->EndRecPtr: 210043072,
SnapBuildXactNeedsSkip(ctx->snapshot_builder, ctx->reader->EndRecPtr): 0
and inside the loop:
cur_txn->first_lsn: 209792872
cur_txn->first_lsn: 209975744
cur_txn->first_lsn: 210043008
cur_txn->first_lsn: 210043008
and it triggers the Assert.
So what's the prev_first_lsn value for these first_lsn values? How does
it change over time? Did you try looking at the pg_waldump for these
positions?
With more logging I've got (for another run):
ReorderBufferTXNByXid| xid: 3397, lsn: c1fbc80
ctx->snapshot_builder->start_decoding_at: c1f2cc0, ctx->reader->EndRecPtr: c1fbcc0,
SnapBuildXactNeedsSkip(ctx->snapshot_builder, ctx->reader->EndRecPtr): 0
prev_first_lsn: 0, cur_txn->first_lsn: c1fbc80
prev_first_lsn: c1fbc80, cur_txn->first_lsn: c1fbc80
TRAP: failed Assert("prev_first_lsn < cur_txn->first_lsn") ...
waldump for 00000001000000000000000C shows:
grep c1fbc80:
rmgr: Heap2 len (rec/tot): 60/ 60, tx: 3398, lsn: 0/0C1FBC80, prev 0/0C1FBC50, desc: NEW_CID rel:
1663/18763/19987, tid: 0/1, cmin: 1, cmax: 4294967295, combo: 4294967295
rmgr: Heap len (rec/tot): 59/ 59, tx: 3398, lsn: 0/0C1FBCC0, prev 0/0C1FBC80, desc: INSERT+INIT off:
1, flags: 0x08, blkref #0: rel 1663/18763/19987 blk 0
grep '( 3397| 3398)'
rmgr: Transaction len (rec/tot): 43/ 43, tx: 3398, lsn: 0/0C1F2B20, prev 0/0C1F2688, desc: ASSIGNMENT xtop
3397: subxacts: 3398
rmgr: Heap len (rec/tot): 59/ 59, tx: 3398, lsn: 0/0C1F2B50, prev 0/0C1F2B20, desc: INSERT+INIT off:
1, flags: 0x08, blkref #0: rel 1663/18763/19981 blk 0
rmgr: Standby len (rec/tot): 62/ 62, tx: 0, lsn: 0/0C1F2BD0, prev 0/0C1F2B90, desc: RUNNING_XACTS
nextXid 3400 latestCompletedXid 3396 oldestRunningXid 3397; 2 xacts: 3399 3397; 1 subxacts: 3398
rmgr: Standby len (rec/tot): 58/ 58, tx: 0, lsn: 0/0C1F2C80, prev 0/0C1F2C50, desc: RUNNING_XACTS
nextXid 3400 latestCompletedXid 3399 oldestRunningXid 3397; 1 xacts: 3397; 1 subxacts: 3398
rmgr: XLOG len (rec/tot): 114/ 114, tx: 0, lsn: 0/0C1F2CC0, prev 0/0C1F2C80, desc:
CHECKPOINT_ONLINE redo 0/C1F2C10; tli 1; prev tli 1; fpw true; xid 0:3400; oid 24576; multi 13; offset 29; oldest xid
722 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 3397; online
rmgr: Standby len (rec/tot): 62/ 62, tx: 0, lsn: 0/0C1FBAD0, prev 0/0C1FBAA0, desc: RUNNING_XACTS
nextXid 3401 latestCompletedXid 3399 oldestRunningXid 3397; 2 xacts: 3400 3397; 1 subxacts: 3398
rmgr: Heap2 len (rec/tot): 60/ 60, tx: 3398, lsn: 0/0C1FBC80, prev 0/0C1FBC50, desc: NEW_CID rel:
1663/18763/19987, tid: 0/1, cmin: 1, cmax: 4294967295, combo: 4294967295
rmgr: Heap len (rec/tot): 59/ 59, tx: 3398, lsn: 0/0C1FBCC0, prev 0/0C1FBC80, desc: INSERT+INIT off:
1, flags: 0x08, blkref #0: rel 1663/18763/19987 blk 0
rmgr: Transaction len (rec/tot): 54/ 54, tx: 3397, lsn: 0/0C1FBD00, prev 0/0C1FBCC0, desc: COMMIT
2023-06-06 13:55:26.955268 MSK; subxacts: 3398
Best regards,
Alexander
