From: | torikoshia <torikoshia(at)oss(dot)nttdata(dot)com> |
---|---|
To: | Pgsql Hackers <pgsql-hackers(at)postgresql(dot)org>, michael(at)paquier(dot)xyz |
Subject: | Allow auto_explain to log plan duration and buffer usage |
Date: | 2023-02-07 13:02:00 |
Message-ID: | 5f9fa94fa0979f567dc4071dc44e442f@oss.nttdata.com |
Views: | Raw Message | Whole Thread | Download mbox | Resend email |
Thread: | |
Lists: | pgsql-hackers |
Hi,
-- commit 9d2d9728b8d546434aade4f9667a59666588edd6
> Author: Michael Paquier <michael(at)paquier(dot)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
Attachment | Content-Type | Size |
---|---|---|
v1-0001-PoC-Enable-auto_explain-to-track-planning-time-an.patch | text/x-diff | 9.9 KB |
From | Date | Subject | |
---|---|---|---|
Next Message | Andrew Dunstan | 2023-02-07 13:17:49 | Re: run pgindent on a regular basis / scripted manner |
Previous Message | Magnus Hagander | 2023-02-07 12:59:53 | Re: run pgindent on a regular basis / scripted manner |