Hi all,
most of the time I use auto_explain, all I need is duration of the query
and the plan with estimates and actual row counts. And it would be handy
to be able to catch long running queries with estimates that are
significantly off (say 100x lower or higher compared to actual row numbers).
The gettimeofday() calls are not exactly cheap in some cases, so why to
pay that price when all you need is the number of rows?
The patch attached does this:
1) adds INSTRUMENT_ROWS, a new InstrumentOption
- counts rows without timing (no gettimeofday() callse)
- if you want timing info, use INSTRUMENT_TIMER
2) adds new option "TIMING" to EXPLAIN, i.e.
EXPLAIN (ANALYZE ON, TIMING ON) SELECT ...
3) adds auto_explain.log_rows_only (false by default)
- if you set this to 'true', then the instrumentation will just
count rows, without calling gettimeofday()
It works quite well, except one tiny issue - when the log_rows_only is
set to false (so that auto_explain requires timing), it silently
overrides the EXPLAIN option. So that even when the user explicitly
disables timing (TIMING OFF), it's overwritten and the explain collects
the timing data.
I could probably hide the timing info, but that'd make the issue even
worse (the user would not notice that the timing was actually enabled).
Maybe the right thing would be to explicitly disable timing for queries
executed with "EXPLAIN (TIMING OFF)". Any other ideas how to make this
work reasonably?
The patch does not implement any checks (how far is the estimate from
the reality) yet, that'll be round two.
regards
Tomas
diff --git a/contrib/auto_explain/auto_explain.c
b/contrib/auto_explain/auto_explain.c
index b320698..34015b8 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_rows_only = 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_rows_only",
+ "Do not collect timing
data, just row number.",
+ NULL,
+
&auto_explain_log_rows_only,
+ false,
+ PGC_SUSET,
+ 0,
+ NULL,
+ NULL,
+ NULL);
+
EmitWarningsOnPlaceholders("auto_explain");
/* Install hooks. */
@@ -170,7 +182,11 @@ 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_rows_only)
+ queryDesc->instrument_options |=
INSTRUMENT_ROWS;
+ else
+ queryDesc->instrument_options |=
(INSTRUMENT_TIMER | INSTRUMENT_ROWS);
+
if (auto_explain_log_buffers)
queryDesc->instrument_options |=
INSTRUMENT_BUFFERS;
}
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index e38de5c..4e3f343 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);
@@ -229,6 +231,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 +358,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 +957,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..2904d10 100644
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -33,12 +33,14 @@ typedef enum InstrumentOption
{
INSTRUMENT_TIMER = 1 << 0, /* needs timer */
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 */
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
