diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index 61da6a27dec6e59d70987d6ce7b1056f4f794119..9fc0ae1d92338417c416fe79f44a84332b4a9735 100644
--- a/contrib/auto_explain/auto_explain.c
+++ b/contrib/auto_explain/auto_explain.c
@@ -23,6 +23,7 @@ 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_timing = false;
static int auto_explain_log_format = EXPLAIN_FORMAT_TEXT;
static bool auto_explain_log_nested_statements = false;
@@ -133,6 +134,17 @@ _PG_init(void)
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);
+
EmitWarningsOnPlaceholders("auto_explain");
/* Install hooks. */
@@ -170,7 +182,12 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags)
/* Enable per-node instrumentation iff log_analyze is required. */
if (auto_explain_log_analyze && (eflags & EXEC_FLAG_EXPLAIN_ONLY) == 0)
{
- queryDesc->instrument_options |= INSTRUMENT_TIMER;
+ 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;
}
diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml
index 8a9c9defcacad2765583b76a535d3b6bdad42faa..419b72cad348fe8d2e522a78eee981a121e8c402 100644
--- a/doc/src/sgml/ref/explain.sgml
+++ b/doc/src/sgml/ref/explain.sgml
@@ -40,6 +40,7 @@ EXPLAIN [ ANALYZE ] [ VERBOSE ] <replaceable class="parameter">statement</replac
VERBOSE [ <replaceable class="parameter">boolean</replaceable> ]
COSTS [ <replaceable class="parameter">boolean</replaceable> ]
BUFFERS [ <replaceable class="parameter">boolean</replaceable> ]
+ TIMING [ <replaceable class="parameter">boolean</replaceable> ]
FORMAT { TEXT | XML | JSON | YAML }
</synopsis>
</refsynopsisdiv>
@@ -171,6 +172,21 @@ ROLLBACK;
</listitem>
</varlistentry>
+ <varlistentry>
+ <term><literal>TIMING</literal></term>
+ <listitem>
+ <para>
+ Include the actual startup time and time spent in the node in the output.
+ The overhead of repeatedly reading the system clock can slow down the
+ query significantly on some systems, so it may be useful to set this
+ parameter to <literal>FALSE</literal> when only actual row counts, and not
+ exact times, are needed.
+ This parameter may only be used when <literal>ANALYZE</literal> is also
+ enabled. It defaults to <literal>TRUE</literal>.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry>
<term><literal>FORMAT</literal></term>
<listitem>
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index e57580e8addb24e9e203bdc47d4858c0db80a86e..a1692f82ae85ae06cdfcf4dc7e00acd707155d72 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -116,6 +116,7 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
TupOutputState *tstate;
List *rewritten;
ListCell *lc;
+ bool timing_set = false;
/* Initialize ExplainState. */
ExplainInitState(&es);
@@ -133,6 +134,11 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
es.costs = defGetBoolean(opt);
else if (strcmp(opt->defname, "buffers") == 0)
es.buffers = defGetBoolean(opt);
+ else if (strcmp(opt->defname, "timing") == 0)
+ {
+ timing_set = true;
+ es.timing = defGetBoolean(opt);
+ }
else if (strcmp(opt->defname, "format") == 0)
{
char *p = defGetString(opt);
@@ -162,6 +168,15 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
ereport(ERROR,
(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
errmsg("EXPLAIN option BUFFERS requires ANALYZE")));
+
+ /* if the timing was not set explicitly, set default value */
+ es.timing = (timing_set) ? es.timing : es.analyze;
+
+ /* check that timing is used with EXPLAIN ANALYZE */
+ if (es.timing && !es.analyze)
+ ereport(ERROR,
+ (errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+ errmsg("EXPLAIN option TIMING requires ANALYZE")));
/*
* Parse analysis was done already, but we still have to run the rule
@@ -360,8 +375,11 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ExplainState *es,
int eflags;
int instrument_option = 0;
- if (es->analyze)
+ if (es->analyze && es->timing)
instrument_option |= INSTRUMENT_TIMER;
+ else if (es->analyze)
+ instrument_option |= INSTRUMENT_ROWS;
+
if (es->buffers)
instrument_option |= INSTRUMENT_BUFFERS;
@@ -956,29 +974,42 @@ ExplainNode(PlanState *planstate, List *ancestors,
if (es->format == EXPLAIN_FORMAT_TEXT)
{
- appendStringInfo(es->str,
- " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",
- startup_sec, total_sec, rows, nloops);
+ if (planstate->instrument->need_timer)
+ appendStringInfo(es->str,
+ " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",
+ startup_sec, total_sec, rows, nloops);
+ else
+ appendStringInfo(es->str,
+ " (actual rows=%.0f loops=%.0f)",
+ rows, nloops);
}
else
{
- ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es);
- ExplainPropertyFloat("Actual Total Time", total_sec, 3, es);
+ if (planstate->instrument->need_timer)
+ {
+ ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es);
+ ExplainPropertyFloat("Actual Total Time", total_sec, 3, es);
+ }
ExplainPropertyFloat("Actual Rows", rows, 0, es);
ExplainPropertyFloat("Actual Loops", nloops, 0, es);
}
}
else if (es->analyze)
{
+
if (es->format == EXPLAIN_FORMAT_TEXT)
appendStringInfo(es->str, " (never executed)");
- else
+ else if (planstate->instrument->need_timer)
{
ExplainPropertyFloat("Actual Startup Time", 0.0, 3, es);
ExplainPropertyFloat("Actual Total Time", 0.0, 3, es);
+ }
+ else
+ {
ExplainPropertyFloat("Actual Rows", 0.0, 0, es);
ExplainPropertyFloat("Actual Loops", 0.0, 0, es);
}
+
}
/* in text format, first line ends here */
diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c
index dde73b7919263233ef3e258be570360a737bfd43..2c749b13cd8b4c3761df4c8fae6a2538f225fb56 100644
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -29,17 +29,19 @@ InstrAlloc(int n, int instrument_options)
{
Instrumentation *instr;
- /* timer is always required for now */
- Assert(instrument_options & INSTRUMENT_TIMER);
-
/* initialize all fields to zeroes, then modify as needed */
instr = palloc0(n * sizeof(Instrumentation));
- if (instrument_options & INSTRUMENT_BUFFERS)
+ if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER))
{
int i;
+ bool need_buffers = instrument_options & INSTRUMENT_BUFFERS;
+ bool need_timer = instrument_options & INSTRUMENT_TIMER;
for (i = 0; i < n; i++)
- instr[i].need_bufusage = true;
+ {
+ instr[i].need_bufusage = need_buffers;
+ instr[i].need_timer = need_timer;
+ }
}
return instr;
@@ -49,7 +51,7 @@ InstrAlloc(int n, int instrument_options)
void
InstrStartNode(Instrumentation *instr)
{
- if (INSTR_TIME_IS_ZERO(instr->starttime))
+ if (instr->need_timer && INSTR_TIME_IS_ZERO(instr->starttime))
INSTR_TIME_SET_CURRENT(instr->starttime);
else
elog(DEBUG2, "InstrStartNode called twice in a row");
@@ -68,16 +70,22 @@ InstrStopNode(Instrumentation *instr, double nTuples)
/* count the returned tuples */
instr->tuplecount += nTuples;
- if (INSTR_TIME_IS_ZERO(instr->starttime))
+ /* let's update the time only if the timer was requested */
+ if (instr->need_timer)
{
- elog(DEBUG2, "InstrStopNode called without start");
- return;
- }
- INSTR_TIME_SET_CURRENT(endtime);
- INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime);
+ if (INSTR_TIME_IS_ZERO(instr->starttime))
+ {
+ elog(DEBUG2, "InstrStopNode called without start");
+ return;
+ }
- INSTR_TIME_SET_ZERO(instr->starttime);
+ INSTR_TIME_SET_CURRENT(endtime);
+ INSTR_TIME_ACCUM_DIFF(instr->counter, endtime, instr->starttime);
+
+ INSTR_TIME_SET_ZERO(instr->starttime);
+
+ }
/* Add delta of buffer usage since entry to node's totals */
if (instr->need_bufusage)
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 3443259b009e475154f887fa3eeeab381de659a6..a987c4312420a2bbbf277b58e7266f03c989e85d 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -31,6 +31,7 @@ typedef struct ExplainState
bool analyze; /* print actual times */
bool costs; /* print costs */
bool buffers; /* print buffer usage */
+ bool timing; /* print timing */
ExplainFormat format; /* output format */
/* other states */
PlannedStmt *pstmt; /* top of plan */
diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h
index 9ecb5445f38edc065b90ab68d1771779bfd8dda6..084302e4e7efef8be05ff9983bc2467cd8595e21 100644
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -31,14 +31,16 @@ typedef struct BufferUsage
/* Flag bits included in InstrAlloc's instrument_options bitmask */
typedef enum InstrumentOption
{
- INSTRUMENT_TIMER = 1 << 0, /* needs timer */
+ INSTRUMENT_TIMER = 1 << 0, /* needs timer (and row counts) */
INSTRUMENT_BUFFERS = 1 << 1, /* needs buffer usage */
+ INSTRUMENT_ROWS = 1 << 2, /* needs row count */
INSTRUMENT_ALL = 0x7FFFFFFF
} InstrumentOption;
typedef struct Instrumentation
{
/* Parameters set at node creation: */
+ bool need_timer; /* TRUE if we need timer data */
bool need_bufusage; /* TRUE if we need buffer usage data */
/* Info about current plan cycle: */
bool running; /* TRUE if we've completed first tuple */