On Thu, 2006-06-08 at 12:56 -0400, Tom Lane wrote:
> Simon Riggs <[EMAIL PROTECTED]> writes:
> > So far we have myself, Kevin, Martijn and Luke all saying there is a
> > distortion or a massive overhead caused by EXPLAIN ANALYZE.
> > http://archives.postgresql.org/pgsql-hackers/2006-03/msg00954.php
> > http://archives.postgresql.org/pgsql-patches/2006-05/msg00168.php
>
> Given that we're seeing diametrically opposed results on the same OS
> (FC5) and similar (at least all Intel) hardware, I think the prudent
> thing is to find out what's really going on before leaping in with
> proposed solutions. As the person who's *not* seeing the problem,
> I'm not in a position to do that investigation...
That seems reasonable.
I've cut a patch to remove timing from the EA results.
Output shown here:
postgres=# set explain_analyze_timing = on;
SET
Time: 0.673 ms
postgres=# explain analyze select count(*) from accounts;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=2890.00..2890.01 rows=1 width=0) (actual
time=0.000..690.780 rows=1 loops=1)
-> Seq Scan on accounts (cost=0.00..2640.00 rows=100000 width=0)
(actual time=0.000..2672.562 rows=100000 loops=1)
Total runtime: 734.474 ms
(3 rows)
Time: 891.822 ms
postgres=# set explain_analyze_timing = off;
SET
Time: 0.480 ms
postgres=# explain analyze select count(*) from accounts;
QUERY PLAN
--------------------------------------------------------------------------------------------
Aggregate (cost=2890.00..2890.01 rows=1 width=0) (rows=1 loops=1)
-> Seq Scan on accounts (cost=0.00..2640.00 rows=100000 width=0)
(rows=100000 loops=1)
Total runtime: 133.674 ms
(3 rows)
Time: 134.565 ms
postgres=# select count(*) from accounts;
count
--------
100000
(1 row)
Time: 130.528 ms
So the timing is clearly responsible for the additional time I'm
personally experiencing and very likely to be that for others also.
As to why that should be the case, I'm not sure. The timing overhead
seems fairly constant on particular hardware/OS, just different for
each.
--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com
Index: src/backend/commands/explain.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/commands/explain.c,v
retrieving revision 1.147
diff -c -r1.147 explain.c
*** src/backend/commands/explain.c 8 Apr 2006 18:49:52 -0000 1.147
--- src/backend/commands/explain.c 8 Jun 2006 20:27:13 -0000
***************
*** 689,699 ****
{
double nloops = planstate->instrument->nloops;
! appendStringInfo(str, " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",
1000.0 * planstate->instrument->startup / nloops,
1000.0 * planstate->instrument->total / nloops,
planstate->instrument->ntuples / nloops,
planstate->instrument->nloops);
}
else if (es->printAnalyze)
appendStringInfo(str, " (never executed)");
--- 689,704 ----
{
double nloops = planstate->instrument->nloops;
! if (planstate->instrument->actualtime)
! appendStringInfo(str, " (actual time=%.3f..%.3f rows=%.0f loops=%.0f)",
1000.0 * planstate->instrument->startup / nloops,
1000.0 * planstate->instrument->total / nloops,
planstate->instrument->ntuples / nloops,
planstate->instrument->nloops);
+ else
+ appendStringInfo(str, " (rows=%.0f loops=%.0f)",
+ planstate->instrument->ntuples / nloops,
+ planstate->instrument->nloops);
}
else if (es->printAnalyze)
appendStringInfo(str, " (never executed)");
Index: src/backend/executor/instrument.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/executor/instrument.c,v
retrieving revision 1.17
diff -c -r1.17 instrument.c
*** src/backend/executor/instrument.c 7 Jun 2006 18:49:03 -0000 1.17
--- src/backend/executor/instrument.c 8 Jun 2006 20:27:13 -0000
***************
*** 17,23 ****
#include <unistd.h>
#include "executor/instrument.h"
!
/*
* As of PostgreSQL 8.2, we try to reduce the overhead of EXPLAIN ANALYZE
--- 17,23 ----
#include <unistd.h>
#include "executor/instrument.h"
! #include "utils/guc.h"
/*
* As of PostgreSQL 8.2, we try to reduce the overhead of EXPLAIN ANALYZE
***************
*** 115,120 ****
--- 115,121 ----
instr = palloc0(n * sizeof(Instrumentation));
/* we don't need to do any initialization except zero 'em */
+ instr->actualtime = explain_analyze_timing;
return instr;
}
***************
*** 123,128 ****
--- 124,132 ----
void
InstrStartNode(Instrumentation *instr)
{
+ if (!instr->actualtime)
+ return;
+
if (INSTR_TIME_IS_ZERO(instr->starttime))
{
/*
***************
*** 150,155 ****
--- 154,166 ----
{
/* count the returned tuples and iterations */
instr->tuplecount += nTuples;
+
+ if (!instr->running)
+ instr->running = true;
+
+ if (!instr->actualtime)
+ return;
+
instr->itercount += 1;
/* measure runtime if appropriate */
***************
*** 198,207 ****
/* Is this the first tuple of this cycle? */
if (!instr->running)
- {
- instr->running = true;
instr->firsttuple = INSTR_TIME_GET_DOUBLE(instr->counter);
- }
}
/* Finish a run cycle for a plan node */
--- 209,215 ----
***************
*** 214,219 ****
--- 222,233 ----
if (!instr->running)
return;
+ instr->ntuples += instr->tuplecount;
+ instr->nloops += 1;
+
+ if (!instr->actualtime)
+ return;
+
if (!INSTR_TIME_IS_ZERO(instr->starttime))
elog(DEBUG2, "InstrEndLoop called on running node");
***************
*** 244,251 ****
/* Accumulate per-cycle statistics into totals */
instr->startup += instr->firsttuple;
instr->total += totaltime;
- instr->ntuples += instr->tuplecount;
- instr->nloops += 1;
/* Reset for next cycle (if any) */
instr->running = false;
--- 258,263 ----
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/utils/misc/guc.c,v
retrieving revision 1.321
diff -c -r1.321 guc.c
*** src/backend/utils/misc/guc.c 5 Jun 2006 02:49:58 -0000 1.321
--- src/backend/utils/misc/guc.c 8 Jun 2006 20:27:19 -0000
***************
*** 161,166 ****
--- 161,167 ----
bool Debug_print_rewritten = false;
bool Debug_pretty_print = false;
bool Explain_pretty_print = true;
+ bool explain_analyze_timing = true;
bool log_parser_stats = false;
bool log_planner_stats = false;
***************
*** 472,477 ****
--- 473,487 ----
true, NULL, NULL
},
{
+ {"explain_analyze_timing", PGC_USERSET, QUERY_TUNING_METHOD,
+ gettext_noop("Enables collection of actual times by EXPLAIN ANALYZE."),
+ NULL,
+ GUC_NOT_IN_SAMPLE
+ },
+ &explain_analyze_timing,
+ true, NULL, NULL
+ },
+ {
{"constraint_exclusion", PGC_USERSET, QUERY_TUNING_OTHER,
gettext_noop("Enables the planner to use constraints to optimize queries."),
gettext_noop("Child table scans will be skipped if their "
Index: src/include/executor/instrument.h
===================================================================
RCS file: /projects/cvsroot/pgsql/src/include/executor/instrument.h,v
retrieving revision 1.15
diff -c -r1.15 instrument.h
*** src/include/executor/instrument.h 30 May 2006 19:24:25 -0000 1.15
--- src/include/executor/instrument.h 8 Jun 2006 20:27:20 -0000
***************
*** 58,63 ****
--- 58,64 ----
/* Info about current plan cycle: */
bool running; /* TRUE if we've completed first tuple */
bool sampling; /* Are we sampling in current iteration? */
+ bool actualtime; /* do we want the actual time also? */
instr_time starttime; /* Start time of current iteration of node */
instr_time counter; /* Accumulated runtime for this node */
double firsttuple; /* Time for first tuple of this cycle */
Index: src/include/utils/guc.h
===================================================================
RCS file: /projects/cvsroot/pgsql/src/include/utils/guc.h,v
retrieving revision 1.68
diff -c -r1.68 guc.h
*** src/include/utils/guc.h 11 May 2006 19:15:35 -0000 1.68
--- src/include/utils/guc.h 8 Jun 2006 20:27:20 -0000
***************
*** 109,114 ****
--- 109,115 ----
extern bool Debug_print_rewritten;
extern bool Debug_pretty_print;
extern bool Explain_pretty_print;
+ extern bool explain_analyze_timing;
extern bool log_parser_stats;
extern bool log_planner_stats;
---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings
