Subject: TRAP: FailedAssertion("HaveRegisteredOrActiveSnapshot()", File: "toast_internals.c", Line: 670, PID: 19403)

From: Erik Rijkers <[email-masked]>
Date: Sun, 27 Mar 2022 20:32:45 +0200

Hi,

On master I got a FailedAssertion("HaveRegisteredOrActiveSnapshot()"
on an assert-enabled instance and with (I think) data over a certain length.

I whittled it down to the attached bash (careful - it drops stuff).  It 
has 5 tsv-data lines (one long line) that COPY slurps into a table.  The 
middle, third line causes the problem, later on.  Shortening the long 
line to somewhere below 2000 characters fixes it again.

More info in the attached .sh file.

If debug-assert is 'off', the problem does not occur. (REL_14_STABLE 
also does not have the problem, assertions or not)

thanks,

Erik Rijkers

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Mon, 28 Mar 2022 18:36:46 +0900 (JST)

At Sun, 27 Mar 2022 20:32:45 +0200, Erik Rijkers <[email-masked]> wrote in 
> I whittled it down to the attached bash (careful - it drops stuff).
> It has 5 tsv-data lines (one long line) that COPY slurps into a table.
> The middle, third line causes the problem, later on.  Shortening the
> long line to somewhere below 2000 characters fixes it again.
> 

It is reproducible for me. Thanks for the reproducer.

> also does not have the problem, assertions or not)

It seems like related with [1]?

Inserting EnsurePortalSnapshotExists() to RunFromStore fixes this but
I'm not sure where is the right place to do this..

[1] https://www.postgresql.org/message-id/flat/20210623035916.GL29179%40telsasoft.com#f802617a00cee4d013ad8fa69e1af048

For someone's information, this is more readable stack trace.

#0  0x00007f43aeed037f in raise () from /lib64/libc.so.6
#1  0x00007f43aeebadb5 in abort () from /lib64/libc.so.6
#2  0x0000000000b28747 in ExceptionalCondition (
    conditionName=0xba2c48 "HaveRegisteredOrActiveSnapshot()", 
    errorType=0xba2882 "FailedAssertion", 
    fileName=0xba2870 "toast_internals.c", lineNumber=670) at assert.c:69
#3  0x00000000004ac776 in init_toast_snapshot (toast_snapshot=0x7ffce64f7440)
    at toast_internals.c:670
#4  0x00000000005164ea in heap_fetch_toast_slice (toastrel=0x7f43b193cad0, 
    valueid=16393, attrsize=1848, sliceoffset=0, slicelength=1848, 
    result=0x1cbb948) at heaptoast.c:688
#5  0x000000000049fc86 in table_relation_fetch_toast_slice (
    toastrel=0x7f43b193cad0, valueid=16393, attrsize=1848, sliceoffset=0, 
    slicelength=1848, result=0x1cbb948)
    at ../../../../src/include/access/tableam.h:1892
#6  0x00000000004a0a0f in toast_fetch_datum (attr=0x1d6b171) at detoast.c:375
#7  0x000000000049fffb in detoast_attr (attr=0x1d6b171) at detoast.c:123
#8  0x0000000000b345ba in pg_detoast_datum_packed (datum=0x1d6b171)
    at fmgr.c:1757
#9  0x0000000000aece72 in text_to_cstring (t=0x1d6b171) at varlena.c:225
#10 0x0000000000aedda2 in textout (fcinfo=0x7ffce64f77a0) at varlena.c:574
#11 0x0000000000b331bf in FunctionCall1Coll (flinfo=0x1d695e0, collation=0, 
    arg1=30847345) at fmgr.c:1138
#12 0x0000000000b3422b in OutputFunctionCall (flinfo=0x1d695e0, val=30847345)
    at fmgr.c:1575
#13 0x00000000004a6b6c in printtup (slot=0x1cb81f0, self=0x1c96e90)
    at printtup.c:357
#14 0x000000000099499f in RunFromStore (portal=0x1cf9380, 
    direction=ForwardScanDirection, count=0, dest=0x1c96e90) at pquery.c:1096
#15 0x00000000009944e3 in PortalRunSelect (portal=0x1cf9380, forward=true, 
    count=0, dest=0x1c96e90) at pquery.c:917
#16 0x00000000009941d3 in PortalRun (portal=0x1cf9380, 
    count=9223372036854775807, isTopLevel=true, run_once=true, 
    dest=0x1c96e90, altdest=0x1c96e90, qc=0x7ffce64f7ac0) at pquery.c:765
#17 0x000000000098df4b in exec_simple_query (
    query_string=0x1c96030 "fetch all in myportal;") at postgres.c:1250
#18 0x00000000009923a3 in PostgresMain (dbname=0x1cc11b0 "postgres", 
    username=0x1cc1188 "horiguti") at postgres.c:4520
#19 0x00000000008c6caf in BackendRun (port=0x1cb74c0) at postmaster.c:4593
#20 0x00000000008c6631 in BackendStartup (port=0x1cb74c0) at postmaster.c:4321
#21 0x00000000008c29cb in ServerLoop () at postmaster.c:1801
#22 0x00000000008c2298 in PostmasterMain (argc=1, argv=0x1c8e0e0)
    at postmaster.c:1473
#23 0x00000000007c14c3 in main (argc=1, argv=0x1c8e0e0) at main.c:202

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Tue, 29 Mar 2022 17:06:21 +0900 (JST)

At Mon, 28 Mar 2022 18:36:46 +0900 (JST), Kyotaro Horiguchi <[email-masked]> wrote in 
> I'm not sure where is the right place to do this..

Then, I found that portal->holdSnapshot is that.  I came up with the
attached.  It does the follows:

1. Teach PlannedStmtRequiresSnapshot() to return true for FetchStmt.

2. Use holdSnapshot in RunFromStore if any.

The rerpducer is reduced to as small as the following.

CREATE TABLE t (a text);
INSERT INTO t VALUES('some random text');
BEGIN;
DECLARE c CURSOR FOR SELECT * FROM t;
FETCH ALL IN c;

But I haven't come up with a reasonable way to generate the 'some
random text' yet.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center
diff --git a/src/backend/tcop/pquery.c b/src/backend/tcop/pquery.c
index 5aa5a350f3..8354029f2a 100644
--- a/src/backend/tcop/pquery.c
+++ b/src/backend/tcop/pquery.c
@@ -1068,6 +1068,18 @@ RunFromStore(Portal portal, ScanDirection direction, uint64 count,
 
 	dest->rStartup(dest, CMD_SELECT, portal->tupDesc);
 
+	/*
+	 * If holdSnapshot is set, that means we should use the snapshot to read
+	 * this store.
+	 */
+	if (portal->holdSnapshot)
+	{
+		Assert(portal->portalSnapshot == 0);
+		PushActiveSnapshotWithLevel(portal->holdSnapshot,
+									portal->createLevel);
+		portal->portalSnapshot = GetActiveSnapshot();
+	}
+	
 	if (ScanDirectionIsNoMovement(direction))
 	{
 		/* do nothing except start/stop the destination */
@@ -1114,6 +1126,13 @@ RunFromStore(Portal portal, ScanDirection direction, uint64 count,
 
 	dest->rShutdown(dest);
 
+	if (portal->holdSnapshot)
+	{
+		Assert(portal->portalSnapshot == GetActiveSnapshot());
+		PopActiveSnapshot();
+		portal->portalSnapshot = NULL;
+	}
+
 	ExecDropSingleTupleTableSlot(slot);
 
 	return current_tuple_count;
@@ -1756,7 +1775,6 @@ PlannedStmtRequiresSnapshot(PlannedStmt *pstmt)
 		IsA(utilityStmt, VariableShowStmt) ||
 		IsA(utilityStmt, ConstraintsSetStmt) ||
 	/* efficiency hacks from here down */
-		IsA(utilityStmt, FetchStmt) ||
 		IsA(utilityStmt, ListenStmt) ||
 		IsA(utilityStmt, NotifyStmt) ||
 		IsA(utilityStmt, UnlistenStmt) ||

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Tue, 29 Mar 2022 18:10:11 +0900 (JST)

At Tue, 29 Mar 2022 17:06:21 +0900 (JST), Kyotaro Horiguchi <[email-masked]> wrote in 
> But I haven't come up with a reasonable way to generate the 'some

I gave up and took a straightforward way to generate one.

I don't like that it uses a fixed length for the random text, but
anyway it works for now...

regards.

---

From: Matthias van de Meent <[email-masked]>
Date: Tue, 29 Mar 2022 12:50:09 +0200

> anyway it works for now...

An shorter (?) reproducer might be the following, which forces any
value for 'a' to be toasted and thus triggering the check in
init_toast_snapshot regardless of value length:

CREATE TABLE t (a text);
ALTER TABLE t ALTER COLUMN a SET STORAGE EXTERNAL;
INSERT INTO t VALUES ('toast');
BEGIN;
DECLARE c CURSOR FOR SELECT * FROM t;
FETCH ALL IN c;

Enjoy,

-Matthias

---

From: Erik Rijkers <[email-masked]>
Date: Tue, 29 Mar 2022 13:29:15 +0200

> DECLARE c CURSOR FOR SELECT * FROM t;

Excellent. That indeed immediately forces the error.

(and the patch prevents it)

Thanks!

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Wed, 30 Mar 2022 10:06:17 +0900 (JST)

At Tue, 29 Mar 2022 13:29:15 +0200, Erik Rijkers <[email-masked]> wrote in 
> > DECLARE c CURSOR FOR SELECT * FROM t;

Yeah, unfortunately I tried that first and saw it didn't work. And it
still doesn't for me.  With such a short text pg_detoast_datum_pakced
doesn't call detoast_attr.  Actually it is VARATT_IS_1B. (@master)

I think I'm missing something here. I'm going to examine around.

regards.

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Wed, 30 Mar 2022 11:46:13 +0900 (JST)

At Wed, 30 Mar 2022 10:06:17 +0900 (JST), Kyotaro Horiguchi <[email-masked]> wrote in 
> I think I'm missing something here. I'm going to examine around.

Hmm. Strange. My memory tells that I did the same thing before.. I
thought that it is somewhat related to compression since repeat('x',
4096) didin't seem working at that time, but it worked this time.
Maybe I was confused between extended and external..

But, in the first place the *fix* has been found to be wrong.  I'm
going to search for the right fix..

regards.

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Wed, 30 Mar 2022 17:58:24 +0900 (JST)

At Wed, 30 Mar 2022 11:46:13 +0900 (JST), Kyotaro Horiguchi <[email-masked]> wrote in 
> going to search for the right fix..

FETCH uses the snapshot at DECLARE. So anyhow I needed to set the
queryDesk's snapshot used in PortalRunSelect to the FETCH's portal's
holdSnapshot.  What I did in this version is:

1. Add a new member "snapshot" to the type DestReceiver.

2. In PortalRunSelect, set the DECLARE'd query's snapshot to the
  member iff the dest is tupelstore and the active snapshot is not
  set.

3. In FillPortalStore, copy the snapshot to the portal's holdSnapshot.

4. RunFromStore uses holdSnapshot if any.

I'm not still confident on this, but it should be better than the v1.

regards.