explain vs auto_explain

Hi,

Why does auto_explain have extended flags to support nested statements and
triggers whereas explain does not.
the objects of concern have the same ownership and access, so it does not
even sound like a security thing.

or maybe it is just a format/display issue ?
i tried to check the doc, there is no explicit mention of differences
PostgreSQL: Documentation: 17: F.3. auto_explain — log execution plans of
slow queries <https://www.postgresql.org/docs/current/auto-explain.html>

/*

postgres(at)ubuntu:/tmp$ cat db1/postgresql.auto.conf | grep -v '^#'
port=5432
session_preload_libraries = auto_explain
auto_explain.log_min_duration = 0
auto_explain.log_analyze = true
auto_explain.log_buffers = true
auto_explain.log_timing = true
auto_explain.log_verbose = on
auto_explain.log_triggers = on
auto_explain.log_nested_statements = on
postgres(at)ubuntu:/tmp$ psql -p 5432 demo
psql (16.4 (Ubuntu 16.4-0ubuntu0.24.04.1))
Type "help" for help.

demo=# create table t(col1 int primary key, col2 int);
CREATE TABLE
demo=# create table r(col3 int primary key, col1 int references
t(col1) on update cascade on delete cascade); -- foreign table with
col1 having no index
CREATE TABLE
demo=# insert into t select x, x from generate_series(1, 1000000) x;
INSERT 0 1000000
demo=# insert into r select x, (x % 3) + 1 from generate_series(1,
100000) x; -- only 1,2,3 for col1
INSERT 0 100000
demo=# begin;
BEGIN
demo=*# explain (analyze,verbose,buffers) delete from t where col1 <
5; -- when we delete from t, it will show it touches r but will not
show what plan was used to delete data from r. we need to check the
actual plan to figure out why the delete is slow and how to fix it
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------
Delete on public.t (cost=0.42..8.50 rows=0 width=0) (actual
time=0.025..0.026 rows=0 loops=1)
Buffers: shared hit=13
-> Index Scan using t_pkey on public.t (cost=0.42..8.50 rows=4
width=6) (actual time=0.006..0.008 rows=4 loops=1)
Output: ctid
Index Cond: (t.col1 < 5)
Buffers: shared hit=4
Planning:
Buffers: shared hit=7
Planning Time: 0.083 ms
Trigger RI_ConstraintTrigger_a_16475 for constraint r_col1_fkey:
time=46.274 calls=4
Execution Time: 46.460 ms
(11 rows)

demo=*# -- note Trigger RI_ConstraintTrigger_a_16475 for constraint
r_col1_fkey: time=46.274 calls=4 , it made 4 calls to r
demo=*# rollback;
ROLLBACK
demo=#
\q

-------------- why do we not see this via console EXPLAIN, it is still
the same PID

postgres(at)ubuntu:/tmp$ less db1.log
postgres(at)ubuntu:/tmp$ tail -20 db1.log
2024-10-05 18:40:26.429 UTC [2260] LOG: duration: 1.087 ms plan:
Query Text: DELETE FROM ONLY "public"."r" WHERE $1
OPERATOR(pg_catalog.=) "col1"
Query Parameters: $1 = '4'
Delete on public.r (cost=0.00..1693.00 rows=0 width=0)
(actual time=1.086..1.087 rows=0 loops=1)
Buffers: shared hit=443
-> Seq Scan on public.r (cost=0.00..1693.00 rows=1
width=6) (actual time=1.086..1.086 rows=0 loops=1)
Output: ctid
Filter: (4 = r.col1)
Buffers: shared hit=443
2024-10-05 18:40:26.429 UTC [2260] CONTEXT: SQL statement "DELETE
FROM ONLY "public"."r" WHERE $1 OPERATOR(pg_catalog.=) "col1""
2024-10-05 18:40:26.429 UTC [2260] LOG: duration: 46.303 ms plan:
Query Text: explain (analyze,verbose,buffers) delete from t
where col1 < 5;
Delete on public.t (cost=0.42..8.50 rows=0 width=0) (actual
time=0.025..0.026 rows=0 loops=1)
Buffers: shared hit=13
-> Index Scan using t_pkey on public.t (cost=0.42..8.50
rows=4 width=6) (actual time=0.006..0.008 rows=4 loops=1)
Output: ctid
Index Cond: (t.col1 < 5)
Buffers: shared hit=4
Trigger RI_ConstraintTrigger_a_16475 for constraint
r_col1_fkey: time=46.274 calls=4

*/

--
Thanks,
Vijay

Open to work
Resume - Vijaykumar Jain <https://github.com/cabecada>