auto_explain.c File Reference

#include "postgres.h"
#include <limits.h>
#include "access/parallel.h"
#include "commands/explain.h"
#include "commands/explain_format.h"
#include "commands/explain_state.h"
#include "common/pg_prng.h"
#include "executor/instrument.h"
#include "utils/guc.h"

Include dependency graph for auto_explain.c:

Go to the source code of this file.

Macros
#define	auto_explain_enabled()

Functions
	PG_MODULE_MAGIC_EXT (.name="auto_explain",.version=PG_VERSION)
static void	explain_ExecutorStart (QueryDesc *queryDesc, int eflags)
static void	explain_ExecutorRun (QueryDesc *queryDesc, ScanDirection direction, uint64 count)
static void	explain_ExecutorFinish (QueryDesc *queryDesc)
static void	explain_ExecutorEnd (QueryDesc *queryDesc)
void	_PG_init (void)

Variables
static int	auto_explain_log_min_duration = -1
static int	auto_explain_log_parameter_max_length = -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_wal = false
static bool	auto_explain_log_triggers = false
static bool	auto_explain_log_timing = true
static bool	auto_explain_log_settings = false
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 []
static const struct config_enum_entry	loglevel_options []
static int	nesting_level = 0
static bool	current_query_sampled = false
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

Macro Definition Documentation

auto_explain_enabled

#define auto_explain_enabled

(

)

Value:

    (auto_explain_log_min_duration >= 0 && \
     (nesting_level == 0 || auto_explain_log_nested_statements) && \
     current_query_sampled)

Definition at line 73 of file auto_explain.c.

Function Documentation

_PG_init()

void _PG_init

(

void

)

Definition at line 96 of file auto_explain.c.

{
    /* Define custom GUC variables. */
    DefineCustomIntVariable("auto_explain.log_min_duration",
                            "Sets the minimum execution time above which plans will be logged.",
                            "-1 disables logging plans. 0 means log all plans.",
                            &auto_explain_log_min_duration,
                            -1,
                            -1, INT_MAX,
                            PGC_SUSET,
                            GUC_UNIT_MS,
                            NULL,
                            NULL,
                            NULL);
 
    DefineCustomIntVariable("auto_explain.log_parameter_max_length",
                            "Sets the maximum length of query parameter values to log.",
                            "-1 means log values in full.",
                            &auto_explain_log_parameter_max_length,
                            -1,
                            -1, INT_MAX,
                            PGC_SUSET,
                            GUC_UNIT_BYTE,
                            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_settings",
                             "Log modified configuration parameters affecting query planning.",
                             NULL,
                             &auto_explain_log_settings,
                             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_wal",
                             "Log WAL usage.",
                             NULL,
                             &auto_explain_log_wal,
                             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);
 
    MarkGUCPrefixReserved("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;
}

References auto_explain_log_analyze, auto_explain_log_buffers, auto_explain_log_format, auto_explain_log_level, auto_explain_log_min_duration, auto_explain_log_nested_statements, auto_explain_log_parameter_max_length, auto_explain_log_settings, auto_explain_log_timing, auto_explain_log_triggers, auto_explain_log_verbose, auto_explain_log_wal, auto_explain_sample_rate, DefineCustomBoolVariable(), DefineCustomEnumVariable(), DefineCustomIntVariable(), DefineCustomRealVariable(), ExecutorEnd_hook, ExecutorFinish_hook, ExecutorRun_hook, ExecutorStart_hook, explain_ExecutorEnd(), explain_ExecutorFinish(), explain_ExecutorRun(), explain_ExecutorStart(), EXPLAIN_FORMAT_TEXT, format_options, GUC_UNIT_BYTE, GUC_UNIT_MS, LOG, loglevel_options, MarkGUCPrefixReserved(), PGC_SUSET, prev_ExecutorEnd, prev_ExecutorFinish, prev_ExecutorRun, and prev_ExecutorStart.

explain_ExecutorEnd()

static void explain_ExecutorEnd ( QueryDesc *  queryDesc )

static

Definition at line 371 of file auto_explain.c.

{
    if (queryDesc->totaltime && auto_explain_enabled())
    {
        MemoryContext oldcxt;
        double      msec;
 
        /*
         * 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);
 
        /*
         * 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->wal = (es->analyze && auto_explain_log_wal);
            es->timing = (es->analyze && auto_explain_log_timing);
            es->summary = es->analyze;
            /* No support for MEMORY */
            /* es->memory = false; */
            es->format = auto_explain_log_format;
            es->settings = auto_explain_log_settings;
 
            ExplainBeginOutput(es);
            ExplainQueryText(es, queryDesc);
            ExplainQueryParameters(es, queryDesc->params, auto_explain_log_parameter_max_length);
            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)));
        }
 
        MemoryContextSwitchTo(oldcxt);
    }
 
    if (prev_ExecutorEnd)
        prev_ExecutorEnd(queryDesc);
    else
        standard_ExecutorEnd(queryDesc);
}

References ExplainState::analyze, auto_explain_enabled, auto_explain_log_analyze, auto_explain_log_buffers, auto_explain_log_format, auto_explain_log_level, auto_explain_log_min_duration, auto_explain_log_parameter_max_length, auto_explain_log_settings, auto_explain_log_timing, auto_explain_log_triggers, auto_explain_log_verbose, auto_explain_log_wal, ExplainState::buffers, ExplainState::costs, StringInfoData::data, ereport, errhidestmt(), errmsg(), EState::es_query_cxt, QueryDesc::estate, EXPLAIN_FORMAT_JSON, ExplainBeginOutput(), ExplainEndOutput(), ExplainPrintJITSummary(), ExplainPrintPlan(), ExplainPrintTriggers(), ExplainQueryParameters(), ExplainQueryText(), ExplainState::format, InstrEndLoop(), QueryDesc::instrument_options, StringInfoData::len, MemoryContextSwitchTo(), NewExplainState(), QueryDesc::params, prev_ExecutorEnd, ExplainState::settings, standard_ExecutorEnd(), ExplainState::str, ExplainState::summary, ExplainState::timing, Instrumentation::total, QueryDesc::totaltime, ExplainState::verbose, and ExplainState::wal.

Referenced by _PG_init().

explain_ExecutorFinish()

static void explain_ExecutorFinish ( QueryDesc *  queryDesc )

static

Definition at line 350 of file auto_explain.c.

{
    nesting_level++;
    PG_TRY();
    {
        if (prev_ExecutorFinish)
            prev_ExecutorFinish(queryDesc);
        else
            standard_ExecutorFinish(queryDesc);
    }
    PG_FINALLY();
    {
        nesting_level--;
    }
    PG_END_TRY();
}

References nesting_level, PG_END_TRY, PG_FINALLY, PG_TRY, prev_ExecutorFinish, and standard_ExecutorFinish().

Referenced by _PG_init().

explain_ExecutorRun()

static void explain_ExecutorRun ( QueryDesc *  queryDesc, ScanDirection  direction, uint64  count  )

static

Definition at line 328 of file auto_explain.c.

{
    nesting_level++;
    PG_TRY();
    {
        if (prev_ExecutorRun)
            prev_ExecutorRun(queryDesc, direction, count);
        else
            standard_ExecutorRun(queryDesc, direction, count);
    }
    PG_FINALLY();
    {
        nesting_level--;
    }
    PG_END_TRY();
}

References nesting_level, PG_END_TRY, PG_FINALLY, PG_TRY, prev_ExecutorRun, and standard_ExecutorRun().

Referenced by _PG_init().

explain_ExecutorStart()

static void explain_ExecutorStart ( QueryDesc *  queryDesc, int  eflags  )

static

Definition at line 265 of file auto_explain.c.

{
    /*
     * 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.
     */
    if (nesting_level == 0)
    {
        if (auto_explain_log_min_duration >= 0 && !IsParallelWorker())
            current_query_sampled = (pg_prng_double(&pg_global_prng_state) < auto_explain_sample_rate);
        else
            current_query_sampled = false;
    }
 
    if (auto_explain_enabled())
    {
        /* 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 (auto_explain_log_wal)
                queryDesc->instrument_options |= INSTRUMENT_WAL;
        }
    }
 
    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, INSTRUMENT_ALL, false);
            MemoryContextSwitchTo(oldcxt);
        }
    }
}

References auto_explain_enabled, auto_explain_log_analyze, auto_explain_log_buffers, auto_explain_log_min_duration, auto_explain_log_timing, auto_explain_log_wal, auto_explain_sample_rate, current_query_sampled, EState::es_query_cxt, QueryDesc::estate, EXEC_FLAG_EXPLAIN_ONLY, InstrAlloc(), INSTRUMENT_ALL, INSTRUMENT_BUFFERS, QueryDesc::instrument_options, INSTRUMENT_ROWS, INSTRUMENT_TIMER, INSTRUMENT_WAL, IsParallelWorker, MemoryContextSwitchTo(), nesting_level, pg_global_prng_state, pg_prng_double(), prev_ExecutorStart, standard_ExecutorStart(), and QueryDesc::totaltime.

Referenced by _PG_init().

PG_MODULE_MAGIC_EXT()

PG_MODULE_MAGIC_EXT	(	.	name = "auto_explain",
		.	version = PG_VERSION
	)

Variable Documentation

auto_explain_log_analyze

bool auto_explain_log_analyze = false

static

Definition at line 33 of file auto_explain.c.

Referenced by _PG_init(), explain_ExecutorEnd(), and explain_ExecutorStart().

auto_explain_log_buffers

bool auto_explain_log_buffers = false

static

Definition at line 35 of file auto_explain.c.

Referenced by _PG_init(), explain_ExecutorEnd(), and explain_ExecutorStart().

auto_explain_log_format

int auto_explain_log_format = EXPLAIN_FORMAT_TEXT

static

Definition at line 40 of file auto_explain.c.

Referenced by _PG_init(), and explain_ExecutorEnd().

auto_explain_log_level

int auto_explain_log_level = LOG

static

Definition at line 41 of file auto_explain.c.

Referenced by _PG_init(), and explain_ExecutorEnd().

auto_explain_log_min_duration

int auto_explain_log_min_duration = -1

static

Definition at line 31 of file auto_explain.c.

Referenced by _PG_init(), explain_ExecutorEnd(), and explain_ExecutorStart().

auto_explain_log_nested_statements

bool auto_explain_log_nested_statements = false

static

Definition at line 42 of file auto_explain.c.

Referenced by _PG_init().

auto_explain_log_parameter_max_length

int auto_explain_log_parameter_max_length = -1

static

Definition at line 32 of file auto_explain.c.

Referenced by _PG_init(), and explain_ExecutorEnd().

auto_explain_log_settings

bool auto_explain_log_settings = false

static

Definition at line 39 of file auto_explain.c.

Referenced by _PG_init(), and explain_ExecutorEnd().

auto_explain_log_timing

bool auto_explain_log_timing = true

static

Definition at line 38 of file auto_explain.c.

Referenced by _PG_init(), explain_ExecutorEnd(), and explain_ExecutorStart().

auto_explain_log_triggers

bool auto_explain_log_triggers = false

static

Definition at line 37 of file auto_explain.c.

Referenced by _PG_init(), and explain_ExecutorEnd().

auto_explain_log_verbose

bool auto_explain_log_verbose = false

static

Definition at line 34 of file auto_explain.c.

Referenced by _PG_init(), and explain_ExecutorEnd().

auto_explain_log_wal

bool auto_explain_log_wal = false

static

Definition at line 36 of file auto_explain.c.

Referenced by _PG_init(), explain_ExecutorEnd(), and explain_ExecutorStart().

auto_explain_sample_rate

double auto_explain_sample_rate = 1

static

Definition at line 43 of file auto_explain.c.

Referenced by _PG_init(), and explain_ExecutorStart().

current_query_sampled

bool current_query_sampled = false

static

Definition at line 71 of file auto_explain.c.

Referenced by explain_ExecutorStart().

format_options

const struct config_enum_entry format_options[]

static

Initial value:

= {
    {"text", EXPLAIN_FORMAT_TEXT, false},
    {"xml", EXPLAIN_FORMAT_XML, false},
    {"json", EXPLAIN_FORMAT_JSON, false},
    {"yaml", EXPLAIN_FORMAT_YAML, false},
    {NULL, 0, false}
}

Definition at line 45 of file auto_explain.c.

Referenced by _PG_init().

loglevel_options

const struct config_enum_entry loglevel_options[]

static

Initial value:

= {
    {"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}
}

Definition at line 53 of file auto_explain.c.

Referenced by _PG_init().

nesting_level

int nesting_level = 0

static

Definition at line 68 of file auto_explain.c.

Referenced by explain_ExecutorFinish(), explain_ExecutorRun(), and explain_ExecutorStart().

prev_ExecutorEnd

ExecutorEnd_hook_type prev_ExecutorEnd = NULL

static

Definition at line 82 of file auto_explain.c.

Referenced by _PG_init(), and explain_ExecutorEnd().

prev_ExecutorFinish

ExecutorFinish_hook_type prev_ExecutorFinish = NULL

static

Definition at line 81 of file auto_explain.c.

Referenced by _PG_init(), and explain_ExecutorFinish().

prev_ExecutorRun

ExecutorRun_hook_type prev_ExecutorRun = NULL

static

Definition at line 80 of file auto_explain.c.

Referenced by _PG_init(), and explain_ExecutorRun().

prev_ExecutorStart

ExecutorStart_hook_type prev_ExecutorStart = NULL

static

Definition at line 79 of file auto_explain.c.

Referenced by _PG_init(), and explain_ExecutorStart().