mirror of
https://git.postgresql.org/git/postgresql.git
synced 2024-08-25 06:07:20 +02:00
229 lines
5.3 KiB
C
229 lines
5.3 KiB
C
|
/*-------------------------------------------------------------------------
|
||
|
*
|
||
|
* auto_explain.c
|
||
|
*
|
||
|
*
|
||
|
* Copyright (c) 2008, PostgreSQL Global Development Group
|
||
|
*
|
||
|
* IDENTIFICATION
|
||
|
* $PostgreSQL: pgsql/contrib/auto_explain/auto_explain.c,v 1.1 2008/11/19 02:59:28 tgl Exp $
|
||
|
*
|
||
|
*-------------------------------------------------------------------------
|
||
|
*/
|
||
|
#include "postgres.h"
|
||
|
|
||
|
#include "commands/explain.h"
|
||
|
#include "executor/instrument.h"
|
||
|
#include "utils/guc.h"
|
||
|
|
||
|
PG_MODULE_MAGIC;
|
||
|
|
||
|
#define GUCNAME(name) ("explain." name)
|
||
|
|
||
|
/* GUC variables */
|
||
|
static int explain_log_min_duration = -1; /* msec or -1 */
|
||
|
static bool explain_log_analyze = false;
|
||
|
static bool explain_log_verbose = false;
|
||
|
static bool explain_log_nested = false;
|
||
|
|
||
|
/* Current nesting depth of ExecutorRun calls */
|
||
|
static int nesting_level = 0;
|
||
|
|
||
|
/* Saved hook values in case of unload */
|
||
|
static ExecutorStart_hook_type prev_ExecutorStart = NULL;
|
||
|
static ExecutorRun_hook_type prev_ExecutorRun = NULL;
|
||
|
static ExecutorEnd_hook_type prev_ExecutorEnd = NULL;
|
||
|
|
||
|
#define auto_explain_enabled() \
|
||
|
(explain_log_min_duration >= 0 && \
|
||
|
(nesting_level == 0 || explain_log_nested))
|
||
|
|
||
|
void _PG_init(void);
|
||
|
void _PG_fini(void);
|
||
|
|
||
|
static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags);
|
||
|
static void explain_ExecutorRun(QueryDesc *queryDesc,
|
||
|
ScanDirection direction,
|
||
|
long count);
|
||
|
static void explain_ExecutorEnd(QueryDesc *queryDesc);
|
||
|
|
||
|
|
||
|
/*
|
||
|
* Module load callback
|
||
|
*/
|
||
|
void
|
||
|
_PG_init(void)
|
||
|
{
|
||
|
/* Define custom GUC variables. */
|
||
|
DefineCustomIntVariable(GUCNAME("log_min_duration"),
|
||
|
"Sets the minimum execution time above which plans will be logged.",
|
||
|
"Zero prints all plans. -1 turns this feature off.",
|
||
|
&explain_log_min_duration,
|
||
|
-1,
|
||
|
-1, INT_MAX / 1000,
|
||
|
PGC_SUSET,
|
||
|
GUC_UNIT_MS,
|
||
|
NULL,
|
||
|
NULL);
|
||
|
|
||
|
DefineCustomBoolVariable(GUCNAME("log_analyze"),
|
||
|
"Use EXPLAIN ANALYZE for plan logging.",
|
||
|
NULL,
|
||
|
&explain_log_analyze,
|
||
|
false,
|
||
|
PGC_SUSET,
|
||
|
0,
|
||
|
NULL,
|
||
|
NULL);
|
||
|
|
||
|
DefineCustomBoolVariable(GUCNAME("log_verbose"),
|
||
|
"Use EXPLAIN VERBOSE for plan logging.",
|
||
|
NULL,
|
||
|
&explain_log_verbose,
|
||
|
false,
|
||
|
PGC_SUSET,
|
||
|
0,
|
||
|
NULL,
|
||
|
NULL);
|
||
|
|
||
|
DefineCustomBoolVariable(GUCNAME("log_nested_statements"),
|
||
|
"Log nested statements.",
|
||
|
NULL,
|
||
|
&explain_log_nested,
|
||
|
false,
|
||
|
PGC_SUSET,
|
||
|
0,
|
||
|
NULL,
|
||
|
NULL);
|
||
|
|
||
|
/* Install hooks. */
|
||
|
prev_ExecutorStart = ExecutorStart_hook;
|
||
|
ExecutorStart_hook = explain_ExecutorStart;
|
||
|
prev_ExecutorRun = ExecutorRun_hook;
|
||
|
ExecutorRun_hook = explain_ExecutorRun;
|
||
|
prev_ExecutorEnd = ExecutorEnd_hook;
|
||
|
ExecutorEnd_hook = explain_ExecutorEnd;
|
||
|
}
|
||
|
|
||
|
/*
|
||
|
* Module unload callback
|
||
|
*/
|
||
|
void
|
||
|
_PG_fini(void)
|
||
|
{
|
||
|
/* Uninstall hooks. */
|
||
|
ExecutorStart_hook = prev_ExecutorStart;
|
||
|
ExecutorRun_hook = prev_ExecutorRun;
|
||
|
ExecutorEnd_hook = prev_ExecutorEnd;
|
||
|
}
|
||
|
|
||
|
/*
|
||
|
* ExecutorStart hook: start up logging if needed
|
||
|
*/
|
||
|
void
|
||
|
explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
|
||
|
{
|
||
|
if (auto_explain_enabled())
|
||
|
{
|
||
|
/* Enable per-node instrumentation iff log_analyze is required. */
|
||
|
if (explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
|
||
|
queryDesc->doInstrument = true;
|
||
|
}
|
||
|
|
||
|
if (prev_ExecutorStart)
|
||
|
prev_ExecutorStart(queryDesc, eflags);
|
||
|
else
|
||
|
standard_ExecutorStart(queryDesc, eflags);
|
||
|
|
||
|
if (auto_explain_enabled())
|
||
|
{
|
||
|
/*
|
||
|
* 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);
|
||
|
queryDesc->totaltime = InstrAlloc(1);
|
||
|
MemoryContextSwitchTo(oldcxt);
|
||
|
}
|
||
|
}
|
||
|
}
|
||
|
|
||
|
/*
|
||
|
* ExecutorRun hook: all we need do is track nesting depth
|
||
|
*/
|
||
|
void
|
||
|
explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, long count)
|
||
|
{
|
||
|
nesting_level++;
|
||
|
PG_TRY();
|
||
|
{
|
||
|
if (prev_ExecutorRun)
|
||
|
prev_ExecutorRun(queryDesc, direction, count);
|
||
|
else
|
||
|
standard_ExecutorRun(queryDesc, direction, count);
|
||
|
nesting_level--;
|
||
|
}
|
||
|
PG_CATCH();
|
||
|
{
|
||
|
nesting_level--;
|
||
|
PG_RE_THROW();
|
||
|
}
|
||
|
PG_END_TRY();
|
||
|
}
|
||
|
|
||
|
/*
|
||
|
* ExecutorEnd hook: log results if needed
|
||
|
*/
|
||
|
void
|
||
|
explain_ExecutorEnd(QueryDesc *queryDesc)
|
||
|
{
|
||
|
if (queryDesc->totaltime && auto_explain_enabled())
|
||
|
{
|
||
|
double msec;
|
||
|
|
||
|
/*
|
||
|
* 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;
|
||
|
if (msec >= explain_log_min_duration)
|
||
|
{
|
||
|
StringInfoData buf;
|
||
|
|
||
|
initStringInfo(&buf);
|
||
|
ExplainPrintPlan(&buf, queryDesc,
|
||
|
queryDesc->doInstrument && explain_log_analyze,
|
||
|
explain_log_verbose);
|
||
|
|
||
|
/* Remove last line break */
|
||
|
if (buf.len > 0 && buf.data[buf.len - 1] == '\n')
|
||
|
buf.data[--buf.len] = '\0';
|
||
|
|
||
|
/*
|
||
|
* 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(LOG,
|
||
|
(errmsg("duration: %.3f ms plan:\n%s",
|
||
|
msec, buf.data)));
|
||
|
|
||
|
pfree(buf.data);
|
||
|
}
|
||
|
}
|
||
|
|
||
|
if (prev_ExecutorEnd)
|
||
|
prev_ExecutorEnd(queryDesc);
|
||
|
else
|
||
|
standard_ExecutorEnd(queryDesc);
|
||
|
}
|