Thread: EXPLAIN ANALYZE time calculations

I'd like to get confirmation that I'm correctly understanding the
times given in EXPLAIN ANALYZE. Taking the example given in the Using
Explain section of the docs,

http://www.postgresql.org/docs/current/static/using-explain

EXPLAIN ANALYZE SELECT * FROM tenk1 t1, tenk2 t2 WHERE t1.unique1 <
100 AND t1.unique2 = t2.unique2;

                                                             QUERY PLAN
------------------------------------------------------------------------
----------------------------------------------------------
Nested Loop  (cost=2.37..553.11 rows=106 width=488) (actual
time=1.392..12.700 rows=100 loops=1)
    ->  Bitmap Heap Scan on tenk1 t1  (cost=2.37..232.35 rows=106
width=244) (actual time=0.878..2.367 rows=100 loops=1)
          Recheck Cond: (unique1 < 100)
          ->  Bitmap Index Scan on tenk1_unique1  (cost=0.00..2.37
rows=106 width=0) (actual time=0.546..0.546 rows=100 loops=1)
                Index Cond: (unique1 < 100)
    ->  Index Scan using tenk2_unique2 on tenk2 t2  (cost=0.00..3.01
rows=1 width=244) (actual time=0.067..0.078 rows=1 loops=100)
          Index Cond: ("outer".unique2 = t2.unique2)
Total runtime: 14.452 ms

I'm interested in figuring out what percentage of the total runtime
is spent in each node. Here are my calculations.

Nested loop:
   actual time: 12.700 ms/loop * 1 loop = 12.700 ms
   percent of total runtime: 88%
   percent spent in subnodes: 16% + 54% = 70%
   percent spent in node: 18%

     Bitmap Heap Scan on tenk1:
       actual time: 2.367 ms/loop * 1 loop = 2.367 ms
       percent of total runtime: 16%
       time spent in subnodes: 4%
       time spent in node: 12%

         Bitmap Heap Scan on tenk1_unique1:
           actual time: 0.546 ms/loop * 1 loop = 0.546 ms: 4%
           time spent in subnodes: 0%
           time spent in node: 4%

     Index Scan total time:
       actual time: 0.078 ms/loop * 100 loops = 7.80 ms
       percent of total runtime: 54%
       percent spent in subnodes: 0%
       percent spent in node: 54%

executor overhead: 14.452 ms - 12.700 ms = 1.752 ms: 12%

Is this correct?

Michael Glaesemann
grzm seespotcode net

Michael Glaesemann <grzm@seespotcode.net> writes:
> I'd like to get confirmation that I'm correctly understanding the
> times given in EXPLAIN ANALYZE.
> ...
> Is this correct?

Looks about right to me.  Note that some of what you are calling
"executor overhead" might also be classed as "gettimeofday overhead".
The measured difference between two successive gettimeofday readings
presumably includes the actual userland runtime plus the equivalent
of one gettimeofday call; but we actually did two calls.  IOW the
actual time to get in and out of a node is going to be a shade more
than is reported.

            regards, tom lane

On Dec 2, 2007, at 19:56 , Tom Lane wrote:

> IOW the actual time to get in and out of a node is going to be a
> shade more
> than is reported.

Thanks, Tom. Should be close enough for jazz.

When I was first going over the Using Explain section, I stumbled a
bit on the startup time/total time/loops bit (which is why explain-
analyze.info times and percentages are currently miscalculated). I
took startup time to be the time to return the first row *of the
first loop*. But it's actually the average startup time to return the
first row *in each loop*, right?

Michael Glaesemann
grzm seespotcode net

Michael Glaesemann <grzm@seespotcode.net> writes:
> I took startup time to be the time to return the first row *of the
> first loop*. But it's actually the average startup time to return the
> first row *in each loop*, right?

Correct, just as the total time and tuples returned are averages over all
the loops.

            regards, tom lane