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
>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.albe@xxxxxxxxxxx>, wrote:
On Fri, 2023-02-17 at 13:28 -0500, Tom Lane wrote:
Hotmail <crajac66@xxxxxxxxxxx> 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
