Thread: Too rigorous assert in reorderbuffer.c
Hi,
My colleague Alexander Lakhin has noticed an assertion failure in
reorderbuffer.c:1330. Here is a simple snippet reproducing it:
SELECT 'init' FROM pg_create_logical_replication_slot('regression_slot', 'test_decoding');
create table t(k int);
begin;
savepoint a;
alter table t alter column k type text;
rollback to savepoint a;
alter table t alter column k type bigint;
commit;
SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts',
'1');
It is indeed too opinionated since cmax of a tuple is not stable; it can
be rewritten if subxact who tried to delete it later aborts (analogy
also holds for xmax). Attached patch removes it. While here, I had also
considered worthwhile to add a test involving DDL in aborted subxact as
it is interesting anyway and wasn't covered before.
From c5cd30f9e23c96390cafad82f832c918dfd3397f Mon Sep 17 00:00:00 2001
From: Arseny Sher <sher-ars@yandex.ru>
Date: Wed, 30 Jan 2019 23:31:47 +0300
Subject: [PATCH] Remove assertion in reorderbuffer that cmax is stable.
Since it can be rewritten arbitrary number of times if subxact(s) who tried to
delete some tuple version abort later. Add small test involving DDL in aborted
subxact as this case is interesting on its own and wasn't covered before.
---
contrib/test_decoding/expected/ddl.out | 20 ++++++++++++++++++++
contrib/test_decoding/sql/ddl.sql | 14 ++++++++++++++
src/backend/replication/logical/reorderbuffer.c | 10 ++++++----
3 files changed, 40 insertions(+), 4 deletions(-)
diff --git a/contrib/test_decoding/expected/ddl.out b/contrib/test_decoding/expected/ddl.out
index b7c76469fc..69dd74676c 100644
--- a/contrib/test_decoding/expected/ddl.out
+++ b/contrib/test_decoding/expected/ddl.out
@@ -409,6 +409,26 @@ SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'inc
COMMIT
(6 rows)
+-- check that DDL in aborted subtransactions handled correctly
+CREATE TABLE tr_sub_ddl(data int);
+BEGIN;
+INSERT INTO tr_sub_ddl VALUES (42);
+SAVEPOINT a;
+ALTER TABLE tr_sub_ddl ALTER COLUMN data TYPE text;
+INSERT INTO tr_sub_ddl VALUES ('blah-blah');
+ROLLBACK TO SAVEPOINT a;
+ALTER TABLE tr_sub_ddl ALTER COLUMN data TYPE bigint;
+INSERT INTO tr_sub_ddl VALUES(43);
+COMMIT;
+SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts',
'1');
+ data
+---------------------------------------------------
+ BEGIN
+ table public.tr_sub_ddl: INSERT: data[integer]:42
+ table public.tr_sub_ddl: INSERT: data[bigint]:43
+ COMMIT
+(4 rows)
+
/*
* Check whether treating a table as a catalog table works somewhat
*/
diff --git a/contrib/test_decoding/sql/ddl.sql b/contrib/test_decoding/sql/ddl.sql
index c4b10a4cf9..f47b4ad716 100644
--- a/contrib/test_decoding/sql/ddl.sql
+++ b/contrib/test_decoding/sql/ddl.sql
@@ -236,6 +236,20 @@ COMMIT;
SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts',
'1');
+-- check that DDL in aborted subtransactions handled correctly
+CREATE TABLE tr_sub_ddl(data int);
+BEGIN;
+INSERT INTO tr_sub_ddl VALUES (42);
+SAVEPOINT a;
+ALTER TABLE tr_sub_ddl ALTER COLUMN data TYPE text;
+INSERT INTO tr_sub_ddl VALUES ('blah-blah');
+ROLLBACK TO SAVEPOINT a;
+ALTER TABLE tr_sub_ddl ALTER COLUMN data TYPE bigint;
+INSERT INTO tr_sub_ddl VALUES(43);
+COMMIT;
+
+SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts',
'1');
+
/*
* Check whether treating a table as a catalog table works somewhat
diff --git a/src/backend/replication/logical/reorderbuffer.c b/src/backend/replication/logical/reorderbuffer.c
index a49e226967..0ace0cfb87 100644
--- a/src/backend/replication/logical/reorderbuffer.c
+++ b/src/backend/replication/logical/reorderbuffer.c
@@ -1327,13 +1327,15 @@ ReorderBufferBuildTupleCidHash(ReorderBuffer *rb, ReorderBufferTXN *txn)
else
{
Assert(ent->cmin == change->data.tuplecid.cmin);
- Assert(ent->cmax == InvalidCommandId ||
- ent->cmax == change->data.tuplecid.cmax);
/*
* if the tuple got valid in this transaction and now got deleted
- * we already have a valid cmin stored. The cmax will be
- * InvalidCommandId though.
+ * we already have a valid cmin stored. The cmax is still
+ * InvalidCommandId though, so stamp it. Moreover, cmax might
+ * be rewritten arbitrary number of times if subxacts who tried to
+ * delete this version abort later. Pick up the latest since it is
+ * (belonging to potentially committed subxact) the only one which
+ * matters.
*/
ent->cmax = change->data.tuplecid.cmax;
}
--
2.11.0
--
Arseny Sher
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company
Hi,
On 31.01.2019 9:21, Arseny Sher wrote:
> My colleague Alexander Lakhin has noticed an assertion failure in
> reorderbuffer.c:1330. Here is a simple snippet reproducing it:
>
> SELECT 'init' FROM pg_create_logical_replication_slot('regression_slot', 'test_decoding');
>
> create table t(k int);
> begin;
> savepoint a;
> alter table t alter column k type text;
> rollback to savepoint a;
> alter table t alter column k type bigint;
> commit;
>
> SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts',
'1');
I just want to add, that I have accidentally discovered the same issue
during the testing of the Tomas's large transactions streaming patch
[1], and had to remove this assert to get things working. I thought that
it was somehow related to the streaming mode and did not test the same
query alone.
[1]
https://www.postgresql.org/message-id/76fc440e-91c3-afe2-b78a-987205b3c758%402ndquadrant.com
Regards
--
Alexey Kondratov
Postgres Professional https://www.postgrespro.com
Russian Postgres Company
On 2019-Jan-31, Arseny Sher wrote:
> My colleague Alexander Lakhin has noticed an assertion failure in
> reorderbuffer.c:1330. Here is a simple snippet reproducing it:
>
> SELECT 'init' FROM pg_create_logical_replication_slot('regression_slot', 'test_decoding');
>
> create table t(k int);
> begin;
> savepoint a;
> alter table t alter column k type text;
> rollback to savepoint a;
> alter table t alter column k type bigint;
> commit;
>
> SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts',
'1');
Hmm, the new test introduced by your patch fails in early branches (at
least 9.4): the transaction is decoded like this:
! data
! -----------------------------------------------------
BEGIN
table public.tr_sub_ddl: INSERT: data[integer]:42
+ table public.pg_temp_16445: INSERT: data[bigint]:42
table public.tr_sub_ddl: INSERT: data[bigint]:43
COMMIT
! (5 rows)
note the additional pg_temp_XYZ row in the middle. This is caused by
the rewrite in ALTER TABLE. Peter E fixed that in Pg11 in commit
325f2ec55; I don't think there's much to do in the backbranches other
than hide the pesky record to avoid it breaking the test.
--
Álvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Alvaro Herrera <alvherre@2ndquadrant.com> writes: > note the additional pg_temp_XYZ row in the middle. This is caused by > the rewrite in ALTER TABLE. Peter E fixed that in Pg11 in commit > 325f2ec55; I don't think there's much to do in the backbranches other > than hide the pesky record to avoid it breaking the test. Oh, I see. Let's just remove the first insertion then, as in attached. I've tested it on master and on 9.4. -- Arseny Sher Postgres Professional: http://www.postgrespro.com The Russian Postgres Company From b34726d9b7565df73319a44664d9cd04de5f514f Mon Sep 17 00:00:00 2001 From: Arseny Sher <sher-ars@yandex.ru> Date: Wed, 30 Jan 2019 23:31:47 +0300 Subject: [PATCH] Remove assertion in reorderbuffer that cmax is stable. Since it can be rewritten arbitrary number of times if subxact(s) who tried to delete some tuple version abort later. Add small test involving DDL in aborted subxact as this case is interesting on its own and wasn't covered before. --- contrib/test_decoding/expected/ddl.out | 18 ++++++++++++++++++ contrib/test_decoding/sql/ddl.sql | 13 +++++++++++++ src/backend/replication/logical/reorderbuffer.c | 10 ++++++---- 3 files changed, 37 insertions(+), 4 deletions(-) diff --git a/contrib/test_decoding/expected/ddl.out b/contrib/test_decoding/expected/ddl.out index b7c76469fc..2bd28e6d15 100644 --- a/contrib/test_decoding/expected/ddl.out +++ b/contrib/test_decoding/expected/ddl.out @@ -409,6 +409,24 @@ SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'inc COMMIT (6 rows) +-- check that DDL in aborted subtransactions handled correctly +CREATE TABLE tr_sub_ddl(data int); +BEGIN; +SAVEPOINT a; +ALTER TABLE tr_sub_ddl ALTER COLUMN data TYPE text; +INSERT INTO tr_sub_ddl VALUES ('blah-blah'); +ROLLBACK TO SAVEPOINT a; +ALTER TABLE tr_sub_ddl ALTER COLUMN data TYPE bigint; +INSERT INTO tr_sub_ddl VALUES(43); +COMMIT; +SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1'); + data +-------------------------------------------------- + BEGIN + table public.tr_sub_ddl: INSERT: data[bigint]:43 + COMMIT +(3 rows) + /* * Check whether treating a table as a catalog table works somewhat */ diff --git a/contrib/test_decoding/sql/ddl.sql b/contrib/test_decoding/sql/ddl.sql index c4b10a4cf9..a55086443c 100644 --- a/contrib/test_decoding/sql/ddl.sql +++ b/contrib/test_decoding/sql/ddl.sql @@ -236,6 +236,19 @@ COMMIT; SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1'); +-- check that DDL in aborted subtransactions handled correctly +CREATE TABLE tr_sub_ddl(data int); +BEGIN; +SAVEPOINT a; +ALTER TABLE tr_sub_ddl ALTER COLUMN data TYPE text; +INSERT INTO tr_sub_ddl VALUES ('blah-blah'); +ROLLBACK TO SAVEPOINT a; +ALTER TABLE tr_sub_ddl ALTER COLUMN data TYPE bigint; +INSERT INTO tr_sub_ddl VALUES(43); +COMMIT; + +SELECT data FROM pg_logical_slot_get_changes('regression_slot', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1'); + /* * Check whether treating a table as a catalog table works somewhat diff --git a/src/backend/replication/logical/reorderbuffer.c b/src/backend/replication/logical/reorderbuffer.c index a49e226967..0ace0cfb87 100644 --- a/src/backend/replication/logical/reorderbuffer.c +++ b/src/backend/replication/logical/reorderbuffer.c @@ -1327,13 +1327,15 @@ ReorderBufferBuildTupleCidHash(ReorderBuffer *rb, ReorderBufferTXN *txn) else { Assert(ent->cmin == change->data.tuplecid.cmin); - Assert(ent->cmax == InvalidCommandId || - ent->cmax == change->data.tuplecid.cmax); /* * if the tuple got valid in this transaction and now got deleted - * we already have a valid cmin stored. The cmax will be - * InvalidCommandId though. + * we already have a valid cmin stored. The cmax is still + * InvalidCommandId though, so stamp it. Moreover, cmax might + * be rewritten arbitrary number of times if subxacts who tried to + * delete this version abort later. Pick up the latest since it is + * (belonging to potentially committed subxact) the only one which + * matters. */ ent->cmax = change->data.tuplecid.cmax; } -- 2.11.0
On 2019-Feb-06, Arseny Sher wrote: > > Alvaro Herrera <alvherre@2ndquadrant.com> writes: > > > note the additional pg_temp_XYZ row in the middle. This is caused by > > the rewrite in ALTER TABLE. Peter E fixed that in Pg11 in commit > > 325f2ec55; I don't think there's much to do in the backbranches other > > than hide the pesky record to avoid it breaking the test. > > Oh, I see. Let's just remove the first insertion then, as in attached. > I've tested it on master and on 9.4. Ah, okay. Does the test still fail when run without the code fix? -- Álvaro Herrera https://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Alvaro Herrera <alvherre@2ndquadrant.com> writes: > On 2019-Feb-06, Arseny Sher wrote: > >> >> Alvaro Herrera <alvherre@2ndquadrant.com> writes: >> >> > note the additional pg_temp_XYZ row in the middle. This is caused by >> > the rewrite in ALTER TABLE. Peter E fixed that in Pg11 in commit >> > 325f2ec55; I don't think there's much to do in the backbranches other >> > than hide the pesky record to avoid it breaking the test. >> >> Oh, I see. Let's just remove the first insertion then, as in attached. >> I've tested it on master and on 9.4. > > Ah, okay. Does the test still fail when run without the code fix? Yes. The problem here is overriding cmax of catalog (pg_attribute in the test) tuples, so it fails without any data at all. -- Arseny Sher Postgres Professional: http://www.postgrespro.com The Russian Postgres Company
On 2019-Feb-07, Arseny Sher wrote: > Alvaro Herrera <alvherre@2ndquadrant.com> writes: > > Ah, okay. Does the test still fail when run without the code fix? > > Yes. The problem here is overriding cmax of catalog (pg_attribute in the > test) tuples, so it fails without any data at all. Makes sense. I thought the blanket removal of the assert() was excessive, and we can relax it instead; what do you think of the attached? -- Álvaro Herrera https://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Attachment
On 2019-Feb-11, Alvaro Herrera wrote: > On 2019-Feb-07, Arseny Sher wrote: > > > Alvaro Herrera <alvherre@2ndquadrant.com> writes: > > > > Ah, okay. Does the test still fail when run without the code fix? > > > > Yes. The problem here is overriding cmax of catalog (pg_attribute in the > > test) tuples, so it fails without any data at all. > > Makes sense. > > I thought the blanket removal of the assert() was excessive, and we can > relax it instead; what do you think of the attached? More precisely, my question was: with this change, does the code still work correctly in your non-toy case? -- Álvaro Herrera https://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Alvaro Herrera <alvherre@2ndquadrant.com> writes: >> I thought the blanket removal of the assert() was excessive, and we can >> relax it instead; what do you think of the attached? > > More precisely, my question was: with this change, does the code still > work correctly in your non-toy case? Yes, it works. I thought for a moment that some obscure cases where cmax on a single tuple is not strictly monotonic might exist, but looks like they don't. So your change is ok for me, reshaping assert is better than removing. make check is also good on all supported branches. -- Arseny Sher Postgres Professional: http://www.postgrespro.com The Russian Postgres Company
On 2019-Feb-12, Arseny Sher wrote: > > Alvaro Herrera <alvherre@2ndquadrant.com> writes: > > >> I thought the blanket removal of the assert() was excessive, and we can > >> relax it instead; what do you think of the attached? > > > > More precisely, my question was: with this change, does the code still > > work correctly in your non-toy case? > > Yes, it works. I thought for a moment that some obscure cases where cmax > on a single tuple is not strictly monotonic might exist, but looks like > they don't. So your change is ok for me, reshaping assert is better than > removing. make check is also good on all supported branches. Thanks for checking! I also run it on all branches, everything passes. Pushed now. -- Álvaro Herrera https://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Alvaro Herrera <alvherre@2ndquadrant.com> writes: > Thanks for checking! I also run it on all branches, everything passes. > Pushed now. I'm sorry to bother you with this again, but due to new test our internal buildfarm revealed that ajacent assert on cmin is also lie. You see, we can't assume cmin is stable because the same key (relnode, tid) might refer to completely different tuples if tuple was inserted by aborted subxact, immeditaly reclaimed and then space occupied by another one. Fix is attached. Technically this might mean a user-facing bug, because we only pick the first cmin which means we might get visibility wrong, allowing to see some version too early (i.e real cmin of tuple is y, but decoding thinks it is x, and x < y). However, I couldn't quickly make up an example where this would actually lead to bad consequences. I tried to create such extra visible row in pg_attribute, but that's ok because loop in RelationBuildTupleDesc spins exactly natts times and ignores what is left unscanned. It is also ok with pg_class, because apparently ScanPgRelation also fishes out the (right) first tuple and doesn't check for duplicates appearing later in the scan. Maybe I just haven't tried hard enough though. Attached 'aborted_subxact_test.patch' is an illustration of such wrong cmin visibility on pg_attribute. It triggers assertion failure, but otherwise ok (no user-facing issues), as I said earlier, so I am disinclined to include it in the fix. -- Arseny Sher Postgres Professional: http://www.postgrespro.com The Russian Postgres Company diff --git a/src/backend/replication/logical/reorderbuffer.c b/src/backend/replication/logical/reorderbuffer.c index 2b486b5e9f..505c7ff134 100644 --- a/src/backend/replication/logical/reorderbuffer.c +++ b/src/backend/replication/logical/reorderbuffer.c @@ -1318,29 +1318,36 @@ ReorderBufferBuildTupleCidHash(ReorderBuffer *rb, ReorderBufferTXN *txn) (void *) &key, HASH_ENTER | HASH_FIND, &found); - if (!found) - { - ent->cmin = change->data.tuplecid.cmin; - ent->cmax = change->data.tuplecid.cmax; - ent->combocid = change->data.tuplecid.combocid; - } - else + if (found) { /* - * Maybe we already saw this tuple before in this transaction, - * but if so it must have the same cmin. + * Tuple with such key (relnode, tid) might be inserted in aborted + * subxact, space reclaimed and then filled with another tuple + * from our xact or another; then we might update it again. It + * means cmin can become valid/invalid at any moment, but valid + * values are always monotonic. */ - Assert(ent->cmin == change->data.tuplecid.cmin); + Assert((ent->cmin == InvalidCommandId) || + (change->data.tuplecid.cmin == InvalidCommandId) || + (change->data.tuplecid.cmin >= ent->cmin)); /* - * cmax may be initially invalid, but once set it can only grow, - * and never become invalid again. + * Practically the same for cmax; to see invalid cmax after + * valid, we need to insert new tuple in place of one reclaimed + * from our aborted subxact. */ Assert((ent->cmax == InvalidCommandId) || - ((change->data.tuplecid.cmax != InvalidCommandId) && - (change->data.tuplecid.cmax > ent->cmax))); - ent->cmax = change->data.tuplecid.cmax; + (change->data.tuplecid.cmax == InvalidCommandId) || + (change->data.tuplecid.cmax > ent->cmax)); } + + /* + * The 'right' (potentially belonging to committed xact) cmin and cmax + * are always the latest. + */ + ent->cmin = change->data.tuplecid.cmin; + ent->cmax = change->data.tuplecid.cmax; + ent->combocid = change->data.tuplecid.combocid; } } diff --git a/contrib/test_decoding/Makefile b/contrib/test_decoding/Makefile index 4afb1d963e..32c2650d1a 100644 --- a/contrib/test_decoding/Makefile +++ b/contrib/test_decoding/Makefile @@ -3,11 +3,11 @@ MODULES = test_decoding PGFILEDESC = "test_decoding - example of a logical decoding output plugin" -REGRESS = ddl xact rewrite toast permissions decoding_in_xact \ +# REGRESS = ddl xact rewrite toast permissions decoding_in_xact \ decoding_into_rel binary prepared replorigin time messages \ spill slot truncate ISOLATION = mxact delayed_startup ondisk_startup concurrent_ddl_dml \ - oldest_xmin snapshot_transfer + oldest_xmin snapshot_transfer aborted_subxact REGRESS_OPTS = --temp-config $(top_srcdir)/contrib/test_decoding/logical.conf ISOLATION_OPTS = --temp-config $(top_srcdir)/contrib/test_decoding/logical.conf diff --git a/contrib/test_decoding/specs/aborted_subxact.spec b/contrib/test_decoding/specs/aborted_subxact.spec new file mode 100644 index 0000000000..cb066fd5d2 --- /dev/null +++ b/contrib/test_decoding/specs/aborted_subxact.spec @@ -0,0 +1,35 @@ +# Test DDL in aborted subxact + +setup +{ + SELECT 'init' FROM pg_create_logical_replication_slot('isolation_slot', 'test_decoding'); -- must be first write inxact + CREATE TABLE harvest(apples int); +} + +teardown +{ + DROP TABLE IF EXISTS harvest; + SELECT 'stop' FROM pg_drop_replication_slot('isolation_slot'); +} + +session "s0" +setup { SET synchronous_commit=on; } +step "s0_begin" { BEGIN; select 'harvest'::regclass::int; } +step "s0_alter_0" { SAVEPOINT a; ALTER TABLE harvest ADD COLUMN pears int; ROLLBACK TO SAVEPOINT a; } +step "s0_alter_1" { ALTER TABLE harvest ADD COLUMN peaches text; } +step "s0_insert" { INSERT INTO harvest values (42, 'red'); } +step "s0_alter_2" { ALTER TABLE harvest ADD COLUMN pears int; } +step "s0_commit" { COMMIT; } +step "s0_get_changes" { SELECT data FROM pg_logical_slot_get_changes('isolation_slot', NULL, NULL, 'include-xids', '0','skip-empty-xacts', '1'); } + +session "s1" +setup { SET synchronous_commit=on; } +step "s1_vacuum" { VACUUM pg_attribute; } +step "s1_vacuum_full" { VACUUM FULL; } + +# alter_0 adds row in pg_attribute for which we remember cmin = 0; it is +# reclaimed by vacuum +# alter_1 ensures we decode insert with current cid = 1 +# alter_2 inserts into another row in place where row of alter_0 was, its cmin +# is 3, however we already remembered it as 0 +permutation "s1_vacuum" "s0_begin" "s0_alter_0" "s0_alter_1" "s0_insert" "s1_vacuum" "s0_alter_2" "s0_commit" "s0_get_changes"
Arseny Sher <a.sher@postgrespro.ru> writes: > I'm sorry to bother you with this again, but due to new test our > internal buildfarm revealed that ajacent assert on cmin is also lie. You > see, we can't assume cmin is stable because the same key (relnode, tid) > might refer to completely different tuples if tuple was inserted by > aborted subxact, immeditaly reclaimed and then space occupied by another > one. Fix is attached. > > Technically this might mean a user-facing bug, because we only pick the > first cmin which means we might get visibility wrong, allowing to see > some version too early (i.e real cmin of tuple is y, but decoding thinks > it is x, and x < y). However, I couldn't quickly make up an example > where this would actually lead to bad consequences. I tried to create > such extra visible row in pg_attribute, but that's ok because loop in > RelationBuildTupleDesc spins exactly natts times and ignores what is > left unscanned. It is also ok with pg_class, because apparently > ScanPgRelation also fishes out the (right) first tuple and doesn't check > for duplicates appearing later in the scan. Maybe I just haven't tried > hard enough though. This issue still exists, it would be nice to fix it... -- Arseny Sher Postgres Professional: http://www.postgrespro.com The Russian Postgres Company