/*------------------------------------------------------------------------- * * auto_explain.c * * * Copyright (c) 2008-2019, PostgreSQL Global Development Group * * IDENTIFICATION * contrib/auto_explain/auto_explain.c * *------------------------------------------------------------------------- */ #include "postgres.h" #include #include "commands/explain.h" #include "executor/instrument.h" #include "jit/jit.h" #include "utils/guc.h" PG_MODULE_MAGIC; /* GUC variables */ static int auto_explain_log_min_duration = -1; /* msec or -1 */ static bool auto_explain_log_analyze = false; static bool auto_explain_log_verbose = false; static bool auto_explain_log_buffers = false; static bool auto_explain_log_triggers = false; static bool auto_explain_log_timing = true; 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 const struct config_enum_entry format_options[] = { {"text", EXPLAIN_FORMAT_TEXT, false}, {"xml", EXPLAIN_FORMAT_XML, false}, {"json", EXPLAIN_FORMAT_JSON, false}, {"yaml", EXPLAIN_FORMAT_YAML, false}, {NULL, 0, false} }; 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} }; /* 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 ExecutorFinish_hook_type prev_ExecutorFinish = NULL; static ExecutorEnd_hook_type prev_ExecutorEnd = NULL; /* Is the current query sampled, per backend */ static bool current_query_sampled = true; #define auto_explain_enabled() \ (auto_explain_log_min_duration >= 0 && \ (nesting_level == 0 || auto_explain_log_nested_statements)) void _PG_init(void); void _PG_fini(void); static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags); static void explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count, bool execute_once); static void explain_ExecutorFinish(QueryDesc *queryDesc); static void explain_ExecutorEnd(QueryDesc *queryDesc); /* * Module load callback */ void _PG_init(void) { /* Define custom GUC variables. */ DefineCustomIntVariable("auto_explain.log_min_duration", "Sets the minimum execution time above which plans will be logged.", "Zero prints all plans. -1 turns this feature off.", &auto_explain_log_min_duration, -1, -1, INT_MAX, PGC_SUSET, GUC_UNIT_MS, NULL, NULL, NULL); DefineCustomBoolVariable("auto_explain.log_analyze", "Use EXPLAIN ANALYZE for plan logging.", NULL, &auto_explain_log_analyze, false, PGC_SUSET, 0, NULL, NULL, NULL); DefineCustomBoolVariable("auto_explain.log_verbose", "Use EXPLAIN VERBOSE for plan logging.", NULL, &auto_explain_log_verbose, false, PGC_SUSET, 0, NULL, NULL, NULL); DefineCustomBoolVariable("auto_explain.log_buffers", "Log buffers usage.", NULL, &auto_explain_log_buffers, false, PGC_SUSET, 0, NULL, NULL, NULL); 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); 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, NULL, NULL); DefineCustomEnumVariable("auto_explain.log_level", "Log level for the plan.", NULL, &auto_explain_log_level, LOG, loglevel_options, PGC_SUSET, 0, NULL, NULL, NULL); DefineCustomBoolVariable("auto_explain.log_nested_statements", "Log nested statements.", NULL, &auto_explain_log_nested_statements, false, PGC_SUSET, 0, NULL, NULL, NULL); DefineCustomBoolVariable("auto_explain.log_timing", "Collect timing data, not just row counts.", NULL, &auto_explain_log_timing, true, PGC_SUSET, 0, NULL, NULL, NULL); DefineCustomRealVariable("auto_explain.sample_rate", "Fraction of queries to process.", NULL, &auto_explain_sample_rate, 1.0, 0.0, 1.0, PGC_SUSET, 0, NULL, NULL, NULL); EmitWarningsOnPlaceholders("auto_explain"); /* Install hooks. */ prev_ExecutorStart = ExecutorStart_hook; ExecutorStart_hook = explain_ExecutorStart; prev_ExecutorRun = ExecutorRun_hook; ExecutorRun_hook = explain_ExecutorRun; prev_ExecutorFinish = ExecutorFinish_hook; ExecutorFinish_hook = explain_ExecutorFinish; 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; ExecutorFinish_hook = prev_ExecutorFinish; ExecutorEnd_hook = prev_ExecutorEnd; } /* * ExecutorStart hook: start up logging if needed */ static void explain_ExecutorStart(QueryDesc *queryDesc, int eflags) { /* * For rate sampling, randomly choose top-level statement. Either all * nested statements will be explained or none will. */ if (auto_explain_log_min_duration >= 0 && nesting_level == 0) current_query_sampled = (random() < auto_explain_sample_rate * MAX_RANDOM_VALUE); if (auto_explain_enabled() && current_query_sampled) { /* Enable per-node instrumentation iff log_analyze is required. */ if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0) { if (auto_explain_log_timing) queryDesc->instrument_options |= INSTRUMENT_TIMER; else queryDesc->instrument_options |= INSTRUMENT_ROWS; if (auto_explain_log_buffers) queryDesc->instrument_options |= INSTRUMENT_BUFFERS; } } if (prev_ExecutorStart) prev_ExecutorStart(queryDesc, eflags); else standard_ExecutorStart(queryDesc, eflags); if (auto_explain_enabled() && current_query_sampled) { /* * 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, INSTRUMENT_ALL); MemoryContextSwitchTo(oldcxt); } } } /* * ExecutorRun hook: all we need do is track nesting depth */ static void explain_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 count, bool execute_once) { nesting_level++; PG_TRY(); { if (prev_ExecutorRun) prev_ExecutorRun(queryDesc, direction, count, execute_once); else standard_ExecutorRun(queryDesc, direction, count, execute_once); nesting_level--; } PG_CATCH(); { nesting_level--; PG_RE_THROW(); } PG_END_TRY(); } /* * 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); nesting_level--; } PG_CATCH(); { nesting_level--; PG_RE_THROW(); } PG_END_TRY(); } /* * ExecutorEnd hook: log results if needed */ static void explain_ExecutorEnd(QueryDesc *queryDesc) { if (queryDesc->totaltime && auto_explain_enabled() && current_query_sampled) { 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 >= 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; 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))); pfree(es->str->data); } } if (prev_ExecutorEnd) prev_ExecutorEnd(queryDesc); else standard_ExecutorEnd(queryDesc); }