Double ocurring Subplan

I am listing the query, it's explain output and explain analyze output at
the end.

The EXPLAIN output shows the 'Subplan 2' node only once, whereas EXPLAIN
ANALYZE output shows that the 'Subplan 2' is being executed twice . Is that
true? Or is it just the plan printer getting confused? Is the confusion
because of the 2 conditions in the WHERE clause of the correlated subquery?

PG Version:
PostgreSQL 9.0.3 on x86_64-unknown-linux-gnu, compiled by GCC gcc
(Ubuntu/Linaro 4.4.4-14ubuntu5) 4.4.5, 64-bit

The query:

select d.m1 - h.m1
from tz_test as d
join tz_test_history as h
on d.server_id = h.server_id
where d.server_id = 5
and h.recorded_time = (select max(recorded_time)
from tz_test_history as h2
where h2.server_id = d.server_id
and h2.recorded_time < d.recorded_time);

The explain output:
QUERY
PLAN
------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=2.26..15.54 rows=1 width=8)
-> Seq Scan on tz_test d (cost=0.00..1.62 rows=1 width=16)
Filter: (server_id = 5)
-> Index Scan using tz_test_hist_rec_time_idx on tz_test_history h
(cost=2.26..11.64 rows=1 width=16)
Index Cond: (h.recorded_time = (SubPlan 2))
Filter: (h.server_id = 5)
SubPlan 2
-> Result (cost=2.25..2.26 rows=1 width=0)
InitPlan 1 (returns $2)
-> Limit (cost=0.00..2.25 rows=1 width=8)
-> Index Scan Backward using
tz_test_hist_rec_time_idx on tz_test_history h2 (cost=0.00..10800.38
rows=4800 width=8)
Index Cond: ((recorded_time IS NOT NULL) AND
(recorded_time < $1))
Filter: (server_id = $0)

explain analyze output:

QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=2.26..15.54 rows=1 width=8) (actual time=0.236..0.289
rows=1 loops=1)
-> Seq Scan on tz_test d (cost=0.00..1.62 rows=1 width=16) (actual
time=0.031..0.072 rows=1 loops=1)
Filter: (server_id = 5)
-> Index Scan using tz_test_hist_rec_time_idx on tz_test_history h
(cost=2.26..11.64 rows=1 width=16) (actual time=0.103..0.112 rows=1 loops=1)
Index Cond: (h.recorded_time = (SubPlan 2))
Filter: (h.server_id = 5)
SubPlan 2
-> Result (cost=2.25..2.26 rows=1 width=0) (actual
time=0.078..0.080 rows=1 loops=1)
InitPlan 1 (returns $2)
-> Limit (cost=0.00..2.25 rows=1 width=8) (actual
time=0.064..0.066 rows=1 loops=1)
-> Index Scan Backward using
tz_test_hist_rec_time_idx on tz_test_history h2 (cost=0.00..10800.38
rows=4800 width=8) (actual time=0.058..0.058 rows=1 loops=1)
Index Cond: ((recorded_time IS NOT NULL) AND
(recorded_time < $1))
Filter: (server_id = $0)
SubPlan 2
-> Result (cost=2.25..2.26 rows=1 width=0) (actual
time=0.078..0.080 rows=1 loops=1)
InitPlan 1 (returns $2)
-> Limit (cost=0.00..2.25 rows=1 width=8) (actual
time=0.064..0.066 rows=1 loops=1)
-> Index Scan Backward using
tz_test_hist_rec_time_idx on tz_test_history h2 (cost=0.00..10800.38
rows=4800 width=8) (actual time=0.058..0.058 rows=1 loops=1)
Index Cond: ((recorded_time IS NOT NULL) AND
(recorded_time < $1))
Filter: (server_id = $0)
Total runtime: 0.525 ms
(21 rows)

--
Gurjeet Singh
EnterpriseDB Corporation
The Enterprise PostgreSQL Company