From 02f3bd5763fb0719827112afff809267fd778989 Mon Sep 17 00:00:00 2001 From: Yugo Nagata 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'; auto_explain.log_min_duration is the minimum statement execution time, in milliseconds, that will cause the statement's plan to be logged. Setting this to 0 logs all plans. + Also if auto_explain.log_before_query is enable, all + plans are logged regardless of auto_explain.log_min_duration. -1 (the default) disables logging of plans. For example, if you set it to 250ms then all statements that run 250ms or longer will be logged. Only superusers can change this @@ -260,6 +262,25 @@ LOAD 'auto_explain'; + + + + auto_explain.log_before_query (boolean) + + auto_explain.log_before_query configuration parameter + + + + + auto_explain.log_before_query 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 auto_explain.log_analyze is enabled. + Only superusers can change this setting. + + + -- 2.17.1