EXPLAIN ANALYZE time calculations

From: Michael Glaesemann <grzm(at)seespotcode(dot)net>
To: pgsql-performance(at)postgresql(dot)org
Subject: EXPLAIN ANALYZE time calculations
Date: 2007-12-03 00:28:15
Message-ID: 8C0EE80A-42A3-4CC1-850B-2A6B9220B422@seespotcode.net
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-performance

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

Responses

Browse pgsql-performance by date

  From Date Subject
Next Message Tom Lane 2007-12-03 00:56:19 Re: EXPLAIN ANALYZE time calculations
Previous Message Beyers Cronje 2007-12-02 23:32:21 Re: PostgreSQL 8.2.5 slow performance on INSERT on Linux