Hi,
-- commit 9d2d9728b8d546434aade4f9667a59666588edd6
> Author: Michael Paquier <michael@paquier.xyz>
> Date: Thu Jan 26 12:23:16 2023 +0900
>
> Make auto_explain print the query identifier in verbose mode
> ..(snip)..
> While looking at the area, I have noticed that more consolidation
> between EXPLAIN and auto_explain would be in order for the logging of
> the plan duration and the buffer usage. This refactoring is left as a
> future change.
I'm working on this now.
Attached a PoC patch which enables auto_explain to log plan duration and
buffer usage on planning phase.
Last 3 lines are added by this patch:
```
=# set auto_explain.log_min_duration = 0;
=# set auto_explain.log_verbose = on;
=# set auto_explain.log_analyze = on;
=# select * from pg_class;
LOG: 00000: duration: 6.774 ms plan:
Query Text: select * from pg_class;
Seq Scan on pg_catalog.pg_class (cost=0.00..18.12 rows=412
width=273) (actual time=0.009..0.231 rows=412 loops=1)
Output: oid, relname, relnamespace, reltype, reloftype,
relowner, relam, relfilenode, reltablespace, relpages, reltuples,
relallvisible, reltoastrelid, relhasindex, relisshared, relpersistence,
relkind, relnatts, relchecks, relhasrules, relhastriggers,
relhassubclass, relrowsecurity, relforcerowsecurity, relispopulated,
relreplident, relispartition, relrewrite, relfrozenxid, relminmxid,
relacl, reloptions, relpartbound
Buffers: shared hit=14
Query Identifier: 8034096446570639838
Planning
Buffers: shared hit=120
Planning Time: 3.908 ms
```
It adds a planner hook to track the plan duration and buffer usage for
planning.
I'm considering the following points and any comments are welcome:
- Plan duration and buffer usage are saved on PlannedStmt. As far as I
referred totaltime in QueryDesc, adding elements for extensions is not
always prohibited, but I'm wondering it's ok to add them in this case.
- Just as pg_stat_statements made it possible to add planner information
in v13, it may be useful for auto_explain to log planner phase
information, especially plan duration. However, I am not sure to what
extent information about the buffers used in the plan phase would be
useful.
- Plan duration and buffer usage may differ from the output of EXPLAIN
command since EXPLAIN command includes pg_plan_query(), but planner hook
doesn’t.
pg_plan_query() do things for log_planner_stats, debugging and tracing.
- (Future works) Log output concerning buffers should be toggled on/off
by auto_explain.log_buffers. Log output concerning planning should be
toggled on/off by new GUC something like auto_explain.track_planning.
What do you think?
--
Regards,
--
Atsushi Torikoshi
NTT DATA CORPORATION