2008-11-19 03:59:28 +01:00
|
|
|
/*-------------------------------------------------------------------------
|
|
|
|
*
|
|
|
|
* auto_explain.c
|
|
|
|
*
|
|
|
|
*
|
2022-01-08 01:04:57 +01:00
|
|
|
* Copyright (c) 2008-2022, PostgreSQL Global Development Group
|
2008-11-19 03:59:28 +01:00
|
|
|
*
|
|
|
|
* IDENTIFICATION
|
2010-09-20 22:08:53 +02:00
|
|
|
* contrib/auto_explain/auto_explain.c
|
2008-11-19 03:59:28 +01:00
|
|
|
*
|
|
|
|
*-------------------------------------------------------------------------
|
|
|
|
*/
|
|
|
|
#include "postgres.h"
|
|
|
|
|
2012-08-29 05:43:09 +02:00
|
|
|
#include <limits.h>
|
|
|
|
|
2019-06-04 00:06:04 +02:00
|
|
|
#include "access/parallel.h"
|
2008-11-19 03:59:28 +01:00
|
|
|
#include "commands/explain.h"
|
Replace random(), pg_erand48(), etc with a better PRNG API and algorithm.
Standardize on xoroshiro128** as our basic PRNG algorithm, eliminating
a bunch of platform dependencies as well as fundamentally-obsolete PRNG
code. In addition, this API replacement will ease replacing the
algorithm again in future, should that become necessary.
xoroshiro128** is a few percent slower than the drand48 family,
but it can produce full-width 64-bit random values not only 48-bit,
and it should be much more trustworthy. It's likely to be noticeably
faster than the platform's random(), depending on which platform you
are thinking about; and we can have non-global state vectors easily,
unlike with random(). It is not cryptographically strong, but neither
are the functions it replaces.
Fabien Coelho, reviewed by Dean Rasheed, Aleksander Alekseev, and myself
Discussion: https://postgr.es/m/alpine.DEB.2.22.394.2105241211230.165418@pseudo
2021-11-29 03:32:36 +01:00
|
|
|
#include "common/pg_prng.h"
|
2008-11-19 03:59:28 +01:00
|
|
|
#include "executor/instrument.h"
|
2018-09-24 22:40:57 +02:00
|
|
|
#include "jit/jit.h"
|
2011-09-04 07:13:16 +02:00
|
|
|
#include "utils/guc.h"
|
2008-11-19 03:59:28 +01:00
|
|
|
|
|
|
|
PG_MODULE_MAGIC;
|
|
|
|
|
|
|
|
/* GUC variables */
|
2009-06-11 16:49:15 +02:00
|
|
|
static int auto_explain_log_min_duration = -1; /* msec or -1 */
|
2009-01-02 02:16:02 +01:00
|
|
|
static bool auto_explain_log_analyze = false;
|
|
|
|
static bool auto_explain_log_verbose = false;
|
2009-12-15 05:57:48 +01:00
|
|
|
static bool auto_explain_log_buffers = false;
|
2020-04-06 04:32:15 +02:00
|
|
|
static bool auto_explain_log_wal = false;
|
2014-03-04 19:31:18 +01:00
|
|
|
static bool auto_explain_log_triggers = false;
|
2014-09-19 19:18:56 +02:00
|
|
|
static bool auto_explain_log_timing = true;
|
2019-04-04 00:04:31 +02:00
|
|
|
static bool auto_explain_log_settings = false;
|
2009-08-10 07:46:50 +02:00
|
|
|
static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
|
2018-07-31 14:03:57 +02:00
|
|
|
static int auto_explain_log_level = LOG;
|
2009-01-02 02:16:02 +01:00
|
|
|
static bool auto_explain_log_nested_statements = false;
|
2016-03-13 13:18:03 +01:00
|
|
|
static double auto_explain_sample_rate = 1;
|
2008-11-19 03:59:28 +01:00
|
|
|
|
2009-08-10 07:46:50 +02:00
|
|
|
static const struct config_enum_entry format_options[] = {
|
2010-02-26 03:01:40 +01:00
|
|
|
{"text", EXPLAIN_FORMAT_TEXT, false},
|
|
|
|
{"xml", EXPLAIN_FORMAT_XML, false},
|
|
|
|
{"json", EXPLAIN_FORMAT_JSON, false},
|
|
|
|
{"yaml", EXPLAIN_FORMAT_YAML, false},
|
|
|
|
{NULL, 0, false}
|
2009-08-10 07:46:50 +02:00
|
|
|
};
|
|
|
|
|
2018-07-31 14:03:57 +02:00
|
|
|
static const struct config_enum_entry loglevel_options[] = {
|
|
|
|
{"debug5", DEBUG5, false},
|
|
|
|
{"debug4", DEBUG4, false},
|
|
|
|
{"debug3", DEBUG3, false},
|
|
|
|
{"debug2", DEBUG2, false},
|
|
|
|
{"debug1", DEBUG1, false},
|
|
|
|
{"debug", DEBUG2, true},
|
|
|
|
{"info", INFO, false},
|
|
|
|
{"notice", NOTICE, false},
|
|
|
|
{"warning", WARNING, false},
|
|
|
|
{"log", LOG, false},
|
|
|
|
{NULL, 0, false}
|
|
|
|
};
|
|
|
|
|
2008-11-19 03:59:28 +01:00
|
|
|
/* Current nesting depth of ExecutorRun calls */
|
|
|
|
static int nesting_level = 0;
|
|
|
|
|
2019-06-04 00:06:04 +02:00
|
|
|
/* 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) && \
|
|
|
|
current_query_sampled)
|
|
|
|
|
2008-11-19 03:59:28 +01:00
|
|
|
/* Saved hook values in case of unload */
|
2009-06-11 16:49:15 +02:00
|
|
|
static ExecutorStart_hook_type prev_ExecutorStart = NULL;
|
|
|
|
static ExecutorRun_hook_type prev_ExecutorRun = NULL;
|
2011-02-27 19:43:29 +01:00
|
|
|
static ExecutorFinish_hook_type prev_ExecutorFinish = NULL;
|
2009-06-11 16:49:15 +02:00
|
|
|
static ExecutorEnd_hook_type prev_ExecutorEnd = NULL;
|
2008-11-19 03:59:28 +01:00
|
|
|
|
2009-06-11 16:49:15 +02:00
|
|
|
void _PG_init(void);
|
2008-11-19 03:59:28 +01:00
|
|
|
|
|
|
|
static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags);
|
|
|
|
static void explain_ExecutorRun(QueryDesc *queryDesc,
|
2019-05-22 19:04:48 +02:00
|
|
|
ScanDirection direction,
|
|
|
|
uint64 count, bool execute_once);
|
2011-02-27 19:43:29 +01:00
|
|
|
static void explain_ExecutorFinish(QueryDesc *queryDesc);
|
2008-11-19 03:59:28 +01:00
|
|
|
static void explain_ExecutorEnd(QueryDesc *queryDesc);
|
|
|
|
|
|
|
|
|
|
|
|
/*
|
|
|
|
* Module load callback
|
|
|
|
*/
|
|
|
|
void
|
|
|
|
_PG_init(void)
|
|
|
|
{
|
|
|
|
/* Define custom GUC variables. */
|
2009-01-02 02:16:02 +01:00
|
|
|
DefineCustomIntVariable("auto_explain.log_min_duration",
|
Phase 3 of pgindent updates.
Don't move parenthesized lines to the left, even if that means they
flow past the right margin.
By default, BSD indent lines up statement continuation lines that are
within parentheses so that they start just to the right of the preceding
left parenthesis. However, traditionally, if that resulted in the
continuation line extending to the right of the desired right margin,
then indent would push it left just far enough to not overrun the margin,
if it could do so without making the continuation line start to the left of
the current statement indent. That makes for a weird mix of indentations
unless one has been completely rigid about never violating the 80-column
limit.
This behavior has been pretty universally panned by Postgres developers.
Hence, disable it with indent's new -lpl switch, so that parenthesized
lines are always lined up with the preceding left paren.
This patch is much less interesting than the first round of indent
changes, but also bulkier, so I thought it best to separate the effects.
Discussion: https://postgr.es/m/E1dAmxK-0006EE-1r@gemulon.postgresql.org
Discussion: https://postgr.es/m/30527.1495162840@sss.pgh.pa.us
2017-06-21 21:35:54 +02:00
|
|
|
"Sets the minimum execution time above which plans will be logged.",
|
|
|
|
"Zero prints all plans. -1 turns this feature off.",
|
2009-01-02 02:16:02 +01:00
|
|
|
&auto_explain_log_min_duration,
|
2008-11-19 03:59:28 +01:00
|
|
|
-1,
|
2018-02-23 20:38:19 +01:00
|
|
|
-1, INT_MAX,
|
2008-11-19 03:59:28 +01:00
|
|
|
PGC_SUSET,
|
|
|
|
GUC_UNIT_MS,
|
|
|
|
NULL,
|
2011-04-07 06:11:01 +02:00
|
|
|
NULL,
|
2008-11-19 03:59:28 +01:00
|
|
|
NULL);
|
|
|
|
|
2009-01-02 02:16:02 +01:00
|
|
|
DefineCustomBoolVariable("auto_explain.log_analyze",
|
2008-11-19 03:59:28 +01:00
|
|
|
"Use EXPLAIN ANALYZE for plan logging.",
|
|
|
|
NULL,
|
2009-01-02 02:16:02 +01:00
|
|
|
&auto_explain_log_analyze,
|
2008-11-19 03:59:28 +01:00
|
|
|
false,
|
|
|
|
PGC_SUSET,
|
|
|
|
0,
|
|
|
|
NULL,
|
2011-04-07 06:11:01 +02:00
|
|
|
NULL,
|
2008-11-19 03:59:28 +01:00
|
|
|
NULL);
|
|
|
|
|
2019-04-04 00:04:31 +02:00
|
|
|
DefineCustomBoolVariable("auto_explain.log_settings",
|
|
|
|
"Log modified configuration parameters affecting query planning.",
|
|
|
|
NULL,
|
|
|
|
&auto_explain_log_settings,
|
|
|
|
false,
|
|
|
|
PGC_SUSET,
|
|
|
|
0,
|
|
|
|
NULL,
|
|
|
|
NULL,
|
|
|
|
NULL);
|
|
|
|
|
2009-01-02 02:16:02 +01:00
|
|
|
DefineCustomBoolVariable("auto_explain.log_verbose",
|
2008-11-19 03:59:28 +01:00
|
|
|
"Use EXPLAIN VERBOSE for plan logging.",
|
|
|
|
NULL,
|
2009-01-02 02:16:02 +01:00
|
|
|
&auto_explain_log_verbose,
|
2008-11-19 03:59:28 +01:00
|
|
|
false,
|
|
|
|
PGC_SUSET,
|
|
|
|
0,
|
|
|
|
NULL,
|
2011-04-07 06:11:01 +02:00
|
|
|
NULL,
|
2008-11-19 03:59:28 +01:00
|
|
|
NULL);
|
|
|
|
|
2009-12-15 05:57:48 +01:00
|
|
|
DefineCustomBoolVariable("auto_explain.log_buffers",
|
|
|
|
"Log buffers usage.",
|
|
|
|
NULL,
|
|
|
|
&auto_explain_log_buffers,
|
|
|
|
false,
|
|
|
|
PGC_SUSET,
|
|
|
|
0,
|
|
|
|
NULL,
|
2011-04-07 06:11:01 +02:00
|
|
|
NULL,
|
2009-12-15 05:57:48 +01:00
|
|
|
NULL);
|
|
|
|
|
2020-04-06 04:32:15 +02:00
|
|
|
DefineCustomBoolVariable("auto_explain.log_wal",
|
|
|
|
"Log WAL usage.",
|
|
|
|
NULL,
|
|
|
|
&auto_explain_log_wal,
|
|
|
|
false,
|
|
|
|
PGC_SUSET,
|
|
|
|
0,
|
|
|
|
NULL,
|
|
|
|
NULL,
|
|
|
|
NULL);
|
|
|
|
|
2014-03-04 19:31:18 +01:00
|
|
|
DefineCustomBoolVariable("auto_explain.log_triggers",
|
|
|
|
"Include trigger statistics in plans.",
|
Phase 3 of pgindent updates.
Don't move parenthesized lines to the left, even if that means they
flow past the right margin.
By default, BSD indent lines up statement continuation lines that are
within parentheses so that they start just to the right of the preceding
left parenthesis. However, traditionally, if that resulted in the
continuation line extending to the right of the desired right margin,
then indent would push it left just far enough to not overrun the margin,
if it could do so without making the continuation line start to the left of
the current statement indent. That makes for a weird mix of indentations
unless one has been completely rigid about never violating the 80-column
limit.
This behavior has been pretty universally panned by Postgres developers.
Hence, disable it with indent's new -lpl switch, so that parenthesized
lines are always lined up with the preceding left paren.
This patch is much less interesting than the first round of indent
changes, but also bulkier, so I thought it best to separate the effects.
Discussion: https://postgr.es/m/E1dAmxK-0006EE-1r@gemulon.postgresql.org
Discussion: https://postgr.es/m/30527.1495162840@sss.pgh.pa.us
2017-06-21 21:35:54 +02:00
|
|
|
"This has no effect unless log_analyze is also set.",
|
2014-03-04 19:31:18 +01:00
|
|
|
&auto_explain_log_triggers,
|
|
|
|
false,
|
|
|
|
PGC_SUSET,
|
|
|
|
0,
|
|
|
|
NULL,
|
|
|
|
NULL,
|
|
|
|
NULL);
|
|
|
|
|
2009-08-10 07:46:50 +02:00
|
|
|
DefineCustomEnumVariable("auto_explain.log_format",
|
|
|
|
"EXPLAIN format to be used for plan logging.",
|
|
|
|
NULL,
|
|
|
|
&auto_explain_log_format,
|
|
|
|
EXPLAIN_FORMAT_TEXT,
|
|
|
|
format_options,
|
|
|
|
PGC_SUSET,
|
|
|
|
0,
|
|
|
|
NULL,
|
2011-04-07 06:11:01 +02:00
|
|
|
NULL,
|
2009-08-10 07:46:50 +02:00
|
|
|
NULL);
|
|
|
|
|
2018-07-31 14:03:57 +02:00
|
|
|
DefineCustomEnumVariable("auto_explain.log_level",
|
|
|
|
"Log level for the plan.",
|
|
|
|
NULL,
|
|
|
|
&auto_explain_log_level,
|
|
|
|
LOG,
|
|
|
|
loglevel_options,
|
|
|
|
PGC_SUSET,
|
|
|
|
0,
|
|
|
|
NULL,
|
|
|
|
NULL,
|
|
|
|
NULL);
|
|
|
|
|
2009-01-02 02:16:02 +01:00
|
|
|
DefineCustomBoolVariable("auto_explain.log_nested_statements",
|
2008-11-19 03:59:28 +01:00
|
|
|
"Log nested statements.",
|
|
|
|
NULL,
|
2009-01-02 02:16:02 +01:00
|
|
|
&auto_explain_log_nested_statements,
|
2008-11-19 03:59:28 +01:00
|
|
|
false,
|
|
|
|
PGC_SUSET,
|
|
|
|
0,
|
|
|
|
NULL,
|
2011-04-07 06:11:01 +02:00
|
|
|
NULL,
|
2008-11-19 03:59:28 +01:00
|
|
|
NULL);
|
|
|
|
|
2012-02-07 17:23:04 +01:00
|
|
|
DefineCustomBoolVariable("auto_explain.log_timing",
|
|
|
|
"Collect timing data, not just row counts.",
|
|
|
|
NULL,
|
|
|
|
&auto_explain_log_timing,
|
|
|
|
true,
|
|
|
|
PGC_SUSET,
|
|
|
|
0,
|
|
|
|
NULL,
|
|
|
|
NULL,
|
|
|
|
NULL);
|
|
|
|
|
2016-03-13 13:18:03 +01:00
|
|
|
DefineCustomRealVariable("auto_explain.sample_rate",
|
2016-03-11 15:08:34 +01:00
|
|
|
"Fraction of queries to process.",
|
2016-06-10 00:02:36 +02:00
|
|
|
NULL,
|
|
|
|
&auto_explain_sample_rate,
|
|
|
|
1.0,
|
|
|
|
0.0,
|
|
|
|
1.0,
|
|
|
|
PGC_SUSET,
|
|
|
|
0,
|
|
|
|
NULL,
|
|
|
|
NULL,
|
|
|
|
NULL);
|
2016-03-11 15:08:34 +01:00
|
|
|
|
2022-02-21 20:10:15 +01:00
|
|
|
MarkGUCPrefixReserved("auto_explain");
|
2009-01-05 14:35:38 +01:00
|
|
|
|
2008-11-19 03:59:28 +01:00
|
|
|
/* Install hooks. */
|
|
|
|
prev_ExecutorStart = ExecutorStart_hook;
|
|
|
|
ExecutorStart_hook = explain_ExecutorStart;
|
|
|
|
prev_ExecutorRun = ExecutorRun_hook;
|
|
|
|
ExecutorRun_hook = explain_ExecutorRun;
|
2011-02-27 19:43:29 +01:00
|
|
|
prev_ExecutorFinish = ExecutorFinish_hook;
|
|
|
|
ExecutorFinish_hook = explain_ExecutorFinish;
|
2008-11-19 03:59:28 +01:00
|
|
|
prev_ExecutorEnd = ExecutorEnd_hook;
|
|
|
|
ExecutorEnd_hook = explain_ExecutorEnd;
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
* ExecutorStart hook: start up logging if needed
|
|
|
|
*/
|
2010-01-06 19:07:19 +01:00
|
|
|
static void
|
2008-11-19 03:59:28 +01:00
|
|
|
explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
|
|
|
|
{
|
2016-03-11 15:08:34 +01:00
|
|
|
/*
|
2019-06-04 00:06:04 +02:00
|
|
|
* At the beginning of each top-level statement, decide whether we'll
|
|
|
|
* sample this statement. If nested-statement explaining is enabled,
|
|
|
|
* either all nested statements will be explained or none will.
|
|
|
|
*
|
|
|
|
* When in a parallel worker, we should do nothing, which we can implement
|
|
|
|
* cheaply by pretending we decided not to sample the current statement.
|
|
|
|
* If EXPLAIN is active in the parent session, data will be collected and
|
|
|
|
* reported back to the parent, and it's no business of ours to interfere.
|
2016-03-11 15:08:34 +01:00
|
|
|
*/
|
2019-06-04 00:06:04 +02:00
|
|
|
if (nesting_level == 0)
|
|
|
|
{
|
|
|
|
if (auto_explain_log_min_duration >= 0 && !IsParallelWorker())
|
Replace random(), pg_erand48(), etc with a better PRNG API and algorithm.
Standardize on xoroshiro128** as our basic PRNG algorithm, eliminating
a bunch of platform dependencies as well as fundamentally-obsolete PRNG
code. In addition, this API replacement will ease replacing the
algorithm again in future, should that become necessary.
xoroshiro128** is a few percent slower than the drand48 family,
but it can produce full-width 64-bit random values not only 48-bit,
and it should be much more trustworthy. It's likely to be noticeably
faster than the platform's random(), depending on which platform you
are thinking about; and we can have non-global state vectors easily,
unlike with random(). It is not cryptographically strong, but neither
are the functions it replaces.
Fabien Coelho, reviewed by Dean Rasheed, Aleksander Alekseev, and myself
Discussion: https://postgr.es/m/alpine.DEB.2.22.394.2105241211230.165418@pseudo
2021-11-29 03:32:36 +01:00
|
|
|
current_query_sampled = (pg_prng_double(&pg_global_prng_state) < auto_explain_sample_rate);
|
2019-06-04 00:06:04 +02:00
|
|
|
else
|
|
|
|
current_query_sampled = false;
|
|
|
|
}
|
2016-03-11 15:08:34 +01:00
|
|
|
|
2019-06-04 00:06:04 +02:00
|
|
|
if (auto_explain_enabled())
|
2008-11-19 03:59:28 +01:00
|
|
|
{
|
|
|
|
/* Enable per-node instrumentation iff log_analyze is required. */
|
2009-01-02 02:16:02 +01:00
|
|
|
if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
|
2009-12-15 05:57:48 +01:00
|
|
|
{
|
2012-02-07 17:23:04 +01:00
|
|
|
if (auto_explain_log_timing)
|
|
|
|
queryDesc->instrument_options |= INSTRUMENT_TIMER;
|
|
|
|
else
|
|
|
|
queryDesc->instrument_options |= INSTRUMENT_ROWS;
|
2009-12-15 05:57:48 +01:00
|
|
|
if (auto_explain_log_buffers)
|
|
|
|
queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
|
2020-04-06 04:32:15 +02:00
|
|
|
if (auto_explain_log_wal)
|
|
|
|
queryDesc->instrument_options |= INSTRUMENT_WAL;
|
2009-12-15 05:57:48 +01:00
|
|
|
}
|
2008-11-19 03:59:28 +01:00
|
|
|
}
|
|
|
|
|
|
|
|
if (prev_ExecutorStart)
|
|
|
|
prev_ExecutorStart(queryDesc, eflags);
|
|
|
|
else
|
|
|
|
standard_ExecutorStart(queryDesc, eflags);
|
|
|
|
|
2019-06-04 00:06:04 +02:00
|
|
|
if (auto_explain_enabled())
|
2008-11-19 03:59:28 +01:00
|
|
|
{
|
|
|
|
/*
|
2009-06-11 16:49:15 +02:00
|
|
|
* Set up to track total elapsed time in ExecutorRun. Make sure the
|
|
|
|
* space is allocated in the per-query context so it will go away at
|
|
|
|
* ExecutorEnd.
|
2008-11-19 03:59:28 +01:00
|
|
|
*/
|
|
|
|
if (queryDesc->totaltime == NULL)
|
|
|
|
{
|
|
|
|
MemoryContext oldcxt;
|
|
|
|
|
|
|
|
oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
|
2021-05-12 07:00:00 +02:00
|
|
|
queryDesc->totaltime = InstrAlloc(1, INSTRUMENT_ALL, false);
|
2008-11-19 03:59:28 +01:00
|
|
|
MemoryContextSwitchTo(oldcxt);
|
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
* ExecutorRun hook: all we need do is track nesting depth
|
|
|
|
*/
|
2010-01-06 19:07:19 +01:00
|
|
|
static void
|
2017-03-23 18:05:48 +01:00
|
|
|
explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction,
|
|
|
|
uint64 count, bool execute_once)
|
2008-11-19 03:59:28 +01:00
|
|
|
{
|
|
|
|
nesting_level++;
|
|
|
|
PG_TRY();
|
|
|
|
{
|
|
|
|
if (prev_ExecutorRun)
|
2017-03-23 18:05:48 +01:00
|
|
|
prev_ExecutorRun(queryDesc, direction, count, execute_once);
|
2008-11-19 03:59:28 +01:00
|
|
|
else
|
2017-03-23 18:05:48 +01:00
|
|
|
standard_ExecutorRun(queryDesc, direction, count, execute_once);
|
2008-11-19 03:59:28 +01:00
|
|
|
}
|
2019-11-01 11:09:52 +01:00
|
|
|
PG_FINALLY();
|
2008-11-19 03:59:28 +01:00
|
|
|
{
|
|
|
|
nesting_level--;
|
|
|
|
}
|
|
|
|
PG_END_TRY();
|
|
|
|
}
|
|
|
|
|
2011-02-27 19:43:29 +01:00
|
|
|
/*
|
|
|
|
* ExecutorFinish hook: all we need do is track nesting depth
|
|
|
|
*/
|
|
|
|
static void
|
|
|
|
explain_ExecutorFinish(QueryDesc *queryDesc)
|
|
|
|
{
|
|
|
|
nesting_level++;
|
|
|
|
PG_TRY();
|
|
|
|
{
|
|
|
|
if (prev_ExecutorFinish)
|
|
|
|
prev_ExecutorFinish(queryDesc);
|
|
|
|
else
|
|
|
|
standard_ExecutorFinish(queryDesc);
|
|
|
|
}
|
2019-11-01 11:09:52 +01:00
|
|
|
PG_FINALLY();
|
2011-02-27 19:43:29 +01:00
|
|
|
{
|
|
|
|
nesting_level--;
|
|
|
|
}
|
|
|
|
PG_END_TRY();
|
|
|
|
}
|
|
|
|
|
2008-11-19 03:59:28 +01:00
|
|
|
/*
|
|
|
|
* ExecutorEnd hook: log results if needed
|
|
|
|
*/
|
2010-01-06 19:07:19 +01:00
|
|
|
static void
|
2008-11-19 03:59:28 +01:00
|
|
|
explain_ExecutorEnd(QueryDesc *queryDesc)
|
|
|
|
{
|
2019-06-04 00:06:04 +02:00
|
|
|
if (queryDesc->totaltime && auto_explain_enabled())
|
2008-11-19 03:59:28 +01:00
|
|
|
{
|
2021-02-02 19:49:08 +01:00
|
|
|
MemoryContext oldcxt;
|
2009-06-11 16:49:15 +02:00
|
|
|
double msec;
|
2008-11-19 03:59:28 +01:00
|
|
|
|
2021-02-02 19:49:08 +01:00
|
|
|
/*
|
|
|
|
* Make sure we operate in the per-query context, so any cruft will be
|
|
|
|
* discarded later during ExecutorEnd.
|
|
|
|
*/
|
|
|
|
oldcxt = MemoryContextSwitchTo(queryDesc->estate->es_query_cxt);
|
|
|
|
|
2008-11-19 03:59:28 +01:00
|
|
|
/*
|
2009-06-11 16:49:15 +02:00
|
|
|
* Make sure stats accumulation is done. (Note: it's okay if several
|
|
|
|
* levels of hook all do this.)
|
2008-11-19 03:59:28 +01:00
|
|
|
*/
|
|
|
|
InstrEndLoop(queryDesc->totaltime);
|
|
|
|
|
|
|
|
/* Log plan if duration is exceeded. */
|
|
|
|
msec = queryDesc->totaltime->total * 1000.0;
|
2009-01-02 02:16:02 +01:00
|
|
|
if (msec >= auto_explain_log_min_duration)
|
2008-11-19 03:59:28 +01:00
|
|
|
{
|
2015-01-15 19:39:33 +01:00
|
|
|
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);
|
2020-04-06 04:32:15 +02:00
|
|
|
es->wal = (es->analyze && auto_explain_log_wal);
|
2015-01-15 19:39:33 +01:00
|
|
|
es->timing = (es->analyze && auto_explain_log_timing);
|
|
|
|
es->summary = es->analyze;
|
|
|
|
es->format = auto_explain_log_format;
|
2019-04-04 00:04:31 +02:00
|
|
|
es->settings = auto_explain_log_settings;
|
2015-01-15 19:39:33 +01:00
|
|
|
|
|
|
|
ExplainBeginOutput(es);
|
|
|
|
ExplainQueryText(es, queryDesc);
|
|
|
|
ExplainPrintPlan(es, queryDesc);
|
|
|
|
if (es->analyze && auto_explain_log_triggers)
|
|
|
|
ExplainPrintTriggers(es, queryDesc);
|
2018-09-25 21:54:29 +02:00
|
|
|
if (es->costs)
|
2018-10-03 21:48:37 +02:00
|
|
|
ExplainPrintJITSummary(es, queryDesc);
|
2015-01-15 19:39:33 +01:00
|
|
|
ExplainEndOutput(es);
|
2008-11-19 03:59:28 +01:00
|
|
|
|
|
|
|
/* Remove last line break */
|
2015-01-15 19:39:33 +01:00
|
|
|
if (es->str->len > 0 && es->str->data[es->str->len - 1] == '\n')
|
|
|
|
es->str->data[--es->str->len] = '\0';
|
2008-11-19 03:59:28 +01:00
|
|
|
|
2012-02-13 14:22:15 +01:00
|
|
|
/* Fix JSON to output an object */
|
|
|
|
if (auto_explain_log_format == EXPLAIN_FORMAT_JSON)
|
|
|
|
{
|
2015-01-15 19:39:33 +01:00
|
|
|
es->str->data[0] = '{';
|
|
|
|
es->str->data[es->str->len - 1] = '}';
|
2012-02-13 14:22:15 +01:00
|
|
|
}
|
|
|
|
|
2008-11-19 03:59:28 +01:00
|
|
|
/*
|
|
|
|
* 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.
|
|
|
|
*/
|
2018-07-31 14:03:57 +02:00
|
|
|
ereport(auto_explain_log_level,
|
2008-11-19 03:59:28 +01:00
|
|
|
(errmsg("duration: %.3f ms plan:\n%s",
|
2015-01-15 19:39:33 +01:00
|
|
|
msec, es->str->data),
|
2010-02-26 03:01:40 +01:00
|
|
|
errhidestmt(true)));
|
2008-11-19 03:59:28 +01:00
|
|
|
}
|
2021-02-02 19:49:08 +01:00
|
|
|
|
|
|
|
MemoryContextSwitchTo(oldcxt);
|
2008-11-19 03:59:28 +01:00
|
|
|
}
|
|
|
|
|
|
|
|
if (prev_ExecutorEnd)
|
|
|
|
prev_ExecutorEnd(queryDesc);
|
|
|
|
else
|
|
|
|
standard_ExecutorEnd(queryDesc);
|
|
|
|
}
|