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

Thanks for the guidance. FYI, this is what I observed after enabling auto_explain in my test system and tracking nested statements in pg_stat_statements.

>load 'auto_explain';
LOAD
>set auto_explain.log_min_duration=10000;
SET
>set auto_explain.log_nested_statements=true;
set

>delete from parent_oids where parent_oid=281907;
DELETE 1
Time: 18554.906 ms (00:18.555)

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

Craig
On Feb 20, 2023 at 5:52 AM -0800, Laurenz Albe <laurenz(dot)albe(at)cybertec(dot)at>, wrote:
> On Fri, 2023-02-17 at 13:28 -0500, Tom Lane wrote:
> > Hotmail <crajac66(at)hotmail(dot)com> writes:
> > > If it is possible to log long running internal queries as outlined above any guidance would be appreciated.
> >
> > Either auto_explain or pg_stat_statements could have helped you
> > with that, I think.  I believe (without having tested) that if
> > configured to track nested statements they would perceive the
> > FK enforcement query as a separate statement to track.
>
> Yes, they do.
> You need to set "auto_explain.log_nested_statements = on" or
> "pg_stat_statements.track = all".
>
> Yours,
> Laurenz Albe