10000 Add TIMING option to EXPLAIN, to allow eliminating of timing overhead. · postgrespro/postgres_cluster@af7914c · GitHub
[go: up one dir, main page]
Skip to content

Commit af7914c

Browse files
robertmhaasrobertmhaas
committed
Add TIMING option to EXPLAIN, to allow eliminating of timing overhead.
Sometimes it may be useful to get actual row counts out of EXPLAIN (ANALYZE) without paying the cost of timing every node entry/exit. With this patch, you can say EXPLAIN (ANALYZE, TIMING OFF) to get that. Tomas Vondra, reviewed by Eric Theise, with minor doc changes by me.
1 parent 1631598 commit af7914c

File tree

6 files changed

+97
-22
lines changed
  • contrib/auto_explain
  • doc/src/sgml/ref
    • < 8000 div class="PRIVATE_VisuallyHidden prc-TreeView-TreeViewVisuallyHidden-4-mPv" aria-hidden="true" id=":RbflddabH1:">
      explain.sgml
  • src

    • 6 files changed

    +97
    -22
    lines changed

    ‎contrib/auto_explain/auto_explain.c

    Lines changed: 18 additions & 1 deletion
    Original file line numberDiff line numberDiff line change
    @@ -23,6 +23,7 @@ static int auto_explain_log_min_duration = -1; /* msec or -1 */
    2323
    static bool auto_explain_log_analyze = false;
    2424
    static bool auto_explain_log_verbose = false;
    2525
    static bool auto_explain_log_buffers = false;
    26+
    static bool auto_explain_log_timing = false;
    2627
    static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
    2728
    static bool auto_explain_log_nested_statements = false;
    2829

    @@ -133,6 +134,17 @@ _PG_init(void)
    133134
    NULL,
    134135
    NULL);
    135136

    137+
    DefineCustomBoolVariable("auto_explain.log_timing",
    138+
    "Collect timing data, not just row counts.",
    139+
    NULL,
    140+
    &auto_explain_log_timing,
    141+
    true,
    142+
    PGC_SUSET,
    143+
    0,
    144+
    NULL,
    145+
    NULL,
    146+
    NULL);
    147+
    136148
    EmitWarningsOnPlaceholders("auto_explain");
    137149

    138150
    /* Install hooks. */
    @@ -170,7 +182,12 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
    170182
    /* Enable per-node instrumentation iff log_analyze is required. */
    171183
    if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
    172184
    {
    173-
    queryDesc->instrument_options |= INSTRUMENT_TIMER;
    185+
    if (auto_explain_log_timing)
    186+
    queryDesc->instrument_options |= INSTRUMENT_TIMER;
    187+
    else
    188+
    queryDesc->instrument_options |= INSTRUMENT_ROWS;
    189+
    190+
    174191
    if (auto_explain_log_buffers)
    175192
    queryDesc->instrument_options |= INSTRUMENT_BUFFERS;
    176193
    }

    ‎doc/src/sgml/ref/explain.sgml

    Lines changed: 16 additions & 0 deletions
    Original file line numberDiff line numberDiff line change
    @@ -40,6 +40,7 @@ EXPLAIN [ ANALYZE ] [ VERBOSE ] <replaceable class="parameter">statement</replac
    4040
    VERBOSE [ <replaceable class="parameter">boolean</replaceable> ]
    4141
    COSTS [ <replaceable class="parameter">boolean</replaceable> ]
    4242
    BUFFERS [ <replaceable class="parameter">boolean</replaceable> ]
    43+
    TIMING [ <replaceable class="parameter">boolean</replaceable> ]
    4344
    FORMAT { TEXT | XML | JSON | YAML }
    4445
    </synopsis>
    4546
    </refsynopsisdiv>
    @@ -171,6 +172,21 @@ ROLLBACK;
    171172
    </listitem>
    172173
    </varlistentry>
    173174

    175+
    <varlistentry>
    176+
    <term><literal>TIMING</literal></term>
    177+
    <listitem>
    178+
    <para>
    179+
    Include the actual startup time and time spent in the node in the output.
    180+
    The overhead of repeatedly reading the system clock can slow down the
    181+
    query significantly on some 6D47 systems, so it may be useful to set this
    182+
    parameter to <literal>FALSE</literal> when only actual row counts, and not
    183+
    exact times, are needed.
    184+
    This parameter may only be used when <literal>ANALYZE</literal> is also
    185+
    enabled. It defaults to <literal>TRUE</literal>.
    186+
    </para>
    187+
    </listitem>
    188+
    </varlistentry>
    189+
    174190
    <varlistentry>
    175191
    <term><literal>FORMAT</literal></term>
    176192
    <listitem>

    ‎src/backend/commands/explain.c

    Lines changed: 38 additions & 7 deletions
    Original file line numberDiff line numberDiff line change
    @@ -116,6 +116,7 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
    116116
    TupOutputState *tstate;
    117117
    List *rewritten;
    118118
    ListCell *lc;
    119+
    bool timing_set = false;
    119120

    120121
    /* Initialize ExplainState. */
    121122
    ExplainInitState(&es);
    @@ -133,6 +134,11 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
    133134
    es.costs = defGetBoolean(opt);
    134135
    else if (strcmp(opt->defname, "buffers") == 0)
    135136
    es.buffers = defGetBoolean(opt);
    137+
    else if (strcmp(opt->defname, "timing") == 0)
    138+
    {
    139+
    timing_set = true;
    140+
    es.timing = defGetBoolean(opt);
    141+
    }
    136142
    else if (strcmp(opt->defname, "format") == 0)
    137143
    {
    138144
    char *p = defGetString(opt);
    @@ -162,6 +168,15 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
    162168
    ereport(ERROR,
    163169
    (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
    164170
    errmsg("EXPLAIN option BUFFERS requires ANALYZE")));
    171+
    172+
    /* if the timing was not set explicitly, set default value */
    173+
    es.timing = (timing_set) ? es.timing : es.analyze;
    174+
    175+
    /* check that timing is used with EXPLAIN ANALYZE */
    176+
    if (es.timing && !es.analyze)
    177+
    ereport(ERROR,
    178+
    (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
    179+
    errmsg("EXPLAIN option TIMING requires ANALYZE")));
    165180

    166181
    /*
    167182
    * Parse analysis was done already, but we still have to run the rule
    @@ -360,8 +375,11 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ExplainState *es,
    360375
    int eflags;
    361376
    int instrument_option = 0;
    362377

    363-
    if (es->analyze)
    378+
    if (es->analyze && es->timing)
    364379
    instrument_option |= INSTRUMENT_TIMER;
    380+
    else if (es->analyze)
    381+
    instrument_option |= INSTRUMENT_ROWS;
    382+
    365383
    if (es->buffers)
    366384
    instrument_option |= INSTRUMENT_BUFFERS;
    367385

    @@ -956,29 +974,42 @@ ExplainNode(PlanState *planstate, List *ancestors,
    956974

    957975
    if (es->format == EXPLAIN_FORMAT_TEXT)
    958976
    {
    959-
    appendStringInfo(es->str,
    960-
    " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",
    961-
    startup_sec, total_sec, rows, nloops);
    977+
    if (planstate->instrument->need_timer)
    978+
    appendStringInfo(es->str,
    979+
    " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",
    980+
    startup_sec, total_sec, rows, nloops);
    981+
    else
    982+
    appendStringInfo(es->str,
    983+
    " (actual rows=%.0f loops=%.0f)",
    984+
    rows, nloops);
    962985
    }
    963986
    else
    964987
    {
    965-
    ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es);
    966-
    ExplainPropertyFloat("Actual Total Time", total_sec, 3, es);
    988+
    if (planstate->instrument->need_timer)
    989+
    {
    990+
    ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es);
    991+
    ExplainPropertyFloat("Actual Total Time", total_sec, 3, es);
    992+
    }
    967993
    ExplainPropertyFloat("Actual Rows", rows, 0, es);
    968994
    ExplainPropertyFloat("Actual Loops", nloops, 0, es);
    969995
    }
    970996
    }
    971997
    else if (es->analyze)
    972998
    {
    999+
    9731000
    if (es->format == EXPLAIN_FORMAT_TEXT)
    9741001
    appendStringInfo(es->str, " (never executed)");
    975-
    else
    1002+
    else if (planstate->instrument->need_timer)
    9761003
    {
    9771004
    ExplainPropertyFloat("Actual Startup Time", 0.0, 3, es);
    9781005
    ExplainPropertyFloat("Actual Total Time", 0.0, 3, es);
    1006+
    }
    1007+
    else
    1008+
    {
    9791009
    ExplainPropertyFloat("Actual Rows", 0.0, 0, es);
    9801010
    ExplainPropertyFloat("Actual Loops", 0.0, 0, es);
    9811011
    }
    1012+
    9821013
    }
    9831014

    9841015
    /* in text format, first line ends here */

    ‎src/backend/executor/instrument.c

    Lines changed: 21 additions & 13 deletions
    Original file line numberDiff line numberDiff line change
    @@ -29,17 +29,19 @@ InstrAlloc(int n, int instrument_options)
    2929
    {
    3030
    Instrumentation *instr;
    3131

    32-
    /* timer is always required for now */
    33-
    Assert(instrument_options & INSTRUMENT_TIMER);
    34-
    3532
    /* initialize all fields to zeroes, then modify as needed */
    3633
    instr = palloc0(n * sizeof(Instrumentation));
    37-
    if (instrument_options & INSTRUMENT_BUFFERS)
    34+
    if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER))
    3835
    {
    3936
    int i;
    37+
    bool need_buffers = instrument_options & INSTRUMENT_BUFFERS;
    38+
    bool need_timer = instrument_options & INSTRUMENT_TIMER;
    4039

    4140
    for (i = 0; i < n; i++)
    42-
    instr[i].need_bufusage = true;
    41+
    {
    42+
    instr[i].need_bufusage = need_buffers;
    43+
    instr[i].need_timer = need_timer;
    44+
    }
    4345
    }
    4446

    4547
    return instr;
    @@ -49,7 +51,7 @@ InstrAlloc(int n, int instrument_options)
    4951
    void
    5052
    InstrStartNode(Instrumentation *instr)
    5153
    {
    52-
    if (INSTR_TIME_IS_ZERO(instr->starttime))
    54+
    if (instr->need_timer && INSTR_TIME_IS_ZERO(instr->starttime))
    5355
    INSTR_TIME_SET_CURRENT(instr->starttime);
    5456
    else
    5557
    elog(DEBUG2, "InstrStartNode called twice in a row");
    @@ -68,16 +70,22 @@ InstrStopNode(Instrumentation *instr, double nTuples)
    6870
    /* count the returned tuples */
    6971
    instr->tuplecount += nTuples;
    7072

    71-
    if (INSTR_TIME_IS_ZERO(instr->starttime))
    73+
    /* let's update the time only if the timer was requested */
    74+
    if (instr->need_timer)
    7275
    {
    73-
    elog(DEBUG2, "InstrStopNode called without start");
    74-
    return;
    75-
    }
    7676

    77-
    INSTR_TIME_SET_CURRENT(endtime);
    78-
    INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime);
    77+
    if (INSTR_TIME_IS_ZERO(instr->starttime))
    78+
    {
    79+
    elog(DEBUG2, "InstrStopNode called without start");
    80+
    return;
    81+
    }
    7982

    80-
    INSTR_TIME_SET_ZERO(instr->starttime);
    83+
    INSTR_TIME_SET_CURRENT(endtime);
    84+
    INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime);
    85+
    86+
    INSTR_TIME_SET_ZERO(instr->starttime);
    87+
    88+
    }
    8189

    8290
    /* Add delta of buffer usage since entry to node's totals */
    8391
    if (instr->need_bufusage)

    ‎src/include/commands/explain.h

    Lines changed: 1 addition & 0 deletions
    Original file line numberDiff line numberDiff line change
    @@ -31,6 +31,7 @@ typedef struct ExplainState
    3131
    bool analyze; /* print actual times */
    3232
    bool costs; /* print costs */
    3333
    bool buffers; /* print buffer usage */
    34+
    bool timing; /* print timing */
    3435
    ExplainFormat format; /* output format */
    3536
    /* other states */
    3637
    PlannedStmt *pstmt; /* top of plan */

    ‎src/include/executor/instrument.h

    Lines changed: 3 additions & 1 deletion
    Original file line numberDiff line numberDiff line change
    @@ -31,14 +31,16 @@ typedef struct BufferUsage
    3131
    /* Flag bits included in InstrAlloc's instrument_options bitmask */
    3232
    typedef enum InstrumentOption
    3333
    {
    34-
    INSTRUMENT_TIMER = 1 << 0, /* needs timer */
    34+
    INSTRUMENT_TIMER = 1 << 0, /* needs timer (and row counts) */
    3535
    INSTRUMENT_BUFFERS = 1 << 1, /* needs buffer usage */
    36+
    INSTRUMENT_ROWS = 1 << 2, /* needs row count */
    3637
    INSTRUMENT_ALL = 0x7FFFFFFF
    3738
    } InstrumentOption;
    3839

    3940
    typedef struct Instrumentation
    4041
    {
    4142
    /* Parameters set at node creation: */
    43+
    bool need_timer; /* TRUE if we need timer data */
    4244
    bool need_bufusage; /* TRUE if we need buffer usage data */
    4345
    /* Info about current plan cycle: */
    4446
    bool running; /* TRUE if we've completed first tuple */

    0 commit comments

    Comments
     (0)
    0