2008-11-19 03:59:28 +01:00
|
|
|
/*-------------------------------------------------------------------------
|
|
|
|
*
|
|
|
|
* auto_explain.c
|
|
|
|
*
|
|
|
|
*
|
2024-01-04 02:49:05 +01:00
|
|
|
* Copyright (c) 2008-2024, 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"
|
2022-07-06 02:55:30 +02:00
|
|
|
#include "nodes/params.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-01-02 02:16:02 +01:00
|
|
|
static int auto_explain_log_min_duration = -1; /* msec or -1 */
|
2022-07-06 02:55:30 +02:00
|
|
|
static int auto_explain_log_parameter_max_length = -1; /* bytes 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[] = {
|
|
|
|
{"text", EXPLAIN_FORMAT_TEXT, false},
|
|
|
|
{"xml", EXPLAIN_FORMAT_XML, false},
|
|
|
|
{"json", EXPLAIN_FORMAT_JSON, false},
|
2009-12-11 02:33:35 +01:00
|
|
|
{"yaml", EXPLAIN_FORMAT_YAML, false},
|
2009-08-10 07:46:50 +02:00
|
|
|
{NULL, 0, false}
|
|
|
|
};
|
|
|
|
|
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 */
|
|
|
|
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;
|
2008-11-19 03:59:28 +01:00
|
|
|
static ExecutorEnd_hook_type prev_ExecutorEnd = NULL;
|
|
|
|
|
|
|
|
static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags);
|
|
|
|
static void explain_ExecutorRun(QueryDesc *queryDesc,
|
|
|
|
ScanDirection direction,
|
2017-03-23 18:05:48 +01:00
|
|
|
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",
|
2008-11-19 03:59:28 +01: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);
|
|
|
|
|
2022-07-06 02:55:30 +02:00
|
|
|
DefineCustomIntVariable("auto_explain.log_parameter_max_length",
|
|
|
|
"Sets the maximum length of query parameters to log.",
|
|
|
|
"Zero logs no query parameters, -1 logs them in full.",
|
|
|
|
&auto_explain_log_parameter_max_length,
|
|
|
|
-1,
|
|
|
|
-1, INT_MAX,
|
|
|
|
PGC_SUSET,
|
|
|
|
GUC_UNIT_BYTE,
|
|
|
|
NULL,
|
|
|
|
NULL,
|
|
|
|
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.",
|
|
|
|
"This has no effect unless log_analyze is also set.",
|
|
|
|
&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.",
|
|
|
|
NULL,
|
2016-03-13 13:18:03 +01:00
|
|
|
&auto_explain_sample_rate,
|
2016-03-11 15:08:34 +01:00
|
|
|
1.0,
|
|
|
|
0.0,
|
|
|
|
1.0,
|
|
|
|
PGC_SUSET,
|
|
|
|
0,
|
|
|
|
NULL,
|
|
|
|
NULL,
|
|
|
|
NULL);
|
|
|
|
|
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
|
|
|
{
|
|
|
|
/*
|
|
|
|
* 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.
|
|
|
|
*/
|
|
|
|
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;
|
2008-11-19 03:59:28 +01:00
|
|
|
double msec;
|
|
|
|
|
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
|
|
|
/*
|
|
|
|
* Make sure stats accumulation is done. (Note: it's okay if several
|
|
|
|
* levels of hook all do this.)
|
|
|
|
*/
|
|
|
|
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);
|
2022-07-06 02:55:30 +02:00
|
|
|
ExplainQueryParameters(es, queryDesc->params, auto_explain_log_parameter_max_length);
|
2015-01-15 19:39:33 +01:00
|
|
|
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-16 23:19:59 +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);
|
|
|
|
}
|