Обсуждение: BUG #18280: logical decoding build wrong snapshot for subtransactions

The following bug has been logged on the website:

Bug reference:      18280
Logged by:          Fei Changhong
Email address:      feichanghong@qq.com
PostgreSQL version: 15.5
Operating system:   Operating system: centos 7,Kernel version: 5.10.13
Description:

Hi, all
I encountered a problem related to logical decoding history snapshot. The
specific phenomenon is "ERROR: could not map filenode "base/5/16390" to
relation OID".
The sub-transaction that modified the catalog ends earlier than the
restart_lsn of the logical replication slot, but the commit wal record of
its parent transaction is after the restart_lsn. The WAL record related to
the sub-transaction will not be decoded during logical decoding, so it will
not be marked as containing catalog changes. The catalog is not recorded in
the committed list of the snapshot.
SnapBuildXidSetCatalogChanges (introduced in 272248a) skipping the check for
the sub-transactions when the parent transaction has been marked as
containing catalog changes should be the root cause of the problem.

The problem can be reproduced by following the following steps (to avoid the
impact of bgwriter writing XLOG_RUNNING_XACTS WAL records, I increased the
value of LOG_SNAPSHOT_INTERVAL_MS):
session 1:
```
CREATE TABLE tbl1 (val1 integer, val2 integer);
CREATE TABLE tbl1_part (val1 integer) PARTITION BY RANGE (val1);

SELECT 'init' FROM pg_create_logical_replication_slot('isolation_slot',
'test_decoding');

BEGIN;
SAVEPOINT sp1;
CREATE TABLE tbl1_part_p1 PARTITION OF tbl1_part FOR VALUES FROM (0) TO
(10);
RELEASE SAVEPOINT sp1;
```

session 2:
```
CHECKPOINT;
```

session 1:
```
CREATE TABLE tbl1_part_p2 PARTITION OF tbl1_part FOR VALUES FROM (10) TO
(20);
COMMIT;
BEGIN;
TRUNCATE tbl1;
```

session 2:
```
CHECKPOINT;
SELECT data FROM pg_logical_slot_get_changes('isolation_slot', NULL, NULL,
'skip-empty-xacts', '1', 'include-xids', '0');
INSERT INTO tbl1_part VALUES (1);
SELECT data FROM pg_logical_slot_get_changes('isolation_slot', NULL, NULL,
'skip-empty-xacts', '1', 'include-xids', '0');
```

I will provide a patch to fix this problem later.

Hi,

Thanks for the steps for reproducing this bug and the fix!

"feichanghong" <feichanghong@qq.com> writes:

>> SnapBuildXidSetCatalogChanges (introduced in 272248a) skipping the check for
>> the sub-transactions when the parent transaction has been marked as
>> containing catalog changes should be the root cause of the problem.
>
> My fix is to remove the ReorderBufferXidHasCatalogChanges condition from the SnapBuildXidSetCatalogChanges function.
This
> approach has a false positive; the subtransactions that didn't change catalog to the snapshot are also added to the
> commit list. But that won't be a problem since we use snapshot built during decoding only to read system catalogs,
as
> 272248a's commit message says.

The patch looks good to me.

Added Masahiko who is the author of commit 272248a and Amit who is alway
good at this area as well. Hope this can get more attention from them.

-- 
Best Regards
Andy Fan

On Wed, Jan 10, 2024 at 7:56 PM feichanghong <feichanghong@qq.com> wrote:
>
> > SnapBuildXidSetCatalogChanges (introduced in 272248a) skipping the check for
> > the sub-transactions when the parent transaction has been marked as
> > containing catalog changes should be the root cause of the problem.
>
> My fix is to remove the ReorderBufferXidHasCatalogChanges condition from the SnapBuildXidSetCatalogChanges function.
Thisapproach has a false positive; the subtransactions that didn't change catalog to the snapshot are also added to the
commitlist. But that won't be a problem since we use snapshot built during decoding only to read system catalogs, as
272248a'scommit message says. 
>

Thanks, your analysis sounds correct to me. BTW, I think this should
occur only in 15 and 14 because in prior branches we didn't check if
the xact has catalog changes before marking its subxacts. From 16
onwards, we already accurately serialize the xacts and subxacts that
have made any catalog changes, so this problem shouldn't be there. Can
you please once verify the same?

--
With Regards,
Amit Kapila.

Dear hackers,

Thanks for reporting the bug. I could reproduce the issue with your reproducer.
I agreed your point.

> Thanks, your analysis sounds correct to me. BTW, I think this should
> occur only in 15 and 14 because in prior branches we didn't check if
> the xact has catalog changes before marking its subxacts. From 16
> onwards, we already accurately serialize the xacts and subxacts that
> have made any catalog changes, so this problem shouldn't be there. Can
> you please once verify the same?

I tested PG16-PG13 and got below result. As you said, only the ERROR happened
only on PG14 and PG15.

PG16 not happen
PG15 happen
PG14 happen
PG13 not happen

Also, proposed fix could be applied atop REL_14_STABLE and pass the test.

Best Regards,
Hayato Kuroda
FUJITSU LIMITED

On Tue, Jan 23, 2024 at 6:03 PM Hayato Kuroda (Fujitsu)
<kuroda.hayato@fujitsu.com> wrote:
>
> Thanks for reporting the bug. I could reproduce the issue with your reproducer.
> I agreed your point.
>
> > Thanks, your analysis sounds correct to me. BTW, I think this should
> > occur only in 15 and 14 because in prior branches we didn't check if
> > the xact has catalog changes before marking its subxacts. From 16
> > onwards, we already accurately serialize the xacts and subxacts that
> > have made any catalog changes, so this problem shouldn't be there. Can
> > you please once verify the same?
>
> I tested PG16-PG13 and got below result. As you said, only the ERROR happened
> only on PG14 and PG15.
>

While looking closely at the test result, I wondered how the following
part of test "s0_begin" "s0_truncate" "s1_checkpoint" "s1_get_changes"
"s0_insert_part" "s1_get_changes" "s0_commit" can see the insert when
the containing transaction is not yet committed. Then, I found it is
because the insert is performed from session 1 due to way it is
declared.

session "s1"
...
step "s1_get_changes" { SELECT data FROM
pg_logical_slot_get_changes('isolation_slot', NULL, NULL,
'skip-empty-xacts', '1', 'include-xids', '0'); }
+step "s0_insert_part" { INSERT INTO tbl1_part VALUES (1); }

I think this session should be performed from seesion-1 and we need
one more get_changes() call to see the problem. I have modified the
test accordingly and also changed the comments. See the attached and
let me know what you people think.

--
With Regards,
Amit Kapila.

Dear Amit,

> While looking closely at the test result, I wondered how the following
> part of test "s0_begin" "s0_truncate" "s1_checkpoint" "s1_get_changes"
> "s0_insert_part" "s1_get_changes" "s0_commit" can see the insert when
> the containing transaction is not yet committed. Then, I found it is
> because the insert is performed from session 1 due to way it is
> declared.
> 
> session "s1"
> ...
> step "s1_get_changes" { SELECT data FROM
> pg_logical_slot_get_changes('isolation_slot', NULL, NULL,
> 'skip-empty-xacts', '1', 'include-xids', '0'); }
> +step "s0_insert_part" { INSERT INTO tbl1_part VALUES (1); }
> 
> I think this session should be performed from seesion-1 and we need
> one more get_changes() call to see the problem. I have modified the
> test accordingly and also changed the comments. See the attached and
> let me know what you people think.

Agreed your point and thanks for updating the patch.
I confirmed your patch passed the test on both PG14 and PG15.

One comment for commit message:

>
    This can happen when during restart, none of the WAL records from the
    subtransaction was decoded and top-level xact contains a DDL.
>

It may be OK, the word "restart" may be confusing because it does not mean for
the server instance. How about "decode" or "reply"?
If you do not like, it's OK to keep.

Others, LGTM.

Best Regards,
Hayato Kuroda
FUJITSU LIMITED

On Wed, Jan 24, 2024 at 3:30 PM Hayato Kuroda (Fujitsu)
<kuroda.hayato@fujitsu.com> wrote:
>
> > While looking closely at the test result, I wondered how the following
> > part of test "s0_begin" "s0_truncate" "s1_checkpoint" "s1_get_changes"
> > "s0_insert_part" "s1_get_changes" "s0_commit" can see the insert when
> > the containing transaction is not yet committed. Then, I found it is
> > because the insert is performed from session 1 due to way it is
> > declared.
> >
> > session "s1"
> > ...
> > step "s1_get_changes" { SELECT data FROM
> > pg_logical_slot_get_changes('isolation_slot', NULL, NULL,
> > 'skip-empty-xacts', '1', 'include-xids', '0'); }
> > +step "s0_insert_part" { INSERT INTO tbl1_part VALUES (1); }
> >
> > I think this session should be performed from seesion-1 and we need
> > one more get_changes() call to see the problem. I have modified the
> > test accordingly and also changed the comments. See the attached and
> > let me know what you people think.
>
> Agreed your point and thanks for updating the patch.
> I confirmed your patch passed the test on both PG14 and PG15.
>
> One comment for commit message:
>
> >
>     This can happen when during restart, none of the WAL records from the
>     subtransaction was decoded and top-level xact contains a DDL.
> >
>
> It may be OK, the word "restart" may be confusing because it does not mean for
> the server instance. How about "decode" or "reply"?
>

Okay, we can change it to 'decoding'. I'll do this before commit
unless there are more comments. I'll push this early next week
(probably on Monday) unless I see any comments.

--
With Regards,
Amit Kapila.

On Thu, Jan 25, 2024 at 9:28 AM Amit Kapila <amit.kapila16@gmail.com> wrote:
>
> Okay, we can change it to 'decoding'. I'll do this before commit
> unless there are more comments. I'll push this early next week
> (probably on Monday) unless I see any comments.
>

Pushed.

--
With Regards,
Amit Kapila.