pg.ddx.io pgsql-bugs@postgresql.org mailing list archive
help / color / mirror / Atom feedBUG #18658: Assert in SerialAdd() due to race condition
7+ messages / 5 participants
[nested] [flat]
* BUG #18658: Assert in SerialAdd() due to race condition
@ 2024-10-16 15:32 PG Bug reporting form <noreply@postgresql.org>
2024-10-17 05:47 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Andrew Bille <andrewbille@gmail.com>
0 siblings, 1 reply; 7+ messages in thread
From: PG Bug reporting form @ 2024-10-16 15:32 UTC (permalink / raw)
To: pgsql-bugs@lists.postgresql.org; +Cc: andrewbille@gmail.com
The following bug has been logged on the website:
Bug reference: 18658
Logged by: Andrew Bille
Email address: andrewbille@gmail.com
PostgreSQL version: 17.0
Operating system: Ubuntu 20.04
Description:
Hello!
The following script against a server (master c259b1578) compiled with
-DTEST_SUMMARIZE_SERIAL (without the define it's harder to reproduce...):
echo "CREATE TABLE t(f1 int);" | psql test
for i in seq 100; do
echo "
SET default_transaction_isolation to 'SERIALIZABLE';
SELECT 'INSERT INTO t VALUES(42);' FROM generate_series(1, 100) g
\gexec
" | psql -q test &
echo "
SET default_transaction_isolation to 'SERIALIZABLE';
SELECT 'INSERT INTO t VALUES(42);' FROM generate_series(1, 100) g
\gexec
" | psql -q test &
wait
grep 'TRAP:' server.log && break;
done
fails for me with the following stack trace:
#5 0x000055e6aaf3fef5 in ExceptionalCondition
(conditionName=conditionName@entry=0x55e6ab1232d1
"TransactionIdIsValid(tailXid)", fileName=fileName@entry=0x55e6ab1231d9
"predicate.c", lineNumber=lineNumber@entry=886) at assert.c:66
#6 0x000055e6aadcde64 in SerialAdd (xid=976743,
minConflictCommitSeqNo=18446744073709551615) at predicate.c:886
#7 0x000055e6aadd0877 in SummarizeOldestCommittedSxact () at
predicate.c:1521
#8 0x000055e6aadd094f in GetSerializableTransactionSnapshotInt
(snapshot=snapshot@entry=0x55e6ab32f3e0 <CurrentSnapshotData>,
sourcevxid=sourcevxid@entry=0x0, sourcepid=sourcepid@entry=-1) at
predicate.c:1789
#9 0x000055e6aadd2a51 in GetSerializableTransactionSnapshot
(snapshot=snapshot@entry=0x55e6ab32f3e0 <CurrentSnapshotData>) at
predicate.c:1693
#10 0x000055e6aaf868c4 in GetTransactionSnapshot () at snapmgr.c:257
#11 0x000055e6aade2d9a in exec_simple_query
(query_string=query_string@entry=0x55e6ab433fe0 "SELECT 'INSERT INTO t
VALUES(42);' FROM generate_series(1, 100) g\n ") at postgres.c:1173
#12 0x000055e6aade516f in PostgresMain (dbname=<optimized out>,
username=<optimized out>) at postgres.c:4793
#13 0x000055e6aadde301 in BackendMain (startup_data=<optimized out>,
startup_data_len=<optimized out>) at backend_startup.c:107
#14 0x000055e6aad2cbf8 in postmaster_child_launch
(child_type=child_type@entry=B_BACKEND,
startup_data=startup_data@entry=0x7ffc1ca820e4 "",
startup_data_len=startup_data_len@entry=4,
client_sock=client_sock@entry=0x7ffc1ca82120)
at launch_backend.c:274
#15 0x000055e6aad30e72 in BackendStartup
(client_sock=client_sock@entry=0x7ffc1ca82120) at postmaster.c:3420
#16 0x000055e6aad31092 in ServerLoop () at postmaster.c:1653
#17 0x000055e6aad324e6 in PostmasterMain (argc=argc@entry=3,
argv=argv@entry=0x55e6ab42e390) at postmaster.c:1351
#18 0x000055e6aac48bd7 in main (argc=3, argv=0x55e6ab42e390) at main.c:197
This is also reproduced on dafaa3efb
Implement genuine serializable isolation level.
...
Thanks, Andrew
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: BUG #18658: Assert in SerialAdd() due to race condition
2024-10-16 15:32 BUG #18658: Assert in SerialAdd() due to race condition PG Bug reporting form <noreply@postgresql.org>
@ 2024-10-17 05:47 ` Andrew Bille <andrewbille@gmail.com>
2024-10-18 08:00 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Alexander Lakhin <exclusion@gmail.com>
0 siblings, 1 reply; 7+ messages in thread
From: Andrew Bille @ 2024-10-17 05:47 UTC (permalink / raw)
To: andrewbille@gmail.com; pgsql-bugs@lists.postgresql.org
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:
> The following bug has been logged on the website:
>
> Bug reference: 18658
> Logged by: Andrew Bille
> Email address: andrewbille@gmail.com
> PostgreSQL version: 17.0
> Operating system: Ubuntu 20.04
> Description:
>
> Hello!
>
> The following script against a server (master c259b1578) compiled with
> -DTEST_SUMMARIZE_SERIAL (without the define it's harder to reproduce...):
>
> echo "CREATE TABLE t(f1 int);" | psql test
>
> for i in seq 100; do
> echo "
> SET default_transaction_isolation to 'SERIALIZABLE';
> SELECT 'INSERT INTO t VALUES(42);' FROM generate_series(1, 100) g
> \gexec
> " | psql -q test &
>
> echo "
> SET default_transaction_isolation to 'SERIALIZABLE';
> SELECT 'INSERT INTO t VALUES(42);' FROM generate_series(1, 100) g
> \gexec
> " | psql -q test &
>
> wait
>
> grep 'TRAP:' server.log && break;
> done
>
> fails for me with the following stack trace:
> #5 0x000055e6aaf3fef5 in ExceptionalCondition
> (conditionName=conditionName@entry=0x55e6ab1232d1
> "TransactionIdIsValid(tailXid)", fileName=fileName@entry=0x55e6ab1231d9
> "predicate.c", lineNumber=lineNumber@entry=886) at assert.c:66
> #6 0x000055e6aadcde64 in SerialAdd (xid=976743,
> minConflictCommitSeqNo=18446744073709551615) at predicate.c:886
> #7 0x000055e6aadd0877 in SummarizeOldestCommittedSxact () at
> predicate.c:1521
> #8 0x000055e6aadd094f in GetSerializableTransactionSnapshotInt
> (snapshot=snapshot@entry=0x55e6ab32f3e0 <CurrentSnapshotData>,
> sourcevxid=sourcevxid@entry=0x0, sourcepid=sourcepid@entry=-1) at
> predicate.c:1789
> #9 0x000055e6aadd2a51 in GetSerializableTransactionSnapshot
> (snapshot=snapshot@entry=0x55e6ab32f3e0 <CurrentSnapshotData>) at
> predicate.c:1693
> #10 0x000055e6aaf868c4 in GetTransactionSnapshot () at snapmgr.c:257
> #11 0x000055e6aade2d9a in exec_simple_query
> (query_string=query_string@entry=0x55e6ab433fe0 "SELECT 'INSERT INTO t
> VALUES(42);' FROM generate_series(1, 100) g\n ") at postgres.c:1173
> #12 0x000055e6aade516f in PostgresMain (dbname=<optimized out>,
> username=<optimized out>) at postgres.c:4793
> #13 0x000055e6aadde301 in BackendMain (startup_data=<optimized out>,
> startup_data_len=<optimized out>) at backend_startup.c:107
> #14 0x000055e6aad2cbf8 in postmaster_child_launch
> (child_type=child_type@entry=B_BACKEND,
> startup_data=startup_data@entry=0x7ffc1ca820e4 "",
> startup_data_len=startup_data_len@entry=4,
> client_sock=client_sock@entry=0x7ffc1ca82120)
> at launch_backend.c:274
> #15 0x000055e6aad30e72 in BackendStartup
> (client_sock=client_sock@entry=0x7ffc1ca82120) at postmaster.c:3420
> #16 0x000055e6aad31092 in ServerLoop () at postmaster.c:1653
> #17 0x000055e6aad324e6 in PostmasterMain (argc=argc@entry=3,
> argv=argv@entry=0x55e6ab42e390) at postmaster.c:1351
> #18 0x000055e6aac48bd7 in main (argc=3, argv=0x55e6ab42e390) at main.c:197
>
> This is also reproduced on dafaa3efb
> Implement genuine serializable isolation level.
>
> ...
>
> Thanks, Andrew
>
>
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: BUG #18658: Assert in SerialAdd() due to race condition
2024-10-16 15:32 BUG #18658: Assert in SerialAdd() due to race condition PG Bug reporting form <noreply@postgresql.org>
2024-10-17 05:47 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Andrew Bille <andrewbille@gmail.com>
@ 2024-10-18 08:00 ` Alexander Lakhin <exclusion@gmail.com>
2024-10-18 20:15 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Heikki Linnakangas <hlinnaka@iki.fi>
0 siblings, 1 reply; 7+ messages in thread
From: Alexander Lakhin @ 2024-10-18 08:00 UTC (permalink / raw)
To: Andrew Bille <andrewbille@gmail.com>; pgsql-bugs@lists.postgresql.org
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
Attachments:
[text/x-patch] SLRU-debugging.patch (2.8K, ../../5634e3e1-6e82-b883-ac87-52d7e926a04d@gmail.com/2-SLRU-debugging.patch)
download | inline diff:
diff --git a/src/backend/access/transam/slru.c b/src/backend/access/transam/slru.c
index 889eff1815..3f0fab052d 100644
--- a/src/backend/access/transam/slru.c
+++ b/src/backend/access/transam/slru.c
@@ -540,6 +540,8 @@ SimpleLruReadPage(SlruCtl ctl, int64 pageno, bool write_ok,
return slotno;
}
+elog(LOG, "!!!SimpleLruReadPage| pageno: %ld, slotno: %d, shared->page_status[slotno]: %d, shared->page_number[slotno]: %ld, shared->page_dirty[slotno]: %d",
+pageno, slotno, shared->page_status[slotno], shared->page_number[slotno], shared->page_dirty[slotno]);
/* We found no match; assert we selected a freeable slot */
Assert(shared->page_status[slotno] == SLRU_PAGE_EMPTY ||
@@ -1057,7 +1059,7 @@ SlruReportIOError(SlruCtl ctl, int64 pageno, TransactionId xid)
switch (slru_errcause)
{
case SLRU_OPEN_FAILED:
- ereport(ERROR,
+ ereport(PANIC,
(errcode_for_file_access(),
errmsg("could not access status of transaction %u", xid),
errdetail("Could not open file \"%s\": %m.", path)));
diff --git a/src/backend/storage/lmgr/predicate.c b/src/backend/storage/lmgr/predicate.c
index e24a0f2fdb..03be4bb3d2 100644
--- a/src/backend/storage/lmgr/predicate.c
+++ b/src/backend/storage/lmgr/predicate.c
@@ -894,12 +894,16 @@ SerialAdd(TransactionId xid, SerCommitSeqNo minConflictCommitSeqNo)
{
firstZeroPage = SerialPage(tailXid);
isNewPage = true;
+elog(LOG, "!!!SerialAdd| xid: %d, serialControl->headPage: %ld, tailXid: %d, SERIAL_ENTRIESPERPAGE: %ld, firstZeroPage: %ld, targetPage: %ld, isNewPage: %d",
+xid, serialControl->headPage, tailXid, SERIAL_ENTRIESPERPAGE, firstZeroPage, targetPage, isNewPage);
}
else
{
firstZeroPage = SerialNextPage(serialControl->headPage);
isNewPage = SerialPagePrecedesLogically(serialControl->headPage,
targetPage);
+elog(LOG, "!!!SerialAdd| xid: %d, serialControl->headPage: %ld, firstZeroPage: %ld, targetPage: %ld, isNewPage: %d",
+xid, serialControl->headPage, firstZeroPage, targetPage, isNewPage);
}
if (!TransactionIdIsValid(serialControl->headXid)
@@ -916,6 +920,7 @@ SerialAdd(TransactionId xid, SerCommitSeqNo minConflictCommitSeqNo)
lock = SimpleLruGetBankLock(SerialSlruCtl, firstZeroPage);
LWLockAcquire(lock, LW_EXCLUSIVE);
slotno = SimpleLruZeroPage(SerialSlruCtl, firstZeroPage);
+elog(LOG, "!!!SerialAdd| after SimpleLruZeroPage(), firstZeroPage: %ld, slotno: %d", firstZeroPage, slotno);
if (firstZeroPage == targetPage)
break;
firstZeroPage = SerialNextPage(firstZeroPage);
@@ -1022,6 +1027,7 @@ SerialSetActiveSerXmin(TransactionId xid)
|| TransactionIdFollows(xid, serialControl->tailXid));
serialControl->tailXid = xid;
+elog(LOG, "!!!SerialSetActiveSerXmin| serialControl->tailXid: %d", serialControl->tailXid);
LWLockRelease(SerialControlLock);
}
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: BUG #18658: Assert in SerialAdd() due to race condition
2024-10-16 15:32 BUG #18658: Assert in SerialAdd() due to race condition PG Bug reporting form <noreply@postgresql.org>
2024-10-17 05:47 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Andrew Bille <andrewbille@gmail.com>
2024-10-18 08:00 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Alexander Lakhin <exclusion@gmail.com>
@ 2024-10-18 20:15 ` Heikki Linnakangas <hlinnaka@iki.fi>
2024-10-19 09:00 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Alexander Lakhin <exclusion@gmail.com>
0 siblings, 1 reply; 7+ messages in thread
From: Heikki Linnakangas @ 2024-10-18 20:15 UTC (permalink / raw)
To: Alexander Lakhin <exclusion@gmail.com>; Andrew Bille <andrewbille@gmail.com>; pgsql-bugs@lists.postgresql.org
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)
Attachments:
[text/x-patch] 0001-Fix-race-condition-in-committing-a-serializable-tran.patch (2.2K, ../../ff9d4350-a82d-4a3f-86e5-3948175a9a86@iki.fi/2-0001-Fix-race-condition-in-committing-a-serializable-tran.patch)
download | inline diff:
From cd5144999fe98def8f21fa54abf16401d53a4f02 Mon Sep 17 00:00:00 2001
From: Heikki Linnakangas <heikki.linnakangas@iki.fi>
Date: Fri, 18 Oct 2024 23:13:15 +0300
Subject: [PATCH 1/1] Fix race condition in committing a serializable
transaction
The finished transaction list can contain XIDs that are older than the
serializable global xmin. It's a short-lived state;
ClearOldPredicateLocks() removes any such transactions from the list,
and it's called whenever the global xmin advances. But if another
backend calls SummarizeOldestCommittedSxact() in that window, it will
call SerialAdd() on an XID that's older than the global xmin, or if
there are no more transactions running, when global xmin is
invalid. That trips the assertion in SerialAdd().
Fixes bug #18658 reported by Andrew Bille. Thanks to Alexander Lakhin
for analysis. Backpatch to all versions.
Discussion: https://www.postgresql.org/message-id/18658-7dab125ec688c70b%40postgresql.org
---
src/backend/storage/lmgr/predicate.c | 13 +++++++++----
1 file changed, 9 insertions(+), 4 deletions(-)
diff --git a/src/backend/storage/lmgr/predicate.c b/src/backend/storage/lmgr/predicate.c
index e24a0f2fdb..2030322f95 100644
--- a/src/backend/storage/lmgr/predicate.c
+++ b/src/backend/storage/lmgr/predicate.c
@@ -877,12 +877,17 @@ SerialAdd(TransactionId xid, SerCommitSeqNo minConflictCommitSeqNo)
LWLockAcquire(SerialControlLock, LW_EXCLUSIVE);
/*
- * If no serializable transactions are active, there shouldn't be anything
- * to push out to the SLRU. Hitting this assert would mean there's
- * something wrong with the earlier cleanup logic.
+ * If 'xid' is older than the global xmin (== tailXid), there's no need to
+ * store it, after all. This can happen if the oldest transaction holding
+ * back the global xmin just finished, making 'xid' uninteresting, but
+ * ClearOldPredicateLocks() has not yet run.
*/
tailXid = serialControl->tailXid;
- Assert(TransactionIdIsValid(tailXid));
+ if (!TransactionIdIsValid(tailXid) || TransactionIdPrecedes(xid, tailXid))
+ {
+ LWLockRelease(SerialControlLock);
+ return;
+ }
/*
* If the SLRU is currently unused, zero out the whole active region from
--
2.39.5
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: BUG #18658: Assert in SerialAdd() due to race condition
2024-10-16 15:32 BUG #18658: Assert in SerialAdd() due to race condition PG Bug reporting form <noreply@postgresql.org>
2024-10-17 05:47 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Andrew Bille <andrewbille@gmail.com>
2024-10-18 08:00 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Alexander Lakhin <exclusion@gmail.com>
2024-10-18 20:15 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Heikki Linnakangas <hlinnaka@iki.fi>
@ 2024-10-19 09:00 ` Alexander Lakhin <exclusion@gmail.com>
2024-10-21 08:02 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Heikki Linnakangas <hlinnaka@iki.fi>
0 siblings, 1 reply; 7+ messages in thread
From: Alexander Lakhin @ 2024-10-19 09:00 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; Andrew Bille <andrewbille@gmail.com>; pgsql-bugs@lists.postgresql.org
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
Attachments:
[text/x-patch] SerialAdd-debugging.patch (1.6K, ../../ea48b857-4e07-dd43-375e-564e13f5bfb2@gmail.com/2-SerialAdd-debugging.patch)
download | inline diff:
diff --git a/src/backend/storage/lmgr/predicate.c b/src/backend/storage/lmgr/predicate.c
index 1af41213b4..4f7c15978a 100644
--- a/src/backend/storage/lmgr/predicate.c
+++ b/src/backend/storage/lmgr/predicate.c
@@ -871,12 +871,16 @@ SerialAdd(TransactionId xid, SerCommitSeqNo minConflictCommitSeqNo)
{
firstZeroPage = SerialPage(tailXid);
isNewPage = true;
+elog(LOG, "!!!SerialAdd| xid: %d, serialControl->headPage: %d, tailXid: %d, SERIAL_ENTRIESPERPAGE: %ld, firstZeroPage: %d, targetPage: %d, isNewPage: %d",
+xid, serialControl->headPage, tailXid, SERIAL_ENTRIESPERPAGE, firstZeroPage, targetPage, isNewPage);
}
else
{
firstZeroPage = SerialNextPage(serialControl->headPage);
isNewPage = SerialPagePrecedesLogically(serialControl->headPage,
targetPage);
+elog(LOG, "!!!SerialAdd| xid: %d, serialControl->headPage: %d, firstZeroPage: %d, targetPage: %d, isNewPage: %d",
+xid, serialControl->headPage, firstZeroPage, targetPage, isNewPage);
}
if (!TransactionIdIsValid(serialControl->headXid)
@@ -887,6 +891,7 @@ SerialAdd(TransactionId xid, SerCommitSeqNo minConflictCommitSeqNo)
if (isNewPage)
{
+elog(LOG, "!!!SerialAdd: isNewPage, firstZeroPage: %d, targetPage: %d", firstZeroPage, targetPage);
/* Initialize intervening pages. */
while (firstZeroPage != targetPage)
{
@@ -894,6 +899,7 @@ SerialAdd(TransactionId xid, SerCommitSeqNo minConflictCommitSeqNo)
firstZeroPage = SerialNextPage(firstZeroPage);
}
slotno = SimpleLruZeroPage(SerialSlruCtl, targetPage);
+elog(LOG, "!!!SerialAdd: after while, slotno: %d", slotno);
}
else
slotno = SimpleLruReadPage(SerialSlruCtl, targetPage, true, xid);
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: BUG #18658: Assert in SerialAdd() due to race condition
2024-10-16 15:32 BUG #18658: Assert in SerialAdd() due to race condition PG Bug reporting form <noreply@postgresql.org>
2024-10-17 05:47 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Andrew Bille <andrewbille@gmail.com>
2024-10-18 08:00 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Alexander Lakhin <exclusion@gmail.com>
2024-10-18 20:15 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Heikki Linnakangas <hlinnaka@iki.fi>
2024-10-19 09:00 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Alexander Lakhin <exclusion@gmail.com>
@ 2024-10-21 08:02 ` Heikki Linnakangas <hlinnaka@iki.fi>
2024-10-23 13:31 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Maxim Orlov <orlovmg@gmail.com>
0 siblings, 1 reply; 7+ messages in thread
From: Heikki Linnakangas @ 2024-10-21 08:02 UTC (permalink / raw)
To: Alexander Lakhin <exclusion@gmail.com>; Andrew Bille <andrewbille@gmail.com>; pgsql-bugs@lists.postgresql.org
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)
^ permalink raw reply [nested|flat] 7+ messages in thread
* Re: BUG #18658: Assert in SerialAdd() due to race condition
2024-10-16 15:32 BUG #18658: Assert in SerialAdd() due to race condition PG Bug reporting form <noreply@postgresql.org>
2024-10-17 05:47 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Andrew Bille <andrewbille@gmail.com>
2024-10-18 08:00 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Alexander Lakhin <exclusion@gmail.com>
2024-10-18 20:15 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Heikki Linnakangas <hlinnaka@iki.fi>
2024-10-19 09:00 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Alexander Lakhin <exclusion@gmail.com>
2024-10-21 08:02 ` Re: BUG #18658: Assert in SerialAdd() due to race condition Heikki Linnakangas <hlinnaka@iki.fi>
@ 2024-10-23 13:31 ` Maxim Orlov <orlovmg@gmail.com>
0 siblings, 0 replies; 7+ messages in thread
From: Maxim Orlov @ 2024-10-23 13:31 UTC (permalink / raw)
To: Heikki Linnakangas <hlinnaka@iki.fi>; +Cc: Alexander Lakhin <exclusion@gmail.com>; Andrew Bille <andrewbille@gmail.com>; pgsql-bugs@lists.postgresql.org
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.
Attachments:
[application/octet-stream] v1-0001-Hold-XidGenLock-to-read-TransamVariables-nextXid.patch (1.4K, ../../CACG=eza1dzSk5EZR-+hW+wk2250+tZjFR1tEssjq5f9ADRgbLg@mail.gmail.com/3-v1-0001-Hold-XidGenLock-to-read-TransamVariables-nextXid.patch)
download | inline diff:
From 8926b83835fb9f0d90318e83150ca6645735140d Mon Sep 17 00:00:00 2001
From: Maxim Orlov <orlovmg@gmail.com>
Date: Wed, 23 Oct 2024 15:44:28 +0300
Subject: [PATCH v1] Hold XidGenLock to read TransamVariables->nextXid
---
src/backend/storage/lmgr/predicate.c | 5 ++---
1 file changed, 2 insertions(+), 3 deletions(-)
diff --git a/src/backend/storage/lmgr/predicate.c b/src/backend/storage/lmgr/predicate.c
index 2030322f95..6dce4d8443 100644
--- a/src/backend/storage/lmgr/predicate.c
+++ b/src/backend/storage/lmgr/predicate.c
@@ -3419,9 +3419,6 @@ ReleasePredicateLocks(bool isCommit, bool isReadOnlySafe)
topLevelIsDeclaredReadOnly = SxactIsReadOnly(MySerializableXact);
/*
- * We don't hold XidGenLock lock here, assuming that TransactionId is
- * atomic!
- *
* If this value is changing, we don't care that much whether we get the
* old or new value -- it is just used to determine how far
* SxactGlobalXmin must advance before this transaction can be fully
@@ -3429,7 +3426,9 @@ ReleasePredicateLocks(bool isCommit, bool isReadOnlySafe)
* transaction to complete before freeing some RAM; correctness of visible
* behavior is not affected.
*/
+ LWLockAcquire(XidGenLock, LW_SHARED);
MySerializableXact->finishedBefore = XidFromFullTransactionId(TransamVariables->nextXid);
+ LWLockRelease(XidGenLock);
/*
* If it's not a commit it's either a rollback or a read-only transaction
--
2.47.0
^ permalink raw reply [nested|flat] 7+ messages in thread
end of thread, other threads:[~2024-10-23 13:31 UTC | newest]
Thread overview: 7+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2024-10-16 15:32 BUG #18658: Assert in SerialAdd() due to race condition PG Bug reporting form <noreply@postgresql.org>
2024-10-17 05:47 ` Andrew Bille <andrewbille@gmail.com>
2024-10-18 08:00 ` Alexander Lakhin <exclusion@gmail.com>
2024-10-18 20:15 ` Heikki Linnakangas <hlinnaka@iki.fi>
2024-10-19 09:00 ` Alexander Lakhin <exclusion@gmail.com>
2024-10-21 08:02 ` Heikki Linnakangas <hlinnaka@iki.fi>
2024-10-23 13:31 ` Maxim Orlov <orlovmg@gmail.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox