Hi,
-- commit 9d2d9728b8d546434aade4f9667a59666588edd6
Author: Michael Paquier <mich...@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
From a0997f139cd964ca0368fe3650e5ad1ce1f5e16e Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <torikos...@oss.nttdata.com>
Date: Tue, 7 Feb 2023 19:49:45 +0900
Subject: [PATCH v1] [PoC] Enable auto_explain to track planning time and
buffer usage
---
contrib/auto_explain/auto_explain.c | 82 ++++++++++++++++++++++++++-
src/backend/commands/explain.c | 36 ++++++------
src/backend/nodes/gen_node_support.pl | 4 ++
src/backend/optimizer/plan/planner.c | 2 +
src/include/commands/explain.h | 4 +-
src/include/nodes/plannodes.h | 6 ++
6 files changed, 114 insertions(+), 20 deletions(-)
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index c3ac27ae99..ea5c2949d0 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -20,6 +20,7 @@
#include "executor/instrument.h"
#include "jit/jit.h"
#include "nodes/params.h"
+#include "optimizer/planner.h"
#include "utils/guc.h"
PG_MODULE_MAGIC;
@@ -64,20 +65,28 @@ static const struct config_enum_entry loglevel_options[] = {
/* Current nesting depth of ExecutorRun calls */
static int nesting_level = 0;
+/* Current nesting depth of planner calls */
+static int plan_nesting_level = 0;
+
/* Is the current top-level query to be sampled? */
static bool current_query_sampled = false;
#define auto_explain_enabled() \
(auto_explain_log_min_duration >= 0 && \
- (nesting_level == 0 || auto_explain_log_nested_statements) && \
+ ((nesting_level == 0 || plan_nesting_level == 0) || \
+ auto_explain_log_nested_statements) && \
current_query_sampled)
/* Saved hook values in case of unload */
+static planner_hook_type prev_planner_hook = NULL;
static ExecutorStart_hook_type prev_ExecutorStart = NULL;
static ExecutorRun_hook_type prev_ExecutorRun = NULL;
static ExecutorFinish_hook_type prev_ExecutorFinish = NULL;
static ExecutorEnd_hook_type prev_ExecutorEnd = NULL;
+static PlannedStmt *explain_Planner(Query *parse, const char *query_string,
+ int cursorOptions,
+ ParamListInfo boundParams);
static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags);
static void explain_ExecutorRun(QueryDesc *queryDesc,
ScanDirection direction,
@@ -245,6 +254,8 @@ _PG_init(void)
MarkGUCPrefixReserved("auto_explain");
/* Install hooks. */
+ prev_planner_hook = planner_hook;
+ planner_hook = explain_Planner;
prev_ExecutorStart = ExecutorStart_hook;
ExecutorStart_hook = explain_ExecutorStart;
prev_ExecutorRun = ExecutorRun_hook;
@@ -255,6 +266,72 @@ _PG_init(void)
ExecutorEnd_hook = explain_ExecutorEnd;
}
+/*
+ * Planner hook: track nesting level and start up logging if needed
+ */
+static PlannedStmt *
+explain_Planner(Query *parse, const char *query_string, int cursorOptions, ParamListInfo boundParams)
+{
+ PlannedStmt *result;
+
+ if (plan_nesting_level == 0)
+ {
+ if (auto_explain_log_min_duration >= 0 && !IsParallelWorker())
+ current_query_sampled = (pg_prng_double(&pg_global_prng_state) < auto_explain_sample_rate);
+ else
+ current_query_sampled = false;
+ }
+
+ if (auto_explain_enabled())
+ {
+ // TODO: Log output concerning buffers should be toggled on/off by auto_explain.log_buffers.
+ // TODO: Log output concerning planning should be toggled on/off by auto_explain.track_planning.
+
+ instr_time start;
+ instr_time duration;
+ BufferUsage bufusage_start;
+
+ /* We need to track buffer usage as the planner can access them. */
+ bufusage_start = pgBufferUsage;
+
+ INSTR_TIME_SET_CURRENT(start);
+
+ plan_nesting_level++;
+ PG_TRY();
+ {
+ if (prev_planner_hook)
+ result = prev_planner_hook(parse, query_string, cursorOptions,
+ boundParams);
+ else
+ result = standard_planner(parse, query_string, cursorOptions,
+ boundParams);
+ }
+ PG_FINALLY();
+ {
+ plan_nesting_level--;
+ }
+ PG_END_TRY();
+
+ INSTR_TIME_SET_CURRENT(duration);
+ INSTR_TIME_SUBTRACT(duration, start);
+
+ result->plantime = duration;
+ /* calc differences of buffer counters and save it */
+ BufferUsageAccumDiff(&result->bufusage, &pgBufferUsage, &bufusage_start);
+ }
+ else
+ {
+ if (prev_planner_hook)
+ result = prev_planner_hook(parse, query_string, cursorOptions,
+ boundParams);
+ else
+ result = standard_planner(parse, query_string, cursorOptions,
+ boundParams);
+ }
+
+ return result;
+}
+
/*
* ExecutorStart hook: start up logging if needed
*/
@@ -402,7 +479,8 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
ExplainBeginOutput(es);
ExplainQueryText(es, queryDesc);
ExplainQueryParameters(es, queryDesc->params, auto_explain_log_parameter_max_length);
- ExplainPrintPlan(es, queryDesc);
+ ExplainPrintPlan(es, queryDesc, &queryDesc->plannedstmt->plantime,
+ &queryDesc->plannedstmt->bufusage);
if (es->analyze && auto_explain_log_triggers)
ExplainPrintTriggers(es, queryDesc);
if (es->costs)
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index a0311ce9dc..f92c7ebb98 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -602,22 +602,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
ExplainOpenGroup("Query", NULL, true, es);
/* Create textual dump of plan tree */
- ExplainPrintPlan(es, queryDesc);
-
- /* Show buffer usage in planning */
- if (bufusage)
- {
- ExplainOpenGroup("Planning", "Planning", true, es);
- show_buffer_usage(es, bufusage, true);
- ExplainCloseGroup("Planning", "Planning", true, es);
- }
-
- if (es->summary && planduration)
- {
- double plantime = INSTR_TIME_GET_DOUBLE(*planduration);
-
- ExplainPropertyFloat("Planning Time", "ms", 1000.0 * plantime, 3, es);
- }
+ ExplainPrintPlan(es, queryDesc, planduration, bufusage);
/* Print info about runtime of triggers */
if (es->analyze)
@@ -738,7 +723,9 @@ ExplainPrintSettings(ExplainState *es)
* NB: will not work on utility statements
*/
void
-ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc)
+ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc,
+ const instr_time *planduration,
+ const BufferUsage *bufusage)
{
Bitmapset *rels_used = NULL;
PlanState *ps;
@@ -791,6 +778,21 @@ ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc)
ExplainPropertyInteger("Query Identifier", NULL, (int64)
queryDesc->plannedstmt->queryId, es);
}
+
+ /* Show buffer usage in planning */
+ if (bufusage)
+ {
+ ExplainOpenGroup("Planning", "Planning", true, es);
+ show_buffer_usage(es, bufusage, true);
+ ExplainCloseGroup("Planning", "Planning", true, es);
+ }
+
+ if (es->summary && planduration)
+ {
+ double plantime = INSTR_TIME_GET_DOUBLE(*planduration);
+
+ ExplainPropertyFloat("Planning Time", "ms", 1000.0 * plantime, 3, es);
+ }
}
/*
diff --git a/src/backend/nodes/gen_node_support.pl b/src/backend/nodes/gen_node_support.pl
index b3c1ead496..65d8721865 100644
--- a/src/backend/nodes/gen_node_support.pl
+++ b/src/backend/nodes/gen_node_support.pl
@@ -759,6 +759,8 @@ _equal${n}(const $n *a, const $n *b)
print $eff "\tCOMPARE_BITMAPSET_FIELD($f);\n"
unless $equal_ignore;
}
+ # temporarily change for PoC
+ elsif ($t eq 'instr_time' || $t eq 'BufferUsage') { }
elsif ($t eq 'int' && $f =~ 'location$')
{
print $cff "\tCOPY_LOCATION_FIELD($f);\n" unless $copy_ignore;
@@ -1073,6 +1075,8 @@ _read${n}(void)
print $off "\tWRITE_BITMAPSET_FIELD($f);\n";
print $rff "\tREAD_BITMAPSET_FIELD($f);\n" unless $no_read;
}
+ # temporalily change for PoC
+ elsif ($t eq 'instr_time' || $t eq 'BufferUsage') { }
elsif (elem $t, @enum_types)
{
print $off "\tWRITE_ENUM_FIELD($f, $t);\n";
diff --git a/src/backend/optimizer/plan/planner.c b/src/backend/optimizer/plan/planner.c
index 05f44faf6e..5095da68f6 100644
--- a/src/backend/optimizer/plan/planner.c
+++ b/src/backend/optimizer/plan/planner.c
@@ -564,6 +564,8 @@ standard_planner(Query *parse, const char *query_string, int cursorOptions,
if (jit_tuple_deforming)
result->jitFlags |= PGJIT_DEFORM;
}
+ memset(&result->bufusage, 0, sizeof(BufferUsage));
+ memset(&result->plantime, 0, sizeof(instr_time));
if (glob->partition_directory != NULL)
DestroyPartitionDirectory(glob->partition_directory);
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 7c1071ddd1..690bc7bece 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -93,7 +93,9 @@ extern void ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into,
const instr_time *planduration,
const BufferUsage *bufusage);
-extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc);
+extern void ExplainPrintPlan(ExplainState *es, QueryDesc *queryDesc,
+ const instr_time *planduration,
+ const BufferUsage *bufusage);
extern void ExplainPrintTriggers(ExplainState *es, QueryDesc *queryDesc);
extern void ExplainPrintJITSummary(ExplainState *es, QueryDesc *queryDesc);
diff --git a/src/include/nodes/plannodes.h b/src/include/nodes/plannodes.h
index c1234fcf36..e0076a2042 100644
--- a/src/include/nodes/plannodes.h
+++ b/src/include/nodes/plannodes.h
@@ -17,11 +17,13 @@
#include "access/sdir.h"
#include "access/stratnum.h"
#include "common/relpath.h"
+#include "executor/instrument.h"
#include "lib/stringinfo.h"
#include "nodes/bitmapset.h"
#include "nodes/lockoptions.h"
#include "nodes/parsenodes.h"
#include "nodes/primnodes.h"
+#include "portability/instr_time.h"
/* ----------------------------------------------------------------
@@ -101,6 +103,10 @@ typedef struct PlannedStmt
/* statement location in source string (copied from Query) */
int stmt_location; /* start location, or -1 if unknown */
int stmt_len; /* length in bytes; 0 means "rest of string" */
+
+ /* These are never used by the core system, but plugins can change them */
+ instr_time plantime; /* planning time */
+ BufferUsage bufusage; /* buffer usage for planning */
} PlannedStmt;
/* macro for fetching the Plan associated with a SubPlan node */
--
2.25.1
