On 13.1.2012 18:07, Josh Berkus wrote:
> Eric's review follows:
>
> Compiling on Ubuntu 10.04 LTS AMD64 on a GoGrid virtual machine from
> 2012-01-12 git checkout.
>
> Patch applied fine.
>
> 'make check' results in failures when this patch is put into place.
>
> ========================
> 6 of 128 tests failed.
> ========================
>
> Here are the relevant failures.
>
> parallel group (2 tests): create_view create_index
> create_index ... FAILED
> parallel group (9 tests): create_cast create_aggregate drop_if_exists
> typed_table vacuum constraints create_table_like triggers inherit
> inherit ... FAILED
> parallel group (20 tests): select_distinct_on btree_index update random
> select_distinct select_having namespace delete case hash_index union
> select_implicit select_into transactions portals subselect arrays
> aggregates join prepared_xacts
> join ... FAILED
> aggregates ... FAILED
> parallel group (15 tests): combocid portals_p2 advisory_lock xmlmap
> tsdicts guc functional_deps dependency select_views cluster tsearch
> window foreign_data foreign_key bitmapops
> foreign_data ... FAILED
> parallel group (19 tests): limit prepare copy2 conversion xml plancache
> returning temp sequence without_oid with rowtypes truncate polymorphism
> domain largeobject rangefuncs alter_table plpgsql
> alter_table ... FAILED
>
Fixed. The default value of TIMING option did not work as intended, it
was set to true even for plain EXPLAIN (without ANALYZE). In that case
the EXPLAIN failed.
Tomas
diff --git a/contrib/auto_explain/auto_explain.c
b/contrib/auto_explain/auto_explain.c
index 61da6a2..9fc0ae1 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 8b48105..8251908 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
@@ -355,8 +370,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 +969,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 dde73b7..2c749b1 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 3443259..a987c43 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 9ecb544..084302e 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
