Allow auto_explain to log plan duration and buffer usage

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

Browse pgsql-hackers by date

  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