Message-ID: <1f860e40-9f95-f0f8-ff4b-4b780f9151ad@gmail.com>
Date: Tue, 6 Jun 2023 15:00:00 +0300
MIME-Version: 1.0
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101
 Thunderbird/102.4.2
Subject: Re: TRAP: FailedAssertion("prev_first_lsn < cur_txn->first_lsn",
 File: "reorderbuffer.c", Line: 927, PID: 568639)
Content-Language: en-US
To: Tomas Vondra <tomas.vondra@enterprisedb.com>,
 Amit Kapila <amit.kapila16@gmail.com>,
 Masahiko Sawada <sawada.mshk@gmail.com>
Cc: pgsql-hackers <pgsql-hackers@postgresql.org>
References: <a89b46b6-0239-2fd5-71a9-b19b1f7a7145@enterprisedb.com>
 <CAA4eK1+u3Y_X8VCW+iFyTsqXqAkFYWMS=-VX7Tt1C_D_FOr9Qg@mail.gmail.com>
 <CAD21AoAE3j=4SgcY3gLZWwpW+OYV=fumhjeEQmb66AvV27-rrQ@mail.gmail.com>
 <CAA4eK1KOAKHCj+fe8-etZ4GBokA4JsqTH=8cYK4CygEzZbJzbA@mail.gmail.com>
 <CAD21AoBmrum63r5anV+Rxo2MyvxehYioRvkKqvENdYzMvE8_7w@mail.gmail.com>
 <CAA4eK1+K5zbf6euH7ei9eX+A8G5122hjJC3CgtJDdrO16GmDvg@mail.gmail.com>
 <CAD21AoAspaKr=iOO+_Vuju8Gu1ynksnT9ZjVe1CQFQvB3kNrCA@mail.gmail.com>
 <CAD21AoA3Q+2VYbmsBK-HSa2Ns4UTMYiQjWMZXum53ZL9q+ZWqA@mail.gmail.com>
 <CAD21AoCMkJ9YAv0xXah19+he5x6ptva07M+eB0qReS_10Wfqfg@mail.gmail.com>
 <CAA4eK1Jsd2JrOzosKL0MoLsSTLCKAP0AiK2924tiRsv4ftnVLA@mail.gmail.com>
 <CAD21AoCf1Q+2feZ8u7JhHfOrcV0FX+8uRPZJA2chyTsYq-g0fA@mail.gmail.com>
 <CAA4eK1Lx=g09z2k9Teq9ca1eRzfpfxJwFdjyHNwgEKv69KWhrQ@mail.gmail.com>
 <f158d9ca-2057-2836-a522-0b1278be5a53@gmail.com>
 <99b45770-e3d8-4522-ea52-f4509931c65b@enterprisedb.com>
From: Alexander Lakhin <exclusion@gmail.com>
In-Reply-To: <99b45770-e3d8-4522-ea52-f4509931c65b@enterprisedb.com>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 8bit
Archived-At: 
 <https://www.postgresql.org/message-id/1f860e40-9f95-f0f8-ff4b-4b780f9151ad%40gmail.com>
Precedence: bulk

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