Content-Type: multipart/mixed; boundary="------------y07G0E8tjQ1tQBaZQFQD6L03"
Message-ID: <5634e3e1-6e82-b883-ac87-52d7e926a04d@gmail.com>
Date: Fri, 18 Oct 2024 11:00:00 +0300
MIME-Version: 1.0
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101
 Thunderbird/102.4.2
Subject: Re: BUG #18658: Assert in SerialAdd() due to race condition
Content-Language: en-US
To: Andrew Bille <andrewbille@gmail.com>, pgsql-bugs@lists.postgresql.org
References: <18658-7dab125ec688c70b@postgresql.org>
 <CAJnzarxBO18Ha==H3hX28yz2zd7cVuasXv1wxyJ7ERd9DzJf=Q@mail.gmail.com>
From: Alexander Lakhin <exclusion@gmail.com>
In-Reply-To: 
 <CAJnzarxBO18Ha==H3hX28yz2zd7cVuasXv1wxyJ7ERd9DzJf=Q@mail.gmail.com>
Archived-At: 
 <https://www.postgresql.org/message-id/5634e3e1-6e82-b883-ac87-52d7e926a04d%40gmail.com>
Precedence: bulk

This is a multi-part message in MIME format.
--------------y07G0E8tjQ1tQBaZQFQD6L03
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 8bit

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
--------------y07G0E8tjQ1tQBaZQFQD6L03
Content-Type: text/x-patch; charset=UTF-8; name="SLRU-debugging.patch"
Content-Disposition: attachment; filename="SLRU-debugging.patch"
Content-Transfer-Encoding: base64

ZGlmZiAtLWdpdCBhL3NyYy9iYWNrZW5kL2FjY2Vzcy90cmFuc2FtL3NscnUuYyBiL3NyYy9i
YWNrZW5kL2FjY2Vzcy90cmFuc2FtL3NscnUuYwppbmRleCA4ODllZmYxODE1Li4zZjBmYWIw
NTJkIDEwMDY0NAotLS0gYS9zcmMvYmFja2VuZC9hY2Nlc3MvdHJhbnNhbS9zbHJ1LmMKKysr
IGIvc3JjL2JhY2tlbmQvYWNjZXNzL3RyYW5zYW0vc2xydS5jCkBAIC01NDAsNiArNTQwLDgg
QEAgU2ltcGxlTHJ1UmVhZFBhZ2UoU2xydUN0bCBjdGwsIGludDY0IHBhZ2VubywgYm9vbCB3
cml0ZV9vaywKIAogCQkJcmV0dXJuIHNsb3RubzsKIAkJfQorZWxvZyhMT0csICIhISFTaW1w
bGVMcnVSZWFkUGFnZXwgcGFnZW5vOiAlbGQsIHNsb3RubzogJWQsIHNoYXJlZC0+cGFnZV9z
dGF0dXNbc2xvdG5vXTogJWQsIHNoYXJlZC0+cGFnZV9udW1iZXJbc2xvdG5vXTogJWxkLCBz
aGFyZWQtPnBhZ2VfZGlydHlbc2xvdG5vXTogJWQiLAorcGFnZW5vLCBzbG90bm8sIHNoYXJl
ZC0+cGFnZV9zdGF0dXNbc2xvdG5vXSwgc2hhcmVkLT5wYWdlX251bWJlcltzbG90bm9dLCBz
aGFyZWQtPnBhZ2VfZGlydHlbc2xvdG5vXSk7CiAKIAkJLyogV2UgZm91bmQgbm8gbWF0Y2g7
IGFzc2VydCB3ZSBzZWxlY3RlZCBhIGZyZWVhYmxlIHNsb3QgKi8KIAkJQXNzZXJ0KHNoYXJl
ZC0+cGFnZV9zdGF0dXNbc2xvdG5vXSA9PSBTTFJVX1BBR0VfRU1QVFkgfHwKQEAgLTEwNTcs
NyArMTA1OSw3IEBAIFNscnVSZXBvcnRJT0Vycm9yKFNscnVDdGwgY3RsLCBpbnQ2NCBwYWdl
bm8sIFRyYW5zYWN0aW9uSWQgeGlkKQogCXN3aXRjaCAoc2xydV9lcnJjYXVzZSkKIAl7CiAJ
CWNhc2UgU0xSVV9PUEVOX0ZBSUxFRDoKLQkJCWVyZXBvcnQoRVJST1IsCisJCQllcmVwb3J0
KFBBTklDLAogCQkJCQkoZXJyY29kZV9mb3JfZmlsZV9hY2Nlc3MoKSwKIAkJCQkJIGVycm1z
ZygiY291bGQgbm90IGFjY2VzcyBzdGF0dXMgb2YgdHJhbnNhY3Rpb24gJXUiLCB4aWQpLAog
CQkJCQkgZXJyZGV0YWlsKCJDb3VsZCBub3Qgb3BlbiBmaWxlIFwiJXNcIjogJW0uIiwgcGF0
aCkpKTsKZGlmZiAtLWdpdCBhL3NyYy9iYWNrZW5kL3N0b3JhZ2UvbG1nci9wcmVkaWNhdGUu
YyBiL3NyYy9iYWNrZW5kL3N0b3JhZ2UvbG1nci9wcmVkaWNhdGUuYwppbmRleCBlMjRhMGYy
ZmRiLi4wM2JlNGJiM2QyIDEwMDY0NAotLS0gYS9zcmMvYmFja2VuZC9zdG9yYWdlL2xtZ3Iv
cHJlZGljYXRlLmMKKysrIGIvc3JjL2JhY2tlbmQvc3RvcmFnZS9sbWdyL3ByZWRpY2F0ZS5j
CkBAIC04OTQsMTIgKzg5NCwxNiBAQCBTZXJpYWxBZGQoVHJhbnNhY3Rpb25JZCB4aWQsIFNl
ckNvbW1pdFNlcU5vIG1pbkNvbmZsaWN0Q29tbWl0U2VxTm8pCiAJewogCQlmaXJzdFplcm9Q
YWdlID0gU2VyaWFsUGFnZSh0YWlsWGlkKTsKIAkJaXNOZXdQYWdlID0gdHJ1ZTsKK2Vsb2co
TE9HLCAiISEhU2VyaWFsQWRkfCB4aWQ6ICVkLCBzZXJpYWxDb250cm9sLT5oZWFkUGFnZTog
JWxkLCB0YWlsWGlkOiAlZCwgU0VSSUFMX0VOVFJJRVNQRVJQQUdFOiAlbGQsIGZpcnN0WmVy
b1BhZ2U6ICVsZCwgdGFyZ2V0UGFnZTogJWxkLCBpc05ld1BhZ2U6ICVkIiwKK3hpZCwgc2Vy
aWFsQ29udHJvbC0+aGVhZFBhZ2UsIHRhaWxYaWQsIFNFUklBTF9FTlRSSUVTUEVSUEFHRSwg
Zmlyc3RaZXJvUGFnZSwgdGFyZ2V0UGFnZSwgaXNOZXdQYWdlKTsKIAl9CiAJZWxzZQogCXsK
IAkJZmlyc3RaZXJvUGFnZSA9IFNlcmlhbE5leHRQYWdlKHNlcmlhbENvbnRyb2wtPmhlYWRQ
YWdlKTsKIAkJaXNOZXdQYWdlID0gU2VyaWFsUGFnZVByZWNlZGVzTG9naWNhbGx5KHNlcmlh
bENvbnRyb2wtPmhlYWRQYWdlLAogCQkJCQkJCQkJCQkJdGFyZ2V0UGFnZSk7CitlbG9nKExP
RywgIiEhIVNlcmlhbEFkZHwgeGlkOiAlZCwgc2VyaWFsQ29udHJvbC0+aGVhZFBhZ2U6ICVs
ZCwgZmlyc3RaZXJvUGFnZTogJWxkLCB0YXJnZXRQYWdlOiAlbGQsIGlzTmV3UGFnZTogJWQi
LAoreGlkLCBzZXJpYWxDb250cm9sLT5oZWFkUGFnZSwgZmlyc3RaZXJvUGFnZSwgdGFyZ2V0
UGFnZSwgaXNOZXdQYWdlKTsKIAl9CiAKIAlpZiAoIVRyYW5zYWN0aW9uSWRJc1ZhbGlkKHNl
cmlhbENvbnRyb2wtPmhlYWRYaWQpCkBAIC05MTYsNiArOTIwLDcgQEAgU2VyaWFsQWRkKFRy
YW5zYWN0aW9uSWQgeGlkLCBTZXJDb21taXRTZXFObyBtaW5Db25mbGljdENvbW1pdFNlcU5v
KQogCQkJbG9jayA9IFNpbXBsZUxydUdldEJhbmtMb2NrKFNlcmlhbFNscnVDdGwsIGZpcnN0
WmVyb1BhZ2UpOwogCQkJTFdMb2NrQWNxdWlyZShsb2NrLCBMV19FWENMVVNJVkUpOwogCQkJ
c2xvdG5vID0gU2ltcGxlTHJ1WmVyb1BhZ2UoU2VyaWFsU2xydUN0bCwgZmlyc3RaZXJvUGFn
ZSk7CitlbG9nKExPRywgIiEhIVNlcmlhbEFkZHwgYWZ0ZXIgU2ltcGxlTHJ1WmVyb1BhZ2Uo
KSwgZmlyc3RaZXJvUGFnZTogJWxkLCBzbG90bm86ICVkIiwgZmlyc3RaZXJvUGFnZSwgc2xv
dG5vKTsKIAkJCWlmIChmaXJzdFplcm9QYWdlID09IHRhcmdldFBhZ2UpCiAJCQkJYnJlYWs7
CiAJCQlmaXJzdFplcm9QYWdlID0gU2VyaWFsTmV4dFBhZ2UoZmlyc3RaZXJvUGFnZSk7CkBA
IC0xMDIyLDYgKzEwMjcsNyBAQCBTZXJpYWxTZXRBY3RpdmVTZXJYbWluKFRyYW5zYWN0aW9u
SWQgeGlkKQogCQkgICB8fCBUcmFuc2FjdGlvbklkRm9sbG93cyh4aWQsIHNlcmlhbENvbnRy
b2wtPnRhaWxYaWQpKTsKIAogCXNlcmlhbENvbnRyb2wtPnRhaWxYaWQgPSB4aWQ7CitlbG9n
KExPRywgIiEhIVNlcmlhbFNldEFjdGl2ZVNlclhtaW58IHNlcmlhbENvbnRyb2wtPnRhaWxY
aWQ6ICVkIiwgc2VyaWFsQ29udHJvbC0+dGFpbFhpZCk7CiAKIAlMV0xvY2tSZWxlYXNlKFNl
cmlhbENvbnRyb2xMb2NrKTsKIH0K

--------------y07G0E8tjQ1tQBaZQFQD6L03--