Re: TRAP: FailedAssertion("prev_first_lsn < cur_txn->first_lsn", File: "reorderbuffer.c", Line: 927, PID: 568639)

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