Message-ID: <4d957ea8d55be25b893e485ba0f499be42f162ef.camel@cybertec.at>
Subject: Re: Is it possible to log long running recursive/internal
 postgresql queries?
From: Laurenz Albe <laurenz.albe@cybertec.at>
To: Hotmail <crajac66@hotmail.com>, Tom Lane <tgl@sss.pgh.pa.us>
Cc: pgsql-admin <pgsql-admin@postgresql.org>
Date: Tue, 21 Feb 2023 10:48:09 +0100
In-Reply-To: 
 <MW4PR11MB6838DF07A014B0DCE775898BD7A49@MW4PR11MB6838.namprd11.prod.outlook.com>
References: <ddc10360-1072-4e3d-9584-436cdb7d4d82@Spark>
	 <MW4PR11MB6838BAF2DF065F88CD5EE301D7A19@MW4PR11MB6838.namprd11.prod.outlook.com>
	 <2713826.1676658480@sss.pgh.pa.us>
	 <563e0f91d547c52d7cd2b0d2767290818836f615.camel@cybertec.at>
	 <MW4PR11MB6838DF07A014B0DCE775898BD7A49@MW4PR11MB6838.namprd11.prod.outlook.com>
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
User-Agent: Evolution 3.46.4 (3.46.4-1.fc37) 
MIME-Version: 1.0
Archived-At: 
 <https://www.postgresql.org/message-id/4d957ea8d55be25b893e485ba0f499be42f162ef.camel%40cybertec.at>
Precedence: bulk

On Mon, 2023-02-20 at 07:53 -0800, Hotmail wrote:
> this is what I observed after enabling auto_explain in my test system and=
 tracking nested statements in pg_stat_statements.=C2=A0
>=20
> Server log entries:
>=20
> 2023-02-20 08:38:22 MST [30367]: user=3Dcjackson,db=3Dtest1,app=3Dpsql,cl=
ient=3D[local] CONTEXT: SQL statement "SELECT 1 FROM ONLY "cjackson"."child=
_oids" x WHERE $1 OPERATOR(pg_catalog.=3D)
> "child_oid"::pg_catalog."numeric" FOR KEY SHARE OF x"
> 2023-02-20 08:38:22 MST [30367]: user=3Dcjackson,db=3Dtest1,app=3Dpsql,cl=
ient=3D[local] LOG: duration: 18621.383 ms plan:
> 	Query Text: delete from parent_oids where parent_oid=3D281907;
> 	Delete on parent_oids (cost=3D0.42..2.54 rows=3D1 width=3D6)
> =C2=A0-> Index Scan using pk_parent_oid on parent_oids (cost=3D0.42..2.54=
 rows=3D1 width=3D6)
> =C2=A0Index Cond: (parent_oid =3D '281907'::numeric)
>=20
> pg_stat_statements
>=20
> > select total_time, mean_time, query from pg_stat_statements where mean_=
time > 10000 and query like '%FOR KEY SHARE OF x%' \gx
> -[ RECORD 1 ]------------------------------------------------------------=
----------------------------------------------------------------------
> total_time | 59550.947124
> mean_time | 19850.315708
> query | SELECT $2 FROM ONLY "cjackson"."child_oids" x WHERE $1 OPERATOR(p=
g_catalog.=3D) "child_oid"::pg_catalog."numeric" FOR KEY SHARE OF x

You have some long running transactions that lock the row.
Long running transactions are a problem fo the application (which forgot to=
 close it).
This may be exacerbated by a SELECT ... FOR UPDATE which conflicts with FOR=
 KEY SHARE.
Often, SELECT ... FOR NO KEY UPDATE is the better choice.

Yours,
Laurenz Albe