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
