Hi,
Attached is a patch for allowing auto_explain to log plans before
queries are executed.
Currently, auto_explain logs plans only after query executions,
so if a query gets stuck its plan could not be logged. If we can
know plans of stuck queries, we may get some hints to resolve the
stuck. This is useful when you are testing and debugging your
application whose queries get stuck in some situations.
This patch adds new option log_before_query to auto_explain.
Setting auto_explain.log_before_query option logs all plans before
queries are executed regardless of auto_explain.log_min_duration
unless this is set -1 to disable logging. If log_before_query is
enabled, only duration time is logged after query execution as in
the case of when both log_statement and log_min_duration_statement
are enabled.
Regards,
Yugo Nagata
--
Yugo NAGATA <nag...@sraoss.co.jp>
>From 02f3bd5763fb0719827112afff809267fd778989 Mon Sep 17 00:00:00 2001
From: Yugo Nagata <nag...@sraoss.co.jp>
Date: Fri, 14 Feb 2020 16:32:32 +0900
Subject: [PATCH] Allow to log plans before queries are executed
Previously, auto_explain logs plans only after query executions,
so if a query gets stuck its plan could not be logged. Setting
auto_explain.log_before_query option logs all plans before queries
are executed regardless of auto_explain.log_min_duration unless
this is set -1 to disable logging.
---
contrib/auto_explain/auto_explain.c | 123 ++++++++++++++++++++--------
doc/src/sgml/auto-explain.sgml | 21 +++++
2 files changed, 109 insertions(+), 35 deletions(-)
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index f69dde876c..1c90ed4469 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -34,6 +34,7 @@ static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
static int auto_explain_log_level = LOG;
static bool auto_explain_log_nested_statements = false;
static double auto_explain_sample_rate = 1;
+static bool auto_explain_log_before_query = false;
static const struct config_enum_entry format_options[] = {
{"text", EXPLAIN_FORMAT_TEXT, false},
@@ -63,6 +64,9 @@ static int nesting_level = 0;
/* Is the current top-level query to be sampled? */
static bool current_query_sampled = false;
+/* Was the plan logged before query execution? */
+static bool was_logged = false;
+
#define auto_explain_enabled() \
(auto_explain_log_min_duration >= 0 && \
(nesting_level == 0 || auto_explain_log_nested_statements) && \
@@ -84,6 +88,7 @@ static void explain_ExecutorRun(QueryDesc *queryDesc,
static void explain_ExecutorFinish(QueryDesc *queryDesc);
static void explain_ExecutorEnd(QueryDesc *queryDesc);
+static ExplainState *do_explain(QueryDesc *queryDesc);
/*
* Module load callback
@@ -218,6 +223,17 @@ _PG_init(void)
NULL,
NULL);
+ DefineCustomBoolVariable("auto_explain.log_before_query",
+ "Log before query is executed.",
+ NULL,
+ &auto_explain_log_before_query,
+ false,
+ PGC_SUSET,
+ 0,
+ NULL,
+ NULL,
+ NULL);
+
EmitWarningsOnPlaceholders("auto_explain");
/* Install hooks. */
@@ -288,6 +304,7 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
else
standard_ExecutorStart(queryDesc, eflags);
+ was_logged = false;
if (auto_explain_enabled())
{
/*
@@ -303,6 +320,25 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL);
MemoryContextSwitchTo(oldcxt);
}
+
+ /* Log plan before the query is executed */
+ if (!auto_explain_log_analyze && auto_explain_log_before_query)
+ {
+ ExplainState *es = do_explain(queryDesc);
+
+ /*
+ * Note: we rely on the existing logging of context or
+ * debug_query_string to identify just which statement is being
+ * reported. This isn't ideal but trying to do it here would
+ * often result in duplication.
+ */
+ ereport(auto_explain_log_level,
+ (errmsg("plan:\n%s", es->str->data),
+ errhidestmt(true)));
+ pfree(es->str->data);
+
+ was_logged = true;
+ }
}
}
@@ -369,48 +405,26 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
msec = queryDesc->totaltime->total * 1000.0;
if (msec >= auto_explain_log_min_duration)
{
- ExplainState *es = NewExplainState();
-
- es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
- es->verbose = auto_explain_log_verbose;
- es->buffers = (es->analyze && auto_explain_log_buffers);
- es->timing = (es->analyze && auto_explain_log_timing);
- es->summary = es->analyze;
- es->format = auto_explain_log_format;
- es->settings = auto_explain_log_settings;
-
- ExplainBeginOutput(es);
- ExplainQueryText(es, queryDesc);
- ExplainPrintPlan(es, queryDesc);
- if (es->analyze && auto_explain_log_triggers)
- ExplainPrintTriggers(es, queryDesc);
- if (es->costs)
- ExplainPrintJITSummary(es, queryDesc);
- ExplainEndOutput(es);
-
- /* Remove last line break */
- if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
- es->str->data[--es->str->len] = '\0';
-
- /* Fix JSON to output an object */
- if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
- {
- es->str->data[0] = '{';
- es->str->data[es->str->len - 1] = '}';
- }
-
/*
* Note: we rely on the existing logging of context or
* debug_query_string to identify just which statement is being
* reported. This isn't ideal but trying to do it here would
* often result in duplication.
*/
- ereport(auto_explain_log_level,
- (errmsg("duration: %.3f ms plan:\n%s",
- msec, es->str->data),
- errhidestmt(true)));
+ if (was_logged)
+ ereport(auto_explain_log_level,
+ (errmsg("duration: %.3f ms", msec),
+ errhidestmt(true)));
+ else
+ {
+ ExplainState *es = do_explain(queryDesc);
- pfree(es->str->data);
+ ereport(auto_explain_log_level,
+ (errmsg("duration: %.3f ms plan:\n%s",
+ msec, es->str->data),
+ errhidestmt(true)));
+ pfree(es->str->data);
+ }
}
}
@@ -419,3 +433,42 @@ explain_ExecutorEnd(QueryDesc *queryDesc)
else
standard_ExecutorEnd(queryDesc);
}
+
+/*
+ * do_explain: make an execution plan
+ */
+static ExplainState *
+do_explain(QueryDesc *queryDesc)
+{
+ ExplainState *es = NewExplainState();
+
+ es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze);
+ es->verbose = auto_explain_log_verbose;
+ es->buffers = (es->analyze && auto_explain_log_buffers);
+ es->timing = (es->analyze && auto_explain_log_timing);
+ es->summary = es->analyze;
+ es->format = auto_explain_log_format;
+ es->settings = auto_explain_log_settings;
+
+ ExplainBeginOutput(es);
+ ExplainQueryText(es, queryDesc);
+ ExplainPrintPlan(es, queryDesc);
+ if (es->analyze && auto_explain_log_triggers)
+ ExplainPrintTriggers(es, queryDesc);
+ if (es->costs)
+ ExplainPrintJITSummary(es, queryDesc);
+ ExplainEndOutput(es);
+
+ /* Remove last line break */
+ if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
+ es->str->data[--es->str->len] = '\0';
+
+ /* Fix JSON to output an object */
+ if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
+ {
+ es->str->data[0] = '{';
+ es->str->data[es->str->len - 1] = '}';
+ }
+
+ return es;
+}
diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml
index 3d619d4a3d..955a158232 100644
--- a/doc/src/sgml/auto-explain.sgml
+++ b/doc/src/sgml/auto-explain.sgml
@@ -55,6 +55,8 @@ LOAD 'auto_explain';
<varname>auto_explain.log_min_duration</varname> is the minimum statement
execution time, in milliseconds, that will cause the statement's plan to
be logged. Setting this to <literal>0</literal> logs all plans.
+ Also if <varname>auto_explain.log_before_query</varname> is enable, all
+ plans are logged regardless of <varname>auto_explain.log_min_duration</varname>.
<literal>-1</literal> (the default) disables logging of plans. For
example, if you set it to <literal>250ms</literal> then all statements
that run 250ms or longer will be logged. Only superusers can change this
@@ -260,6 +262,25 @@ LOAD 'auto_explain';
</para>
</listitem>
</varlistentry>
+
+ <varlistentry>
+ <term>
+ <varname>auto_explain.log_before_query</varname> (<type>boolean</type>)
+ <indexterm>
+ <primary><varname>auto_explain.log_before_query</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ <varname>auto_explain.log_before_query</varname> controls whether
+ execution plans are logged before query are executed. When it is on,
+ all plans are logged before query execution. This parameter is off by
+ default. This parameter has no effect
+ if <varname>auto_explain.log_analyze</varname> is enabled.
+ Only superusers can change this setting.
+ </para>
+ </listitem>
+ </varlistentry>
</variablelist>
<para>
--
2.17.1
