diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c
index b320698..4b52b26 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 8a9c9de..4488956 100644
--- a/doc/src/sgml/ref/explain.sgml
+++ b/doc/src/sgml/ref/explain.sgml
@@ -40,6 +40,7 @@ EXPLAIN [ ANALYZE ] [ VERBOSE ] statementboolean ]
COSTS [ boolean ]
BUFFERS [ boolean ]
+ TIMING [ boolean ]
FORMAT { TEXT | XML | JSON | YAML }
@@ -172,6 +173,20 @@ ROLLBACK;
+ TIMING
+
+
+ Include information on timing for each node. Specifically, include the
+ actual startup time and time spent in the node. This may involve a lot
+ of gettimeofday calls, and on some systems this means significant
+ slowdown of the query.
+ This parameter may only be used when ANALYZE is also
+ enabled. It defaults to TRUE.
+
+
+
+
+
FORMAT
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index e38de5c..468bb56 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -133,6 +133,8 @@ 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)
+ es.timing = defGetBoolean(opt);
else if (strcmp(opt->defname, "format") == 0)
{
char *p = defGetString(opt);
@@ -163,6 +165,11 @@ ExplainQuery(ExplainStmt *stmt, const char *queryString,
(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
errmsg("EXPLAIN option BUFFERS requires 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
* rewriter. We do not do AcquireRewriteLocks: we assume the query either
@@ -229,6 +236,7 @@ ExplainInitState(ExplainState *es)
/* Set default options. */
memset(es, 0, sizeof(ExplainState));
es->costs = true;
+ es->timing = true;
/* Prepare output buffer. */
es->str = makeStringInfo();
}
@@ -355,8 +363,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;
@@ -951,29 +962,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 9d30200..982a961 100644
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -29,17 +29,21 @@ 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;
+
+ elog(WARNING, "need_timer = %d", need_timer ? 1 : 0);
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 +53,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 +72,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 d7998c3..1c80bf3 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 22c3106..671e897 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 */