Allow auto_explain to log plans before queries are executed
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 <nagata@sraoss.co.jp>
Attachments:
0001-Allow-to-log-plans-before-queries-are-executed.patchtext/x-diff; name=0001-Allow-to-log-plans-before-queries-are-executed.patchDownload
From 02f3bd5763fb0719827112afff809267fd778989 Mon Sep 17 00:00:00 2001
From: Yugo Nagata <nagata@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
On Thu, Feb 27, 2020 at 02:35:18AM +0900, Yugo NAGATA wrote:
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.
Indeed that could be useful.
This patch adds new option log_before_query to auto_explain.
Maybe "log_before_execution" would be better?
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.
I'm not sure about this behavior. The final explain plan is needed at least if
log_analyze, log_buffers or log_timing are enabled.
On Wed, 26 Feb 2020 18:51:21 +0100
Julien Rouhaud <rjuju123@gmail.com> wrote:
On Thu, Feb 27, 2020 at 02:35:18AM +0900, Yugo NAGATA wrote:
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.Indeed that could be useful.
This patch adds new option log_before_query to auto_explain.
Maybe "log_before_execution" would be better?
Thanks! This seems better also to me.
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.I'm not sure about this behavior. The final explain plan is needed at least if
log_analyze, log_buffers or log_timing are enabled.
In the current patch, log_before_query (will be log_before_execution)
has no effect if log_analyze is enabled in order to avoid to log the
same plans twice. Instead, is it better to log the plan always twice,
before and after the execution, if log_before_query is enabled
regardless of log_min_duration or log_analyze?
Regards,
Yugo Nagata
--
Yugo NAGATA <nagata@sraoss.co.jp>
Hello.
At Thu, 27 Feb 2020 10:18:16 +0900, Yugo NAGATA <nagata@sraoss.co.jp> wrote in
On Wed, 26 Feb 2020 18:51:21 +0100
Julien Rouhaud <rjuju123@gmail.com> wrote:On Thu, Feb 27, 2020 at 02:35:18AM +0900, Yugo NAGATA wrote:
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.Indeed that could be useful.
This patch adds new option log_before_query to auto_explain.
Maybe "log_before_execution" would be better?
Thanks! This seems better also to me.
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.I'm not sure about this behavior. The final explain plan is needed at least if
log_analyze, log_buffers or log_timing are enabled.In the current patch, log_before_query (will be log_before_execution)
has no effect if log_analyze is enabled in order to avoid to log the
same plans twice. Instead, is it better to log the plan always twice,
before and after the execution, if log_before_query is enabled
regardless of log_min_duration or log_analyze?
Honestly, I don't think showing plans for all queries is useful
behavior.
If you allow the stuck query to be canceled, showing plan in
PG_FINALLY() block in explain_ExecutorRun would work, which look like
this.
explain_ExecutorRun()
{
...
PG_TRY();
{
...
else
starndard_ExecutorRun();
nesting_level--;
}
PG_CATCH();
{
nesting_level--;
if (auto_explain_log_failed_plan &&
<maybe the time elapsed from start exceeds min_duration>)
{
'show the plan'
}
}
}
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
čt 27. 2. 2020 v 6:16 odesílatel Kyotaro Horiguchi <horikyota.ntt@gmail.com>
napsal:
Hello.
At Thu, 27 Feb 2020 10:18:16 +0900, Yugo NAGATA <nagata@sraoss.co.jp>
wrote inOn Wed, 26 Feb 2020 18:51:21 +0100
Julien Rouhaud <rjuju123@gmail.com> wrote:On Thu, Feb 27, 2020 at 02:35:18AM +0900, Yugo NAGATA wrote:
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.Indeed that could be useful.
This patch adds new option log_before_query to auto_explain.
Maybe "log_before_execution" would be better?
Thanks! This seems better also to me.
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.I'm not sure about this behavior. The final explain plan is needed at
least if
log_analyze, log_buffers or log_timing are enabled.
In the current patch, log_before_query (will be log_before_execution)
has no effect if log_analyze is enabled in order to avoid to log the
same plans twice. Instead, is it better to log the plan always twice,
before and after the execution, if log_before_query is enabled
regardless of log_min_duration or log_analyze?Honestly, I don't think showing plans for all queries is useful
behavior.If you allow the stuck query to be canceled, showing plan in
PG_FINALLY() block in explain_ExecutorRun would work, which look like
this.explain_ExecutorRun()
{
...
PG_TRY();
{
...
else
starndard_ExecutorRun();
nesting_level--;
}
PG_CATCH();
{
nesting_level--;if (auto_explain_log_failed_plan &&
<maybe the time elapsed from start exceeds min_duration>)
{
'show the plan'
}
}
}regards.
It can work - but still it is not good enough solution. We need "query
debugger" that allows to get some query execution metrics online.
There was a problem with memory management for passing plans between
processes. Can we used temp files instead shared memory?
Regards
Pavel
Show quoted text
--
Kyotaro Horiguchi
NTT Open Source Software Center
On Thu, 27 Feb 2020 14:14:41 +0900 (JST)
Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote:
Hello.
At Thu, 27 Feb 2020 10:18:16 +0900, Yugo NAGATA <nagata@sraoss.co.jp> wrote in
On Wed, 26 Feb 2020 18:51:21 +0100
Julien Rouhaud <rjuju123@gmail.com> wrote:On Thu, Feb 27, 2020 at 02:35:18AM +0900, Yugo NAGATA wrote:
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.Indeed that could be useful.
This patch adds new option log_before_query to auto_explain.
Maybe "log_before_execution" would be better?
Thanks! This seems better also to me.
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.I'm not sure about this behavior. The final explain plan is needed at least if
log_analyze, log_buffers or log_timing are enabled.In the current patch, log_before_query (will be log_before_execution)
has no effect if log_analyze is enabled in order to avoid to log the
same plans twice. Instead, is it better to log the plan always twice,
before and after the execution, if log_before_query is enabled
regardless of log_min_duration or log_analyze?Honestly, I don't think showing plans for all queries is useful
behavior.If you allow the stuck query to be canceled, showing plan in
PG_FINALLY() block in explain_ExecutorRun would work, which look like
this.explain_ExecutorRun()
{
...
PG_TRY();
{
...
else
starndard_ExecutorRun();
nesting_level--;
}
PG_CATCH();
{
nesting_level--;if (auto_explain_log_failed_plan &&
<maybe the time elapsed from start exceeds min_duration>)
{
'show the plan'
}
}
}
That makes sense. The initial purpose is to log plans of stuck queries
not of all queries, so your suggestion, doing it only when the query
fails, is reasonable. I'll consider it little more.
Regards,
Yugo Nagata
--
Yugo NAGATA <nagata@sraoss.co.jp>
At Thu, 27 Feb 2020 06:27:24 +0100, Pavel Stehule <pavel.stehule@gmail.com> wrote in
odesílatel Kyotaro Horiguchi <horikyota.ntt@gmail.com>
napsal:In the current patch, log_before_query (will be log_before_execution)
has no effect if log_analyze is enabled in order to avoid to log the
same plans twice. Instead, is it better to log the plan always twice,
before and after the execution, if log_before_query is enabled
regardless of log_min_duration or log_analyze?Honestly, I don't think showing plans for all queries is useful
behavior.If you allow the stuck query to be canceled, showing plan in
PG_FINALLY() block in explain_ExecutorRun would work, which look like
this.
...
It can work - but still it is not good enough solution. We need "query
debugger" that allows to get some query execution metrics online.
If we need a live plan dump of a running query, We could do that using
some kind of inter-backend triggering. (I'm not sure if PG offers
inter-backend signalling facility usable by extensions..)
=# select auto_explain.log_plan_backend(12345);
postgresql.log:
LOG: requested plan dump: <blah, blah>..
There was a problem with memory management for passing plans between
processes. Can we used temp files instead shared memory?
=# select auto_explain.dump_plan_backend(12345);
pid | query | plan
-------+-------------+-------------------
12345 | SELECT 1; | Result (cost=....) (actual..)
(1 row)
Doesn't DSA work? I think it would be easier to handle than files.
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
On Thu, 27 Feb 2020 06:27:24 +0100
Pavel Stehule <pavel.stehule@gmail.com> wrote:
čt 27. 2. 2020 v 6:16 odesílatel Kyotaro Horiguchi <horikyota.ntt@gmail.com>
napsal:Hello.
At Thu, 27 Feb 2020 10:18:16 +0900, Yugo NAGATA <nagata@sraoss.co.jp>
wrote inOn Wed, 26 Feb 2020 18:51:21 +0100
Julien Rouhaud <rjuju123@gmail.com> wrote:On Thu, Feb 27, 2020 at 02:35:18AM +0900, Yugo NAGATA wrote:
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.Indeed that could be useful.
This patch adds new option log_before_query to auto_explain.
Maybe "log_before_execution" would be better?
Thanks! This seems better also to me.
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.I'm not sure about this behavior. The final explain plan is needed at
least if
log_analyze, log_buffers or log_timing are enabled.
In the current patch, log_before_query (will be log_before_execution)
has no effect if log_analyze is enabled in order to avoid to log the
same plans twice. Instead, is it better to log the plan always twice,
before and after the execution, if log_before_query is enabled
regardless of log_min_duration or log_analyze?Honestly, I don't think showing plans for all queries is useful
behavior.If you allow the stuck query to be canceled, showing plan in
PG_FINALLY() block in explain_ExecutorRun would work, which look like
this.explain_ExecutorRun()
{
...
PG_TRY();
{
...
else
starndard_ExecutorRun();
nesting_level--;
}
PG_CATCH();
{
nesting_level--;if (auto_explain_log_failed_plan &&
<maybe the time elapsed from start exceeds min_duration>)
{
'show the plan'
}
}
}regards.
It can work - but still it is not good enough solution. We need "query
debugger" that allows to get some query execution metrics online.There was a problem with memory management for passing plans between
processes. Can we used temp files instead shared memory?
I think "query debugger" feature you proposed is out of scope of
auto_explain module. I also think the feature to analyze running
query online is great, but we will need another discussion on a new
module or eature for it.
Regards,
Yugo Nagata
--
Yugo NAGATA <nagata@sraoss.co.jp>
čt 27. 2. 2020 v 6:58 odesílatel Kyotaro Horiguchi <horikyota.ntt@gmail.com>
napsal:
At Thu, 27 Feb 2020 06:27:24 +0100, Pavel Stehule <pavel.stehule@gmail.com>
wrote inodesílatel Kyotaro Horiguchi <horikyota.ntt@gmail.com>
napsal:In the current patch, log_before_query (will be log_before_execution)
has no effect if log_analyze is enabled in order to avoid to log the
same plans twice. Instead, is it better to log the plan alwaystwice,
before and after the execution, if log_before_query is enabled
regardless of log_min_duration or log_analyze?Honestly, I don't think showing plans for all queries is useful
behavior.If you allow the stuck query to be canceled, showing plan in
PG_FINALLY() block in explain_ExecutorRun would work, which look like
this....
It can work - but still it is not good enough solution. We need "query
debugger" that allows to get some query execution metrics online.If we need a live plan dump of a running query, We could do that using
some kind of inter-backend triggering. (I'm not sure if PG offers
inter-backend signalling facility usable by extensions..)=# select auto_explain.log_plan_backend(12345);
postgresql.log:
LOG: requested plan dump: <blah, blah>..There was a problem with memory management for passing plans between
processes. Can we used temp files instead shared memory?=# select auto_explain.dump_plan_backend(12345);
pid | query | plan
-------+-------------+-------------------
12345 | SELECT 1; | Result (cost=....) (actual..)
(1 row)Doesn't DSA work? I think it would be easier to handle than files.
I am not sure. There is hard questions when the allocated shared memory
should be deallocated.
Maybe using third process can be the most nice, safe solution.
The execution plans can be pushed to some background worker memory, and
this process can works like stats_collector.
Show quoted text
regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
čt 27. 2. 2020 v 7:01 odesílatel Yugo NAGATA <nagata@sraoss.co.jp> napsal:
On Thu, 27 Feb 2020 06:27:24 +0100
Pavel Stehule <pavel.stehule@gmail.com> wrote:čt 27. 2. 2020 v 6:16 odesílatel Kyotaro Horiguchi <
horikyota.ntt@gmail.com>
napsal:
Hello.
At Thu, 27 Feb 2020 10:18:16 +0900, Yugo NAGATA <nagata@sraoss.co.jp>
wrote inOn Wed, 26 Feb 2020 18:51:21 +0100
Julien Rouhaud <rjuju123@gmail.com> wrote:On Thu, Feb 27, 2020 at 02:35:18AM +0900, Yugo NAGATA wrote:
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.Indeed that could be useful.
This patch adds new option log_before_query to auto_explain.
Maybe "log_before_execution" would be better?
Thanks! This seems better also to me.
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 andlog_min_duration_statement
are enabled.
I'm not sure about this behavior. The final explain plan is
needed at
least if
log_analyze, log_buffers or log_timing are enabled.
In the current patch, log_before_query (will be log_before_execution)
has no effect if log_analyze is enabled in order to avoid to log the
same plans twice. Instead, is it better to log the plan alwaystwice,
before and after the execution, if log_before_query is enabled
regardless of log_min_duration or log_analyze?Honestly, I don't think showing plans for all queries is useful
behavior.If you allow the stuck query to be canceled, showing plan in
PG_FINALLY() block in explain_ExecutorRun would work, which look like
this.explain_ExecutorRun()
{
...
PG_TRY();
{
...
else
starndard_ExecutorRun();
nesting_level--;
}
PG_CATCH();
{
nesting_level--;if (auto_explain_log_failed_plan &&
<maybe the time elapsed from start exceeds min_duration>)
{
'show the plan'
}
}
}regards.
It can work - but still it is not good enough solution. We need "query
debugger" that allows to get some query execution metrics online.There was a problem with memory management for passing plans between
processes. Can we used temp files instead shared memory?I think "query debugger" feature you proposed is out of scope of
auto_explain module. I also think the feature to analyze running
query online is great, but we will need another discussion on a new
module or eature for it.
sure. My note was about using auto_explain like query_debugger. It has not
too sense, and from this perspective, the original proposal to log plan
before execution has more sense.
you can log every plan with higher cost than some constant.
Show quoted text
Regards,
Yugo Nagata--
Yugo NAGATA <nagata@sraoss.co.jp>
On Thu, Feb 27, 2020 at 7:12 AM Pavel Stehule <pavel.stehule@gmail.com> wrote:
čt 27. 2. 2020 v 7:01 odesílatel Yugo NAGATA <nagata@sraoss.co.jp> napsal:
On Thu, 27 Feb 2020 06:27:24 +0100
Pavel Stehule <pavel.stehule@gmail.com> wrote:čt 27. 2. 2020 v 6:16 odesílatel Kyotaro Horiguchi <horikyota.ntt@gmail.com>
napsal:Hello.
At Thu, 27 Feb 2020 10:18:16 +0900, Yugo NAGATA <nagata@sraoss.co.jp>
wrote inOn Wed, 26 Feb 2020 18:51:21 +0100
Julien Rouhaud <rjuju123@gmail.com> wrote:On Thu, Feb 27, 2020 at 02:35:18AM +0900, Yugo NAGATA wrote:
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.Indeed that could be useful.
This patch adds new option log_before_query to auto_explain.
Maybe "log_before_execution" would be better?
Thanks! This seems better also to me.
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.I'm not sure about this behavior. The final explain plan is needed at
least if
log_analyze, log_buffers or log_timing are enabled.
In the current patch, log_before_query (will be log_before_execution)
has no effect if log_analyze is enabled in order to avoid to log the
same plans twice. Instead, is it better to log the plan always twice,
before and after the execution, if log_before_query is enabled
regardless of log_min_duration or log_analyze?Honestly, I don't think showing plans for all queries is useful
behavior.If you allow the stuck query to be canceled, showing plan in
PG_FINALLY() block in explain_ExecutorRun would work, which look like
this.explain_ExecutorRun()
{
...
PG_TRY();
{
...
else
starndard_ExecutorRun();
nesting_level--;
}
PG_CATCH();
{
nesting_level--;if (auto_explain_log_failed_plan &&
<maybe the time elapsed from start exceeds min_duration>)
{
'show the plan'
}
}
}regards.
It can work - but still it is not good enough solution. We need "query
debugger" that allows to get some query execution metrics online.There was a problem with memory management for passing plans between
processes. Can we used temp files instead shared memory?I think "query debugger" feature you proposed is out of scope of
auto_explain module. I also think the feature to analyze running
query online is great, but we will need another discussion on a new
module or eature for it.sure. My note was about using auto_explain like query_debugger. It has not too sense, and from this perspective, the original proposal to log plan before execution has more sense.
you can log every plan with higher cost than some constant.
Yes I thought about that too. If you're not in an OLAP environment
(or with a specific user running few expensive queries), setup an
auto_explain.log_before_execution_min_cost.
Hi,
that feature for dumping plans with auto explain is already available in
https://github.com/legrandlegrand/pg_stat_sql_plans
This is an hybrid extension combining auto_explain and pg_stat_statements,
adding a planid and tracking metrics even on error, ..., ...
With
pg_stat_sql_plans.track_planid = true
pg_stat_sql_plans.explain = true
--> it writes explain plan in log file after planning and only one time
per (queryid,planid)
then no need of sampling
and with
pg_stat_sql_plans.track = 'all'
--> function pgssp_backend_queryid(pid) retrieves (nested) queryid of a
stuck statement,
and permit to retrieve its plan (by its queryid) in logs.
Regards
PAscal
--
Sent from: https://www.postgresql-archive.org/PostgreSQL-hackers-f1928748.html
On Thu, Feb 27, 2020 at 7:31 AM Julien Rouhaud <rjuju123@gmail.com> wrote:
On Thu, Feb 27, 2020 at 7:12 AM Pavel Stehule <pavel.stehule@gmail.com> wrote:
čt 27. 2. 2020 v 7:01 odesílatel Yugo NAGATA <nagata@sraoss.co.jp> napsal:
I think "query debugger" feature you proposed is out of scope of
auto_explain module. I also think the feature to analyze running
query online is great, but we will need another discussion on a new
module or eature for it.sure. My note was about using auto_explain like query_debugger. It has not too sense, and from this perspective, the original proposal to log plan before execution has more sense.
you can log every plan with higher cost than some constant.
Yes I thought about that too. If you're not in an OLAP environment
(or with a specific user running few expensive queries), setup an
auto_explain.log_before_execution_min_cost.
There was some discussion but no clear consensus on what should really
be done. I'm marking the patch as waiting on author which seems more
accurate. Feel free to switch it back if that's a wrong move.
Kyotaro Horiguchi-4 wrote
At Thu, 27 Feb 2020 06:27:24 +0100, Pavel Stehule <
pavel.stehule@
> wrote in
odesílatel Kyotaro Horiguchi <
horikyota.ntt@
>
napsal:
If we need a live plan dump of a running query, We could do that using
some kind of inter-backend triggering. (I'm not sure if PG offers
inter-backend signalling facility usable by extensions..)=# select auto_explain.log_plan_backend(12345);
postgresql.log:
LOG: requested plan dump: <blah, blah>..regards.
--
Kyotaro Horiguchi
NTT Open Source Software Center
Did you know
https://www.postgresql-archive.org/pg-show-plans-Seeing-all-execution-plans-at-once-td6129231.html
?
Regards
PAscal
--
Sent from: https://www.postgresql-archive.org/PostgreSQL-hackers-f1928748.html
On 3/5/20 8:46 AM, Julien Rouhaud wrote:
On Thu, Feb 27, 2020 at 7:31 AM Julien Rouhaud <rjuju123@gmail.com> wrote:
On Thu, Feb 27, 2020 at 7:12 AM Pavel Stehule <pavel.stehule@gmail.com> wrote:
čt 27. 2. 2020 v 7:01 odesílatel Yugo NAGATA <nagata@sraoss.co.jp> napsal:
I think "query debugger" feature you proposed is out of scope of
auto_explain module. I also think the feature to analyze running
query online is great, but we will need another discussion on a new
module or eature for it.sure. My note was about using auto_explain like query_debugger. It has not too sense, and from this perspective, the original proposal to log plan before execution has more sense.
you can log every plan with higher cost than some constant.
Yes I thought about that too. If you're not in an OLAP environment
(or with a specific user running few expensive queries), setup an
auto_explain.log_before_execution_min_cost.There was some discussion but no clear consensus on what should really
be done. I'm marking the patch as waiting on author which seems more
accurate. Feel free to switch it back if that's a wrong move.
There does seem to be any progress towards a consensus so I'm marking
this Returned with Feedback.
Regards,
--
-David
david@pgmasters.net