diff options
Diffstat (limited to 'contrib/auto_explain/auto_explain.c')
| -rw-r--r-- | contrib/auto_explain/auto_explain.c | 228 |
1 files changed, 228 insertions, 0 deletions
diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c new file mode 100644 index 00000000000..f6816020220 --- /dev/null +++ b/contrib/auto_explain/auto_explain.c @@ -0,0 +1,228 @@ +/*------------------------------------------------------------------------- + * + * 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); +} |