Message-ID: <bedc421a-3cdd-ca5a-7b9e-bc6da989f500@enterprisedb.com>
Date: Tue, 6 Jun 2023 17:42:05 +0200
MIME-Version: 1.0
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101
 Thunderbird/102.10.0
Subject: Re: TRAP: FailedAssertion("prev_first_lsn < cur_txn->first_lsn",
 File: "reorderbuffer.c", Line: 927, PID: 568639)
Content-Language: en-US
To: Alexander Lakhin <exclusion@gmail.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>
 <1f860e40-9f95-f0f8-ff4b-4b780f9151ad@gmail.com>
From: Tomas Vondra <tomas.vondra@enterprisedb.com>
In-Reply-To: <1f860e40-9f95-f0f8-ff4b-4b780f9151ad@gmail.com>
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit
Archived-At: 
 <https://www.postgresql.org/message-id/bedc421a-3cdd-ca5a-7b9e-bc6da989f500%40enterprisedb.com>
Precedence: bulk


On 6/6/23 14:00, Alexander Lakhin wrote:
> 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)'

I've been able to reproduce this, after messing with the script a little
bit (I had to skip the test_decoding regression tests, because that was
complaining about slots already existing etc).

Anyway, AssertTXNLsnOrder sees these two transactions (before aborting):

  26662 0/6462E6F0 (first 0/0)
  26661 0/6462E6F0 (first 0/6462E6F0)


where 26661 is the top xact, 26662 is a subxact of 26661. This is
clearly a problem, because we really should not have subxact in this
list once the assignment gets applied.

And the relevant WAL looks like this:

---------------------------------------------------------------------
26662, lsn: 0/645EDAA0, prev 0/645EDA60, desc: ASSIGNMENT xtop 26661:
subxacts: 26662
26662, lsn: 0/645EDAD0, prev 0/645EDAA0, desc: INSERT+INIT off: 1,
flags: 0x08, blkref #0: rel 1663/125447/126835 blk 0
...
    0, lsn: 0/6462E5D8, prev 0/6462E2A0, desc: RUNNING_XACTS nextXid
26673 latestCompletedXid 26672 oldestRunningXid 26661; 3 xacts: 26667
26661 26664; 3 subxacts: 26668 26662 26665
...
26662, lsn: 0/6462E6F0, prev 0/6462E678, desc: NEW_CID rel:
1663/125447/126841, tid: 0/1, cmin: 1, cmax: 4294967295, combo: 4294967295
26662, lsn: 0/6462E730, prev 0/6462E6F0, desc: INSERT+INIT off: 1,
flags: 0x08, blkref #0: rel 1663/125447/126841 blk 0
26661, lsn: 0/6462E770, prev 0/6462E730, desc: COMMIT 2023-06-06
16:41:24.442870 CEST; subxacts: 26662
---------------------------------------------------------------------

so the assignment is the *first* thing that happens for these xacts.

However, we skip the assignment, because the log for this call of
get_changes says this:

   LOG:  logical decoding found consistent point at 0/6462E5D8

so we fail to realize the 26662 is a subxact.

Then when processing the NEW_CID, SnapBuildProcessNewCid chimes in and
does this:

  ReorderBufferXidSetCatalogChanges(builder->reorder, xid, lsn);

  ReorderBufferAddNewTupleCids(builder->reorder, xlrec->top_xid, lsn,
                 xlrec->target_locator, xlrec->target_tid,
                 xlrec->cmin, xlrec->cmax,
                 xlrec->combocid);

and ReorderBufferAddNewTupleCids() proceeds to enter an entry for the
passed XID (which is xlrec->top_xid, 26661), but with LSN of the WAL
record. But ReorderBufferXidSetCatalogChanges() already did the same
thing for the subxact 26662, as it has no idea it's a subxact (due to
the skipped assignment).

I haven't figured out what exactly is happening / what it should be
doing instead. But it seems wrong to skip the assignment - I wonder if
SnapBuildProcessRunningXacts might be doing that too eagerly.


regards

-- 
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company