MIME-Version: 1.0
References: <CANtu0oiTgFW47QgpTwrMOVm3Bq4N0Y5bjvTy5sP0gYWLQuVgjw@mail.gmail.com>
 <CANtu0ojbx6=esP8euQgzD1CN6tigTQvDmupwEmLTHZT=6_yx_A@mail.gmail.com>
 <CANtu0oiXq548OM_RqBbDQ0dgqtKLAg=x_Fu4eOGRNW0tBsNj_Q@mail.gmail.com>
 <CANtu0oiBAcVnzYYETbWY+2gFXUeAx8BKArjnFco4LeAHfH38Sw@mail.gmail.com> <Z0lL3GKCyijL8HcI@paquier.xyz>
In-Reply-To: <Z0lL3GKCyijL8HcI@paquier.xyz>
From: Michail Nikolaev <michail.nikolaev@gmail.com>
Date: Fri, 29 Nov 2024 12:55:00 +0100
Message-ID: <CANtu0ogaPNFbj=8qQnSW9u2-voVwSfM65WUc7xXxFwr9feGmLw@mail.gmail.com>
Subject: Re: Strange assertion in procarray.c
To: Michael Paquier <michael@paquier.xyz>
Cc: PostgreSQL Hackers <pgsql-hackers@postgresql.org>, nathan@postgresql.org, 
	Heikki Linnakangas <hlinnaka@iki.fi>
Content-Type: multipart/alternative; boundary="00000000000017fe7106280be4b4"
Archived-At: <https://www.postgresql.org/message-id/CANtu0ogaPNFbj%3D8qQnSW9u2-voVwSfM65WUc7xXxFwr9feGmLw%40mail.gmail.com>
Precedence: bulk

--00000000000017fe7106280be4b4
Content-Type: text/plain; charset="UTF-8"

Hello, Michael!

> I fail to see how this is related?  The original issue was that this
> was impossible to run safely concurrently, but now we have the
> facilities able to do so.  There are a few cases where using a wait
> point has limits, for example outside a transaction context for some
> of the processes, but that has not really been an issue up to now.

I encountered this issue while trying to stabilize tests for [0].

Tests were crashing during the installcheck with assertion of that thread.
I have spent time trying to identify the root cause - injection points and
the way it may affect another tests even if them set to be executed locally.

In the spec, the backend performs the following:

    SELECT injection_points_set_local();
    SELECT injection_points_attach('invalidate_catalog_snapshot_end',
'wait');

That's all - we don't even execute any command that would trigger the wait
condition.

Meanwhile, three different backends are attempting to test SERIALIZABLE
isolation without any injection points.
Initially, this was a separate 'two-ids' test executed in parallel during
installcheck,
but I incorporated it into the reproducer spec for simplicity.

> Isn't that pointing to an actual bug with serializable transactions?

No, let me explain.

> What you are telling here is that there is a race condition where it
> is possible to trigger an assertion failure when finishing a session
> while another one is waiting on an invalidation, if there's in the mix
> a read/write dependency error.

Actually, no backend is waiting for invalidation in this case.

Here's the sequence of events:

* The s4 backend creates a local injection point but performs no further
actions. The injection point is marked as local for that pid.
* Three other backends proceed with their serializable snapshot operations.
* s2 determines it cannot commit and correctly decides to abort the
transaction.
* s2 begins releasing resources:

        ResourceOwnerReleaseInternal resowner.c:694 <--- NOTE: After
starting the release process, by calling this function, no new
        ResourceOwnerRelease resowner.c:654                    resources
can be remembered in the resource owner.
        AbortTransaction xact.c:2960
        AbortCurrentTransactionInternal xact.c:3531
        AbortCurrentTransaction xact.c:3449
        PostgresMain postgres.c:4513
        BackendMain backend_startup.c:107
        postmaster_child_launch launch_backend.c:274
        BackendStartup postmaster.c:3377
        ServerLoop postmaster.c:1663
        PostmasterMain postmaster.c:1361
        main main.c:196

* During transaction abort, s2 invalidates its catalog snapshot with this
stack trace:

        InvalidateCatalogSnapshot snapmgr.c:430
        AtEOXact_Snapshot snapmgr.c:1050
        CleanupTransaction xact.c:3016
        AbortCurrentTransactionInternal xact.c:3532
        AbortCurrentTransaction xact.c:3449
        PostgresMain postgres.c:4513
        BackendMain backend_startup.c:107
        postmaster_child_launch launch_backend.c:274
        BackendStartup postmaster.c:3377
        ServerLoop postmaster.c:1663
        PostmasterMain postmaster.c:1361
        main main.c:196

* Consequently, s2 encounters
INJECTION_POINT("invalidate_catalog_snapshot_end");
* Although invalidate_catalog_snapshot_end is set to 'wait' only for s4, s2
enters the injection_wait handler
* Since this is s2's first interaction with injection points (as
injection_points isn't in shared_preload_libraries), it calls
injection_init_shmem
* Here, GetNamedDSMSegment is called - this is new infrastructure for
initializing shared memory for extensions without shared_preload_libraries,
committed by Nathan [1]
* GetNamedDSMSegment attempts to attach to memory and triggers the
assertion:

        if (owner->releasing)
            elog(ERROR, "ResourceOwnerEnlarge called after release
started");

        ResourceOwnerEnlarge resowner.c:449
        dsm_create_descriptor dsm.c:1206
        dsm_attach dsm.c:696
        dsa_attach dsa.c:519
        init_dsm_registry dsm_registry.c:115
        GetNamedDSMSegment dsm_registry.c:156
        injection_init_shmem injection_points.c:185
        injection_wait injection_points.c:277
        InjectionPointRun injection_point.c:551
        InvalidateCatalogSnapshot snapmgr.c:430
        AtEOXact_Snapshot snapmgr.c:1050
        CleanupTransaction xact.c:3016
        AbortCurrentTransactionInternal xact.c:3532
        AbortCurrentTransaction xact.c:3449
        PostgresMain postgres.c:4513
        BackendMain backend_startup.c:107
        postmaster_child_launch launch_backend.c:274
        BackendStartup postmaster.c:3377
        ServerLoop postmaster.c:1663
        PostmasterMain postmaster.c:1361
        main main.c:196

* This assertion during transaction abort triggers another abort call (this
could be improved):

        ProcArrayEndTransaction procarray.c:677
        AbortTransaction xact.c:2946
        AbortCurrentTransactionInternal xact.c:3531
        AbortCurrentTransaction xact.c:3449
        PostgresMain postgres.c:4513 <--------------- exception handler here
        BackendMain backend_startup.c:107
        postmaster_child_launch launch_backend.c:274
        BackendStartup postmaster.c:3377
        ServerLoop postmaster.c:1663
        PostmasterMain postmaster.c:1361
        main main.c:196

This isn't the same abort attempt - it's the second one, which triggers
Assert(TransactionIdIsValid(proc->xid));

In summary:

Each code component functions correctly in isolation
However, when an injection point registered as local by one backend causes
another backend to register resources (and potentially other operations),
it can lead to difficult-to-diagnose issues

I see several potential solutions:

* Add injection_points to shared_preload_libraries for all tests
* Implement a mechanism to call prev_shmem_startup_hook for libraries
outside shared_preload_libraries
* Modify GetNamedDSMSegment's behavior
* Run all injection_points tests in an isolated environment

In my opinion, the last option seems most appropriate.

Best regards,
Mikhail.

[0]: https://commitfest.postgresql.org/50/5160/
[1]:
https://github.com/postgres/postgres/commit/8b2bcf3f287c79eaebf724cba57e5ff664b01e06

--00000000000017fe7106280be4b4
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

<div dir=3D"ltr">Hello, Michael!<br><br>&gt; I fail to see how this is rela=
ted?=C2=A0 The original issue was that this<br>&gt; was impossible to run s=
afely concurrently, but now we have the<br>&gt; facilities able to do so.=
=C2=A0 There are a few cases where using a wait<br>&gt; point has limits, f=
or example outside a transaction context for some<br>&gt; of the processes,=
 but that has not really been an issue up to now.<br><br>I encountered this=
 issue while trying to stabilize tests for [0].<br><br>Tests were crashing =
during the installcheck with assertion of that thread.<br>I have spent time=
 trying to identify the root cause - injection points and<br>the way it may=
 affect another tests even if them set to be executed locally.<br><br>In th=
e spec, the backend performs the following:<br><br>=C2=A0 =C2=A0 SELECT inj=
ection_points_set_local();<br>=C2=A0 =C2=A0 SELECT injection_points_attach(=
&#39;invalidate_catalog_snapshot_end&#39;, &#39;wait&#39;);<br><br>That&#39=
;s all - we don&#39;t even execute any command that would trigger the wait =
condition.<br><br>Meanwhile, three different backends are attempting to tes=
t SERIALIZABLE isolation without any injection points.<br>Initially, this w=
as a separate &#39;two-ids&#39; test executed in parallel during installche=
ck,<br>but I incorporated it into the reproducer spec for simplicity.<br><b=
r>&gt; Isn&#39;t that pointing to an actual bug with serializable transacti=
ons?<br><br>No, let me explain.<br><br>&gt; What you are telling here is th=
at there is a race condition where it<br>&gt; is possible to trigger an ass=
ertion failure when finishing a session<br>&gt; while another one is waitin=
g on an invalidation, if there&#39;s in the mix<br>&gt; a read/write depend=
ency error.<br><br>Actually, no backend is waiting for invalidation in this=
 case.<br><br>Here&#39;s the sequence of events:<br><br>* The s4 backend cr=
eates a local injection point but performs no further actions. The injectio=
n point is marked as local for that pid.<br>* Three other backends proceed =
with their serializable snapshot operations.<br>* s2 determines it cannot c=
ommit and correctly decides to abort the transaction.<br>* s2 begins releas=
ing resources:<br><br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 ResourceOwnerReleaseInter=
nal resowner.c:694 &lt;--- NOTE: After starting the release process, by cal=
ling this function, no new<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 ResourceOwnerRele=
ase resowner.c:654 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =
=C2=A0 =C2=A0resources can be remembered in the resource owner.<br>=C2=A0 =
=C2=A0 =C2=A0 =C2=A0 AbortTransaction xact.c:2960<br>=C2=A0 =C2=A0 =C2=A0 =
=C2=A0 AbortCurrentTransactionInternal xact.c:3531<br>=C2=A0 =C2=A0 =C2=A0 =
=C2=A0 AbortCurrentTransaction xact.c:3449<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 P=
ostgresMain postgres.c:4513<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 BackendMain back=
end_startup.c:107<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 postmaster_child_launch la=
unch_backend.c:274<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 BackendStartup postmaster=
.c:3377<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 ServerLoop postmaster.c:1663<br>=C2=
=A0 =C2=A0 =C2=A0 =C2=A0 PostmasterMain postmaster.c:1361<br>=C2=A0 =C2=A0 =
=C2=A0 =C2=A0 main main.c:196<br><br>* During transaction abort, s2 invalid=
ates its catalog snapshot with this stack trace:<br><br>=C2=A0 =C2=A0 =C2=
=A0 =C2=A0 InvalidateCatalogSnapshot snapmgr.c:430<br>=C2=A0 =C2=A0 =C2=A0 =
=C2=A0 AtEOXact_Snapshot snapmgr.c:1050<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Clea=
nupTransaction xact.c:3016<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 AbortCurrentTrans=
actionInternal xact.c:3532<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 AbortCurrentTrans=
action xact.c:3449<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 PostgresMain postgres.c:4=
513<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 BackendMain backend_startup.c:107<br>=C2=
=A0 =C2=A0 =C2=A0 =C2=A0 postmaster_child_launch launch_backend.c:274<br>=
=C2=A0 =C2=A0 =C2=A0 =C2=A0 BackendStartup postmaster.c:3377<br>=C2=A0 =C2=
=A0 =C2=A0 =C2=A0 ServerLoop postmaster.c:1663<br>=C2=A0 =C2=A0 =C2=A0 =C2=
=A0 PostmasterMain postmaster.c:1361<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 main ma=
in.c:196<br><br>* Consequently, s2 encounters INJECTION_POINT(&quot;invalid=
ate_catalog_snapshot_end&quot;);<br>* Although invalidate_catalog_snapshot_=
end is set to &#39;wait&#39; only for s4, s2 enters the injection_wait hand=
ler<br>* Since this is s2&#39;s first interaction with injection points (as=
 injection_points isn&#39;t in shared_preload_libraries), it calls injectio=
n_init_shmem<br>* Here, GetNamedDSMSegment is called - this is new infrastr=
ucture for initializing shared memory for extensions without shared_preload=
_libraries, committed by Nathan [1]<br>* GetNamedDSMSegment attempts to att=
ach to memory and triggers the assertion:<br><br>=C2=A0 =C2=A0 =C2=A0 =C2=
=A0 if (owner-&gt;releasing)<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 e=
log(ERROR, &quot;ResourceOwnerEnlarge called after release started&quot;);<=
br><br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 ResourceOwnerEnlarge resowner.c:449<br>=
=C2=A0 =C2=A0 =C2=A0 =C2=A0 dsm_create_descriptor dsm.c:1206<br>=C2=A0 =C2=
=A0 =C2=A0 =C2=A0 dsm_attach dsm.c:696<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 dsa_a=
ttach dsa.c:519<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 init_dsm_registry dsm_regist=
ry.c:115<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 GetNamedDSMSegment dsm_registry.c:1=
56<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 injection_init_shmem injection_points.c:1=
85<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 injection_wait injection_points.c:277<br>=
=C2=A0 =C2=A0 =C2=A0 =C2=A0 InjectionPointRun injection_point.c:551<br>=C2=
=A0 =C2=A0 =C2=A0 =C2=A0 InvalidateCatalogSnapshot snapmgr.c:430<br>=C2=A0 =
=C2=A0 =C2=A0 =C2=A0 AtEOXact_Snapshot snapmgr.c:1050<br>=C2=A0 =C2=A0 =C2=
=A0 =C2=A0 CleanupTransaction xact.c:3016<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Ab=
ortCurrentTransactionInternal xact.c:3532<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Ab=
ortCurrentTransaction xact.c:3449<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 PostgresMa=
in postgres.c:4513<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 BackendMain backend_start=
up.c:107<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 postmaster_child_launch launch_back=
end.c:274<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 BackendStartup postmaster.c:3377<b=
r>=C2=A0 =C2=A0 =C2=A0 =C2=A0 ServerLoop postmaster.c:1663<br>=C2=A0 =C2=A0=
 =C2=A0 =C2=A0 PostmasterMain postmaster.c:1361<br>=C2=A0 =C2=A0 =C2=A0 =C2=
=A0 main main.c:196<br><br>* This assertion during transaction abort trigge=
rs another abort call (this could be improved):<br><br>=C2=A0 =C2=A0 =C2=A0=
 =C2=A0 ProcArrayEndTransaction procarray.c:677<br>=C2=A0 =C2=A0 =C2=A0 =C2=
=A0 AbortTransaction xact.c:2946<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 AbortCurren=
tTransactionInternal xact.c:3531<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 AbortCurren=
tTransaction xact.c:3449<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 PostgresMain postgr=
es.c:4513 &lt;--------------- exception handler here<br>=C2=A0 =C2=A0 =C2=
=A0 =C2=A0 BackendMain backend_startup.c:107<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0=
 postmaster_child_launch launch_backend.c:274<br>=C2=A0 =C2=A0 =C2=A0 =C2=
=A0 BackendStartup postmaster.c:3377<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 ServerL=
oop postmaster.c:1663<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 PostmasterMain postmas=
ter.c:1361<br>=C2=A0 =C2=A0 =C2=A0 =C2=A0 main main.c:196<br><br>This isn&#=
39;t the same abort attempt - it&#39;s the second one, which triggers Asser=
t(TransactionIdIsValid(proc-&gt;xid));<br><br>In summary:<br><br>Each code =
component functions correctly in isolation<br>However, when an injection po=
int registered as local by one backend causes another backend to register r=
esources (and potentially other operations),<br>it can lead to difficult-to=
-diagnose issues<br><br>I see several potential solutions:<br><br>* Add inj=
ection_points to shared_preload_libraries for all tests<br>* Implement a me=
chanism to call prev_shmem_startup_hook for libraries outside shared_preloa=
d_libraries<br>* Modify GetNamedDSMSegment&#39;s behavior<br>* Run all inje=
ction_points tests in an isolated environment<br><br>In my opinion, the las=
t option seems most appropriate.<br><br>Best regards,<br>Mikhail.<br><br>[0=
]: <a href=3D"https://commitfest.postgresql.org/50/5160/">https://commitfes=
t.postgresql.org/50/5160/</a><br>[1]: <a href=3D"https://github.com/postgre=
s/postgres/commit/8b2bcf3f287c79eaebf724cba57e5ff664b01e06">https://github.=
com/postgres/postgres/commit/8b2bcf3f287c79eaebf724cba57e5ff664b01e06</a></=
div>

--00000000000017fe7106280be4b4--