Content-Type: multipart/mixed; boundary="------------DT3xcgngxcKv59IlijzS7ZGy"
Message-ID: <42227456-1132-4d4e-d6ef-e096668a9a4a@gmail.com>
Date: Wed, 12 Jun 2024 20: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: BF mamba failure
Content-Language: en-US
To: Peter Smith <smithpb2250@gmail.com>, Michael Paquier <michael@paquier.xyz>
Cc: Tom Lane <tgl@sss.pgh.pa.us>, Amit Kapila <amit.kapila16@gmail.com>,
 PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>
References: 
 <CAA4eK1KxuMVyAryz_Vk5yq3ejgKYcL6F45Hj9ZnMNBS-g+PuZg@mail.gmail.com>
 <341870.1679113563@sss.pgh.pa.us>
 <1941b7e2-be7c-9c4c-8505-c0fd05910e9a@gmail.com>
 <CAHut+PvVrjwJm_9ZqnXJk4x9k8dN0dYrV+T5_Rd30BSneDhv1A@mail.gmail.com>
From: Alexander Lakhin <exclusion@gmail.com>
In-Reply-To: 
 <CAHut+PvVrjwJm_9ZqnXJk4x9k8dN0dYrV+T5_Rd30BSneDhv1A@mail.gmail.com>
Archived-At: 
 <https://www.postgresql.org/message-id/42227456-1132-4d4e-d6ef-e096668a9a4a%40gmail.com>
Precedence: bulk

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

Hello hackers,

20.03.2023 09:10, Peter Smith wrote:
>
> Using this I was also able to reproduce the problem. But test failures
> were rare. The make check-world seemed OK, and indeed the
> test_decoding tests would also appear to PASS around 14 out of 15
> times.

I've stumbled upon this assertion failure again during testing following cd312adc5.

This time I've simplified the reproducer to the attached modification.
With this patch applied, `make -s check -C contrib/test_decoding` fails on master as below:
ok 1         - pgstat_rc_1                                14 ms
not ok 2     - pgstat_rc_2                              1351 ms


contrib/test_decoding/output_iso/log/postmaster.log contains:
TRAP: failed Assert("pg_atomic_read_u32(&entry_ref->shared_entry->refcount) == 0"), File: "pgstat_shmem.c", Line: 562, 
PID: 1130928

With extra logging added, I see the following events happening:
1) pgstat_rc_1.setup calls pgstat_create_replslot(), gets
   ReplicationSlotIndex(slot) = 0 and calls
   pgstat_get_entry_ref_locked(PGSTAT_KIND_REPLSLOT, InvalidOid, 0, 0).

2) pgstat_rc_1.s0_get_changes executes pg_logical_slot_get_changes(...)
   and then calls pgstat_gc_entry_refs on shmem_exit() ->
   pgstat_shutdown_hook() ...;
   with the sleep added inside pgstat_release_entry_ref, this backend waits
   after decreasing entry_ref->shared_entry->refcount to 0.

3) pgstat_rc_1.stop removes the replication slot.

4) pgstat_rc_2.setup calls pgstat_create_replslot(), gets
   ReplicationSlotIndex(slot) = 0 and calls
   pgstat_get_entry_ref_locked(PGSTAT_KIND_REPLSLOT, InvalidOid, 0, 0),
   which leads to the call pgstat_reinit_entry(), which increases refcount
   for the same shared_entry as in (1) and (2), and then to the call
   pgstat_acquire_entry_ref(), which increases refcount once more.

5) the backend 2 reaches
Assert(pg_atomic_read_u32(&entry_ref->shared_entry->refcount) == 0),
   which fails due to refcount = 2.

Best regards,
Alexander
--------------DT3xcgngxcKv59IlijzS7ZGy
Content-Type: text/x-patch; charset=UTF-8; name="pgstat_rc-debugging.patch"
Content-Disposition: attachment; filename="pgstat_rc-debugging.patch"
Content-Transfer-Encoding: base64

ZGlmZiAtLWdpdCBhL2NvbnRyaWIvdGVzdF9kZWNvZGluZy9NYWtlZmlsZSBiL2NvbnRyaWIv
dGVzdF9kZWNvZGluZy9NYWtlZmlsZQppbmRleCBjN2NlNjAzNzA2Li42NjBlZWE4N2ViIDEw
MDY0NAotLS0gYS9jb250cmliL3Rlc3RfZGVjb2RpbmcvTWFrZWZpbGUKKysrIGIvY29udHJp
Yi90ZXN0X2RlY29kaW5nL01ha2VmaWxlCkBAIC02LDEwICs2LDEyIEBAIFBHRklMRURFU0Mg
PSAidGVzdF9kZWNvZGluZyAtIGV4YW1wbGUgb2YgYSBsb2dpY2FsIGRlY29kaW5nIG91dHB1
dCBwbHVnaW4iCiBSRUdSRVNTID0gZGRsIHhhY3QgcmV3cml0ZSB0b2FzdCBwZXJtaXNzaW9u
cyBkZWNvZGluZ19pbl94YWN0IFwKIAlkZWNvZGluZ19pbnRvX3JlbCBiaW5hcnkgcHJlcGFy
ZWQgcmVwbG9yaWdpbiB0aW1lIG1lc3NhZ2VzIFwKIAlzcGlsbCBzbG90IHRydW5jYXRlIHN0
cmVhbSBzdGF0cyB0d29waGFzZSB0d29waGFzZV9zdHJlYW0KLUlTT0xBVElPTiA9IG14YWN0
IGRlbGF5ZWRfc3RhcnR1cCBvbmRpc2tfc3RhcnR1cCBjb25jdXJyZW50X2RkbF9kbWwgXAor
WElTT0xBVElPTiA9IG14YWN0IGRlbGF5ZWRfc3RhcnR1cCBvbmRpc2tfc3RhcnR1cCBjb25j
dXJyZW50X2RkbF9kbWwgXAogCW9sZGVzdF94bWluIHNuYXBzaG90X3RyYW5zZmVyIHN1Ynhh
Y3Rfd2l0aG91dF90b3AgY29uY3VycmVudF9zdHJlYW0gXAogCXR3b3BoYXNlX3NuYXBzaG90
IHNsb3RfY3JlYXRpb25fZXJyb3IgY2F0YWxvZ19jaGFuZ2Vfc25hcHNob3QKIAorSVNPTEFU
SU9OID0gcGdzdGF0X3JjXzEgcGdzdGF0X3JjXzIKKwogUkVHUkVTU19PUFRTID0gLS10ZW1w
LWNvbmZpZyAkKHRvcF9zcmNkaXIpL2NvbnRyaWIvdGVzdF9kZWNvZGluZy9sb2dpY2FsLmNv
bmYKIElTT0xBVElPTl9PUFRTID0gLS10ZW1wLWNvbmZpZyAkKHRvcF9zcmNkaXIpL2NvbnRy
aWIvdGVzdF9kZWNvZGluZy9sb2dpY2FsLmNvbmYKIApkaWZmIC0tZ2l0IGEvY29udHJpYi90
ZXN0X2RlY29kaW5nL2V4cGVjdGVkL3Bnc3RhdF9yY18xLm91dCBiL2NvbnRyaWIvdGVzdF9k
ZWNvZGluZy9leHBlY3RlZC9wZ3N0YXRfcmNfMS5vdXQKbmV3IGZpbGUgbW9kZSAxMDA2NDQK
aW5kZXggMDAwMDAwMDAwMC4uODUwYWRmOTkzMAotLS0gL2Rldi9udWxsCisrKyBiL2NvbnRy
aWIvdGVzdF9kZWNvZGluZy9leHBlY3RlZC9wZ3N0YXRfcmNfMS5vdXQKQEAgLTAsMCArMSwx
OCBAQAorUGFyc2VkIHRlc3Qgc3BlYyB3aXRoIDEgc2Vzc2lvbnMKKworc3RhcnRpbmcgcGVy
bXV0YXRpb246IHMwX2dldF9jaGFuZ2VzCis/Y29sdW1uPworLS0tLS0tLS0KK2luaXQgICAg
CisoMSByb3cpCisKK3N0ZXAgczBfZ2V0X2NoYW5nZXM6IFNFTEVDVCBkYXRhIEZST00gcGdf
bG9naWNhbF9zbG90X2dldF9jaGFuZ2VzKCdpc29sYXRpb25fc2xvdCcsIE5VTEwsIE5VTEws
ICdpbmNsdWRlLXhpZHMnLCAnMCcsICdza2lwLWVtcHR5LXhhY3RzJywgJzEnKTsKK2RhdGEK
Ky0tLS0KKygwIHJvd3MpCisKKz9jb2x1bW4/CistLS0tLS0tLQorc3RvcCAgICAKKygxIHJv
dykKKwpkaWZmIC0tZ2l0IGEvY29udHJpYi90ZXN0X2RlY29kaW5nL2V4cGVjdGVkL3Bnc3Rh
dF9yY18yLm91dCBiL2NvbnRyaWIvdGVzdF9kZWNvZGluZy9leHBlY3RlZC9wZ3N0YXRfcmNf
Mi5vdXQKbmV3IGZpbGUgbW9kZSAxMDA2NDQKaW5kZXggMDAwMDAwMDAwMC4uZjhkNGNlODNh
NgotLS0gL2Rldi9udWxsCisrKyBiL2NvbnRyaWIvdGVzdF9kZWNvZGluZy9leHBlY3RlZC9w
Z3N0YXRfcmNfMi5vdXQKQEAgLTAsMCArMSwxOSBAQAorUGFyc2VkIHRlc3Qgc3BlYyB3aXRo
IDEgc2Vzc2lvbnMKKworc3RhcnRpbmcgcGVybXV0YXRpb246IHMwX3NsZWVwCis/Y29sdW1u
PworLS0tLS0tLS0KK2luaXQgICAgCisoMSByb3cpCisKK3N0ZXAgczBfc2xlZXA6IFNFTEVD
VCBwZ19zbGVlcCgxKTsKK3BnX3NsZWVwCistLS0tLS0tLQorICAgICAgICAKKygxIHJvdykK
KworP2NvbHVtbj8KKy0tLS0tLS0tCitzdG9wICAgIAorKDEgcm93KQorCmRpZmYgLS1naXQg
YS9jb250cmliL3Rlc3RfZGVjb2Rpbmcvc3BlY3MvcGdzdGF0X3JjXzEuc3BlYyBiL2NvbnRy
aWIvdGVzdF9kZWNvZGluZy9zcGVjcy9wZ3N0YXRfcmNfMS5zcGVjCm5ldyBmaWxlIG1vZGUg
MTAwNjQ0CmluZGV4IDAwMDAwMDAwMDAuLjdiMDg3MDRhNTUKLS0tIC9kZXYvbnVsbAorKysg
Yi9jb250cmliL3Rlc3RfZGVjb2Rpbmcvc3BlY3MvcGdzdGF0X3JjXzEuc3BlYwpAQCAtMCww
ICsxLDE0IEBACitzZXR1cAoreworICAgIFNFTEVDVCAnaW5pdCcgRlJPTSBwZ19jcmVhdGVf
bG9naWNhbF9yZXBsaWNhdGlvbl9zbG90KCdpc29sYXRpb25fc2xvdCcsICd0ZXN0X2RlY29k
aW5nJyk7IC0tIG11c3QgYmUgZmlyc3Qgd3JpdGUgaW4geGFjdAorfQorCit0ZWFyZG93bgor
eworICAgIFNFTEVDVCAnc3RvcCcgRlJPTSBwZ19kcm9wX3JlcGxpY2F0aW9uX3Nsb3QoJ2lz
b2xhdGlvbl9zbG90Jyk7Cit9CisKK3Nlc3Npb24gInMwIgorc3RlcCAiczBfZ2V0X2NoYW5n
ZXMiIHsgU0VMRUNUIGRhdGEgRlJPTSBwZ19sb2dpY2FsX3Nsb3RfZ2V0X2NoYW5nZXMoJ2lz
b2xhdGlvbl9zbG90JywgTlVMTCwgTlVMTCwgJ2luY2x1ZGUteGlkcycsICcwJywgJ3NraXAt
ZW1wdHkteGFjdHMnLCAnMScpOyB9CisKK3Blcm11dGF0aW9uICJzMF9nZXRfY2hhbmdlcyIK
ZGlmZiAtLWdpdCBhL2NvbnRyaWIvdGVzdF9kZWNvZGluZy9zcGVjcy9wZ3N0YXRfcmNfMi5z
cGVjIGIvY29udHJpYi90ZXN0X2RlY29kaW5nL3NwZWNzL3Bnc3RhdF9yY18yLnNwZWMKbmV3
IGZpbGUgbW9kZSAxMDA2NDQKaW5kZXggMDAwMDAwMDAwMC4uNGU0NTRhZThlOAotLS0gL2Rl
di9udWxsCisrKyBiL2NvbnRyaWIvdGVzdF9kZWNvZGluZy9zcGVjcy9wZ3N0YXRfcmNfMi5z
cGVjCkBAIC0wLDAgKzEsMTQgQEAKK3NldHVwCit7CisgICAgU0VMRUNUICdpbml0JyBGUk9N
IHBnX2NyZWF0ZV9sb2dpY2FsX3JlcGxpY2F0aW9uX3Nsb3QoJ2lzb2xhdGlvbl9zbG90Jywg
J3Rlc3RfZGVjb2RpbmcnKTsgLS0gbXVzdCBiZSBmaXJzdCB3cml0ZSBpbiB4YWN0Cit9CisK
K3RlYXJkb3duCit7CisJU0VMRUNUICdzdG9wJyBGUk9NIHBnX2Ryb3BfcmVwbGljYXRpb25f
c2xvdCgnaXNvbGF0aW9uX3Nsb3QnKTsKK30KKworc2Vzc2lvbiAiczAiCitzdGVwICJzMF9z
bGVlcCIgeyBTRUxFQ1QgcGdfc2xlZXAoMSk7IH0KKworcGVybXV0YXRpb24gInMwX3NsZWVw
IgpkaWZmIC0tZ2l0IGEvc3JjL2JhY2tlbmQvdXRpbHMvYWN0aXZpdHkvcGdzdGF0X3NobWVt
LmMgYi9zcmMvYmFja2VuZC91dGlscy9hY3Rpdml0eS9wZ3N0YXRfc2htZW0uYwppbmRleCBi
MWM5NDM3ZWRjLi5mZTUxN2Q4NWFmIDEwMDY0NAotLS0gYS9zcmMvYmFja2VuZC91dGlscy9h
Y3Rpdml0eS9wZ3N0YXRfc2htZW0uYworKysgYi9zcmMvYmFja2VuZC91dGlscy9hY3Rpdml0
eS9wZ3N0YXRfc2htZW0uYwpAQCAtNTUxLDYgKzU1MSw3IEBAIHBnc3RhdF9yZWxlYXNlX2Vu
dHJ5X3JlZihQZ1N0YXRfSGFzaEtleSBrZXksIFBnU3RhdF9FbnRyeVJlZiAqZW50cnlfcmVm
LAogCQkJLyogb25seSBkcm9wcGVkIGVudHJpZXMgY2FuIHJlYWNoIGEgMCByZWZjb3VudCAq
LwogCQkJQXNzZXJ0KGVudHJ5X3JlZi0+c2hhcmVkX2VudHJ5LT5kcm9wcGVkKTsKIAorcGdf
dXNsZWVwKDEwMDAwMEwpOwogCQkJc2hlbnQgPSBkc2hhc2hfZmluZChwZ1N0YXRMb2NhbC5z
aGFyZWRfaGFzaCwKIAkJCQkJCQkJJmVudHJ5X3JlZi0+c2hhcmVkX2VudHJ5LT5rZXksCiAJ
CQkJCQkJCXRydWUpOwo=

--------------DT3xcgngxcKv59IlijzS7ZGy--