On 23.12.2011 14:57, Robert Haas wrote:
> 2011/12/22 Tomas Vondra <t...@fuzzy.cz>:
>> 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?
>
> Fair point.
>
>> 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()
>
> This seems like an unnecessarily confusing interface, because you've
> named the auto_explain option differently from the EXPLAIN option and
> given it (almost) the opposite sense: timing=off means the same thing
> as log_rows_only=on.
>
> I think the EXPLAIN (TIMING) option is good the way you have it, but
> then just have auto_explain.log_timing, with a default value of on.
Makes sense. I've updated the patch to reflect this, so the option is
called auto_explain.log_timing and is true by default. I'll add the
patch to the next commit fest.
One thing I'm wondering about is that the InstrumentOptions are not
exclusive - INSTRUMENT_TIMER means 'collect timing and row counts' while
INSTRUMENT_ROWS means 'collect row counts'. Wouldn't it be better to
redefine the INSTRUMENT_TIMER so that it collects just timing info. I.e.
to get the current behaviour, you'd have to do this
instrument_options |= (INSTRUMENT_TIMER | INSTRUMENT_ROWS)
It's quite trivial change in explain.c, the problem I have with that is
that it might break extensions.
Tomas
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 ] <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>
@@ -172,6 +173,20 @@ ROLLBACK;
</varlistentry>
<varlistentry>
+ <term><literal>TIMING</literal></term>
+ <listitem>
+ <para>
+ 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 <literal>ANALYZE</literal> is also
+ enabled. It defaults to <literal>TRUE</literal>.
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry>
<term><literal>FORMAT</literal></term>
<listitem>
<para>
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 */
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
