Re: Is it possible to log long running recursive/internal postgresql queries?

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. 
>
> Server log entries:
>
> 2023-02-20 08:38:22 MST [30367]: user=cjackson,db=test1,app=psql,client=[local] CONTEXT: SQL statement "SELECT 1 FROM ONLY "cjackson"."child_oids" x WHERE $1 OPERATOR(pg_catalog.=)
> "child_oid"::pg_catalog."numeric" FOR KEY SHARE OF x"
> 2023-02-20 08:38:22 MST [30367]: user=cjackson,db=test1,app=psql,client=[local] LOG: duration: 18621.383 ms plan:
> Query Text: delete from parent_oids where parent_oid=281907;
> Delete on parent_oids (cost=0.42..2.54 rows=1 width=6)
>  -> Index Scan using pk_parent_oid on parent_oids (cost=0.42..2.54 rows=1 width=6)
>  Index Cond: (parent_oid = '281907'::numeric)
>
> pg_stat_statements
>
> > 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(pg_catalog.=) "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