BUG #18658: Assert in SerialAdd() due to race condition

Hello again!

Using a build with no asserts enabled and without that define, I can also
see the following errors using the script with increased concurrency
(Initially we got a report from our client, who encountered these errors in
production):

2024-10-17 04:58:29.774 UTC|test|regression|67109975.ed069|PANIC: could
not access status of transaction 18204
2024-10-17 04:58:29.774 UTC|test|regression|67109975.ed069|DETAIL: Could
not open file "pg_serial/0000": No such file or directory.

I changed ERROR to PANIC to get a core dump.

echo "CREATE TABLE t(f1 int);" | psql

res=0

for i in `seq 200`; do
echo "I $i"
for l in `seq 80`; do
echo "
SET default_transaction_isolation to 'SERIALIZABLE';
SELECT 'INSERT INTO t VALUES(42);' FROM generate_series(1, 100) g
\gexec
" | psql -q &
done
wait

grep 'PANIC: could not access status' server.log && { res=1; break; }
grep 'TRAP: ' server.log && { res=1; break; }

done

#5 0x00005f824729a10a in errfinish (filename=0x5f824732df83 "slru.c",
lineno=1060, funcname=0x5f824732e220 <__func__.3> "SlruReportIOError") at
elog.c:599
#6 0x00005f8246c16c26 in SlruReportIOError (ctl=0x5f8247686c80
<SerialSlruCtlData>, pageno=17, xid=18204) at slru.c:1060
#7 0x00005f8246c15cea in SimpleLruReadPage (ctl=0x5f8247686c80
<SerialSlruCtlData>, pageno=17, write_ok=true, xid=18204) at slru.c:579
#8 0x00005f82470988c2 in SerialAdd (xid=18204,
minConflictCommitSeqNo=18446744073709551615) at predicate.c:928
#9 0x00005f8247099854 in SummarizeOldestCommittedSxact () at
predicate.c:1520
#10 0x00005f8247099ddd in GetSerializableTransactionSnapshotInt
(snapshot=0x5f8247691740 <CurrentSnapshotData>, sourcevxid=0x0,
sourcepid=-1) at predicate.c:1798
#11 0x00005f8247099c72 in GetSerializableTransactionSnapshot
(snapshot=0x5f8247691740 <CurrentSnapshotData>) at predicate.c:1692
#12 0x00005f82472ee3b1 in GetTransactionSnapshot () at snapmgr.c:257
#13 0x00005f82470adfe8 in exec_simple_query (query_string=0x5f8248e06a28
"INSERT INTO t VALUES(42);") at postgres.c:1173
#14 0x00005f82470b3453 in PostgresMain (dbname=0x5f8248e030f0 "regression",
username=0x5f8248e3fe08 "test") at postgres.c:4793
#15 0x00005f82470aa5ac in BackendMain (startup_data=0x7fffdf93a054 "",
startup_data_len=4) at backend_startup.c:107
#16 0x00005f8246fd6a6a in postmaster_child_launch (child_type=B_BACKEND,
startup_data=0x7fffdf93a054 "", startup_data_len=4,
client_sock=0x7fffdf93a0a0) at launch_backend.c:274
#17 0x00005f8246fdc4ed in BackendStartup (client_sock=0x7fffdf93a0a0) at
postmaster.c:3420
#18 0x00005f8246fd9dd0 in ServerLoop () at postmaster.c:1653
#19 0x00005f8246fd96d0 in PostmasterMain (argc=1, argv=0x5f8248e01090) at
postmaster.c:1351
#20 0x00005f8246e9729e in main (argc=1, argv=0x5f8248e01090) at main.c:197

Assert would not be triggered in this case, because of:

(gdb) fr 8
#8 0x00005f82470988c2 in SerialAdd (xid=18204,
minConflictCommitSeqNo=18446744073709551615) at predicate.c:928
928 slotno = SimpleLruReadPage(SerialSlruCtl,
targetPage, true, xid);
(gdb) p *serialControl
$1 = {headPage = 18, headXid = 18654, tailXid = 18557}

I'm not sure if this is the same problem.

Thanks to Alexandr Lakhin for help with reproducing the issue!

On Wed, Oct 16, 2024 at 10:33 PM PG Bug reporting form <
noreply@postgresql.org> wrote:

Hello Andrew,

17.10.2024 08:47, Andrew Bille wrote:

Using a build with no asserts enabled and without that define, I can also see the following errors using the script
with increased concurrency (Initially we got a report from our client, who encountered these errors in production):

2024-10-17 04:58:29.774 UTC|test|regression|67109975.ed069|PANIC:  could not access status of transaction 18204
2024-10-17 04:58:29.774 UTC|test|regression|67109975.ed069|DETAIL:  Could not open file "pg_serial/0000": No such file
or directory.

I changed ERROR to PANIC to get a core dump.

With debug logging added (look at the patch attached), I could observe
events, leading to the error:
2024-10-18 07:11:29.301 UTC [2370369:55][client backend][96/762:0] LOG:  statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.301 UTC [2370325:58][client backend][91/0:77843] LOG:  !!!SerialSetActiveSerXmin|
serialControl->tailXid: 77832
2024-10-18 07:11:29.301 UTC [2370325:59][client backend][91/0:77843] STATEMENT:  INSERT INTO t VALUES(42);

1) SerialSetActiveSerXmin(), called by some backend, sets tailXid, which
 corresponds to page 77832 / 1024 = 76.

2024-10-18 07:11:29.301 UTC [2370252:83][client backend][85/794:0] LOG:  statement: INSERT INTO t VALUES(42);
...
2024-10-18 07:11:29.309 UTC [2370375:56][client backend][83/767:0] LOG:  statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370271:106][client backend][63/810:0] LOG:  !!!SerialAdd| xid: 77824,
serialControl->headPage: -1, tailXid: 77832, SERIAL_ENTRIESPERPAGE: 1024, firstZeroPage: 76, targetPage: 76, isNewPage: 1
2024-10-18 07:11:29.309 UTC [2370271:107][client backend][63/810:0] STATEMENT:  INSERT INTO t VALUES(42);

2.1) SerialAdd() called when headPage is not defined yet, for xid 77824,
 which corresponds to page 77824 / 1024 = 76.

2024-10-18 07:11:29.309 UTC [2370327:86][client backend][97/795:0] LOG:  statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370379:72][client backend][87/777:0] LOG:  statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370376:74][client backend][98/781:0] LOG:  statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370321:74][client backend][71/789:0] LOG:  statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370277:86][client backend][76/795:0] LOG:  statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370325:82][client backend][91/791:0] LOG:  statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370373:64][client backend][84/779:0] LOG:  statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370271:108][client backend][63/810:0] LOG:  !!!SerialAdd| after SimpleLruZeroPage(),
firstZeroPage: 76, slotno: 0
2024-10-18 07:11:29.309 UTC [2370271:109][client backend][63/810:0] STATEMENT:  INSERT INTO t VALUES(42);

2.2) SerialAdd() calls SimpleLruZeroPage() to zero out page 76.

2024-10-18 07:11:29.309 UTC [2370330:96][client backend][1/803:0] LOG:  statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370274:95][client backend][70/805:0] LOG:  !!!SerialAdd| xid: 77790,
serialControl->headPage: 76, firstZeroPage: 77, targetPage: 75, isNewPage: 0
2024-10-18 07:11:29.309 UTC [2370274:96][client backend][70/805:0] STATEMENT:  INSERT INTO t VALUES(42);

3.1) SerialAdd() called for another transaction, with xid 77790, which
 corresponds to page 77790 / 1024 = 75, i. e. the page before the page
 just zeroed; this page considered not new.

2024-10-18 07:11:29.309 UTC [2370274:97][client backend][70/805:0] LOG:  !!!SimpleLruReadPage| pageno: 75, slotno: 16,
shared->page_status[slotno]: 0, shared->page_number[slotno]: 0, shared->page_dirty[slotno]: 0
2024-10-18 07:11:29.309 UTC [2370274:98][client backend][70/805:0] STATEMENT:  INSERT INTO t VALUES(42);

3.2) SerialAdd() calls SimpleLruReadPage() for page 75, the page has status
 SLRU_PAGE_EMPTY, so SimpleLruReadPage() wants to read it from disk...

2024-10-18 07:11:29.309 UTC [2370257:89][client backend][58/802:0] LOG:  statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370355:71][client backend][74/780:0] LOG:  statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370274:99][client backend][70/805:0] PANIC:  could not access status of transaction 77790
2024-10-18 07:11:29.309 UTC [2370274:100][client backend][70/805:0] DETAIL:  Could not open file "pg_serial/0002": No
such file or directory.
2024-10-18 07:11:29.309 UTC [2370274:101][client backend][70/805:0] STATEMENT:  INSERT INTO t VALUES(42);

3.3) And fails inside SlruPhysicalReadPage(), because that page was never
 written to disk.

(I used log_line_prefix = '%m [%p:%l][%b][%v:%x] '; decreased 80 to 50 in
the script posted above, had to run the script several dozen times to
catch the error.)

I also saw a failure, when SerialAdd(), which actions 2 and 3 were
performed by one backend.

Best regards,
Alexander

On 18/10/2024 11:00, Alexander Lakhin wrote:

Hello Andrew,

17.10.2024 08:47, Andrew Bille wrote:

Using a build with no asserts enabled and without that define, I can
also see the following errors using the script with increased
concurrency (Initially we got a report from our client, who
encountered these errors in production):

2024-10-17 04:58:29.774 UTC|test|regression|67109975.ed069|PANIC:
 could not access status of transaction 18204
2024-10-17 04:58:29.774 UTC|test|regression|67109975.ed069|DETAIL:
 Could not open file "pg_serial/0000": No such file or directory.

I changed ERROR to PANIC to get a core dump.

With debug logging added (look at the patch attached), I could observe
events, leading to the error:
2024-10-18 07:11:29.301 UTC [2370369:55][client backend][96/762:0] LOG:
statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.301 UTC [2370325:58][client backend][91/0:77843]
LOG:  !!!SerialSetActiveSerXmin| serialControl->tailXid: 77832
2024-10-18 07:11:29.301 UTC [2370325:59][client backend][91/0:77843]
STATEMENT:  INSERT INTO t VALUES(42);

1) SerialSetActiveSerXmin(), called by some backend, sets tailXid, which
 corresponds to page 77832 / 1024 = 76.

2024-10-18 07:11:29.301 UTC [2370252:83][client backend][85/794:0] LOG:
statement: INSERT INTO t VALUES(42);
...
2024-10-18 07:11:29.309 UTC [2370375:56][client backend][83/767:0] LOG:
statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370271:106][client backend][63/810:0]
LOG:  !!!SerialAdd| xid: 77824, serialControl->headPage: -1, tailXid:
77832, SERIAL_ENTRIESPERPAGE: 1024, firstZeroPage: 76, targetPage: 76,
isNewPage: 1
2024-10-18 07:11:29.309 UTC [2370271:107][client backend][63/810:0]
STATEMENT:  INSERT INTO t VALUES(42);

2.1) SerialAdd() called when headPage is not defined yet, for xid 77824,
 which corresponds to page 77824 / 1024 = 76.

2024-10-18 07:11:29.309 UTC [2370327:86][client backend][97/795:0] LOG:
statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370379:72][client backend][87/777:0] LOG:
statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370376:74][client backend][98/781:0] LOG:
statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370321:74][client backend][71/789:0] LOG:
statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370277:86][client backend][76/795:0] LOG:
statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370325:82][client backend][91/791:0] LOG:
statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370373:64][client backend][84/779:0] LOG:
statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370271:108][client backend][63/810:0]
LOG:  !!!SerialAdd| after SimpleLruZeroPage(), firstZeroPage: 76, slotno: 0
2024-10-18 07:11:29.309 UTC [2370271:109][client backend][63/810:0]
STATEMENT:  INSERT INTO t VALUES(42);

2.2) SerialAdd() calls SimpleLruZeroPage() to zero out page 76.

2024-10-18 07:11:29.309 UTC [2370330:96][client backend][1/803:0] LOG:
statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370274:95][client backend][70/805:0] LOG:
!!!SerialAdd| xid: 77790, serialControl->headPage: 76, firstZeroPage:
77, targetPage: 75, isNewPage: 0
2024-10-18 07:11:29.309 UTC [2370274:96][client backend][70/805:0]
STATEMENT:  INSERT INTO t VALUES(42);

3.1) SerialAdd() called for another transaction, with xid 77790, which
 corresponds to page 77790 / 1024 = 75, i. e. the page before the page
 just zeroed; this page considered not new.

2024-10-18 07:11:29.309 UTC [2370274:97][client backend][70/805:0] LOG:
!!!SimpleLruReadPage| pageno: 75, slotno: 16,
shared->page_status[slotno]: 0, shared->page_number[slotno]: 0,
shared->page_dirty[slotno]: 0
2024-10-18 07:11:29.309 UTC [2370274:98][client backend][70/805:0]
STATEMENT:  INSERT INTO t VALUES(42);

3.2) SerialAdd() calls SimpleLruReadPage() for page 75, the page has status
 SLRU_PAGE_EMPTY, so SimpleLruReadPage() wants to read it from disk...

2024-10-18 07:11:29.309 UTC [2370257:89][client backend][58/802:0] LOG:
statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370355:71][client backend][74/780:0] LOG:
statement: INSERT INTO t VALUES(42);
2024-10-18 07:11:29.309 UTC [2370274:99][client backend][70/805:0]
PANIC:  could not access status of transaction 77790
2024-10-18 07:11:29.309 UTC [2370274:100][client backend][70/805:0]
DETAIL:  Could not open file "pg_serial/0002": No such file or directory.
2024-10-18 07:11:29.309 UTC [2370274:101][client backend][70/805:0]
STATEMENT:  INSERT INTO t VALUES(42);

3.3) And fails inside SlruPhysicalReadPage(), because that page was never
 written to disk.

(I used log_line_prefix = '%m [%p:%l][%b][%v:%x] '; decreased 80 to 50 in
the script posted above, had to run the script several dozen times to
catch the error.)

I also saw a failure, when SerialAdd(), which actions 2 and 3 were
performed by one backend.

Thanks for the repro, Andrew & Alexander! I was able to reproduce this
too. It reproduces very quickly with the script you provided, if you add
this sleep to ReleasePredicateLocks():

@@ -3654,6 +3667,8 @@ ReleasePredicateLocks(bool isCommit, bool
isReadOnlySafe)

LWLockRelease(SerializableFinishedListLock);

+	pg_usleep(1000);
+
  	if (needToClear)
  		ClearOldPredicateLocks();

I think the assertion is too strict. It is normal for tailXid to be
invalid in this scenario. The condition is that an XID was added to the
finished list, but the global xmin has already advanced past that XID.
It gets cleared from the finished list by the ClearOldPredicateLocks()
call, but another backend might call SummarizeOldestCommittedSxact()
before that.

The attached patch fixes it.

--
Heikki Linnakangas
Neon (https://neon.tech)

Hello Heikki,

18.10.2024 23:15, Heikki Linnakangas wrote:

Thanks for the repro, Andrew & Alexander! I was able to reproduce this too. It reproduces very quickly with the script
you provided, if you add this sleep to ReleasePredicateLocks():

@@ -3654,6 +3667,8 @@ ReleasePredicateLocks(bool isCommit, bool isReadOnlySafe)

     LWLockRelease(SerializableFinishedListLock);

+    pg_usleep(1000);
+
     if (needToClear)
         ClearOldPredicateLocks();

I think the assertion is too strict. It is normal for tailXid to be invalid in this scenario. The condition is that an
XID was added to the finished list, but the global xmin has already advanced past that XID. It gets cleared from the
finished list by the ClearOldPredicateLocks() call, but another backend might call SummarizeOldestCommittedSxact()
before that.

The attached patch fixes it.

Thank you for your attention to this!

I also encountered another (more rare) failure with that script (initially
on REL_16_STABLE, but now I've reproduced this on master too), when it
fails due to ENOSPC. (I could reproduce the failure more or less reliably
by running that script with parallel -j4 using 4 different servers.)

With additional logging added (see attached), I see the following:
2024-10-19 07:34:48.254 UTC [3032898:1][client backend][48/278:0] LOG:  !!!SerialAdd| xid: 19957,
serialControl->headPage: 4294967295, tailXid: 20491, SERIAL_ENTRIESPERPAGE: 1024, firstZeroPage: 20, targetPage: 19,
isNewPage: 1
2024-10-19 07:34:48.254 UTC [3032898:2][client backend][48/278:0] STATEMENT:  INSERT INTO t VALUES(42);
2024-10-19 07:34:48.254 UTC [3032898:3][client backend][48/278:0] LOG:  !!!SerialAdd: isNewPage, firstZeroPage: 20,
targetPage: 19
2024-10-19 07:34:48.254 UTC [3032898:4][client backend][48/278:0] STATEMENT:  INSERT INTO t VALUES(42);
2024-10-19 07:35:05.105 UTC [3032898:5][client backend][48/278:0] ERROR:  could not access status of transaction 0
2024-10-19 07:35:05.105 UTC [3032898:6][client backend][48/278:0] DETAIL:  Could not write to file "pg_serial/11FB3" at
offset 8192: No space left on device.

That is, if SerialAdd() gets xid preceding tailXid and belonging to a
preceding page, the page zeroing loop just runs until ENOSPC.

Your proposed fix (adjusted for REL_16_STABLE) eliminates the issue for me.
Thank you!

Best regards,
Alexander

On 19/10/2024 12:00, Alexander Lakhin wrote:

Your proposed fix (adjusted for REL_16_STABLE) eliminates the issue for me.
Thank you!

Committed and backpatched to all supported branches. Thanks for the
report and the testing!

--
Heikki Linnakangas
Neon (https://neon.tech)

I think there is a bit more in this module. Though, not related to the
described error. See, we copy nextXid from TransamVariables assuming
TransactionId is atomic. But the nextXid is of FullTransactionId, i.e.
64-bit. And this will work fine on modern 64-bit platforms where 64-bit
FullTransactionId actually would be atomic, but not for the x86. And since
we still support x86 platforms, we better use lock here.

--
Best regards,
Maxim Orlov.