Thread: Double ocurring Subplan
<div dir="ltr">I am listing the query, it's explain output and explain analyze output at the end.<br /><br />The EXPLAINoutput shows the 'Subplan 2' node only once, whereas EXPLAIN ANALYZE output shows that the 'Subplan 2' is being executedtwice . Is that true? Or is it just the plan printer getting confused? Is the confusion because of the 2 conditionsin the WHERE clause of the correlated subquery?<br /><br />PG Version:<br clear="all" /><span style="font-family:courier new,monospace;"> PostgreSQL 9.0.3 on x86_64-unknown-linux-gnu, compiled by GCC gcc (Ubuntu/Linaro4.4.4-14ubuntu5) 4.4.5, 64-bit</span><br /><br />The query:<br /><br /><span style="font-family: courier new,monospace;">selectd.m1 - h.m1</span><br style="font-family: courier new,monospace;" /><span style="font-family: couriernew,monospace;">from tz_test as d</span><br style="font-family: courier new,monospace;" /><span style="font-family:courier new,monospace;">join tz_test_history as h</span><br style="font-family: courier new,monospace;"/><span style="font-family: courier new,monospace;">on d.server_id = h.server_id</span><br style="font-family:courier new,monospace;" /><span style="font-family: courier new,monospace;">where d.server_id = 5</span><brstyle="font-family: courier new,monospace;" /><span style="font-family: courier new,monospace;">and h.recorded_time= (select max(recorded_time)</span><br style="font-family: courier new,monospace;" /><span style="font-family:courier new,monospace;"> from tz_test_history as h2</span><br style="font-family:courier new,monospace;" /><span style="font-family: courier new,monospace;"> whereh2.server_id = d.server_id</span><br style="font-family: courier new,monospace;" /><span style="font-family: couriernew,monospace;"> and h2.recorded_time < d.recorded_time);</span><br style="font-family:courier new,monospace;" /><br />The explain output:<br /><span style="font-family: courier new,monospace;"> QUERY PLAN </span><br style="font-family: courier new,monospace;"/><span style="font-family: courier new,monospace;">------------------------------------------------------------------------------------------------------------------------------------------------</span><br style="font-family:courier new,monospace;" /><span style="font-family: courier new,monospace;"> Nested Loop (cost=2.26..15.54rows=1 width=8)</span><br style="font-family: courier new,monospace;" /><span style="font-family: couriernew,monospace;"> -> Seq Scan on tz_test d (cost=0.00..1.62 rows=1 width=16)</span><br style="font-family: couriernew,monospace;" /><span style="font-family: courier new,monospace;"> Filter: (server_id = 5)</span><br style="font-family:courier new,monospace;" /><span style="font-family: courier new,monospace;"> -> Index Scan usingtz_test_hist_rec_time_idx on tz_test_history h (cost=2.26..11.64 rows=1 width=16)</span><br style="font-family: couriernew,monospace;" /><span style="font-family: courier new,monospace;"> Index Cond: (h.recorded_time = (SubPlan2))</span><br style="font-family: courier new,monospace;" /><span style="font-family: courier new,monospace;"> Filter: (h.server_id = 5)</span><br style="font-family: courier new,monospace;" /><span style="font-family:courier new,monospace;"> SubPlan 2</span><br style="font-family: courier new,monospace;" /><spanstyle="font-family: courier new,monospace;"> -> Result (cost=2.25..2.26 rows=1 width=0)</span><br style="font-family:courier new,monospace;" /><span style="font-family: courier new,monospace;"> InitPlan1 (returns $2)</span><br style="font-family: courier new,monospace;" /><span style="font-family: courier new,monospace;"> -> Limit (cost=0.00..2.25 rows=1 width=8)</span><br style="font-family: courier new,monospace;"/><span style="font-family: courier new,monospace;"> -> Index Scan Backward usingtz_test_hist_rec_time_idx on tz_test_history h2 (cost=0.00..10800.38 rows=4800 width=8)</span><br style="font-family:courier new,monospace;" /><span style="font-family: courier new,monospace;"> Index Cond: ((recorded_time IS NOT NULL) AND (recorded_time < $1))</span><brstyle="font-family: courier new,monospace;" /><span style="font-family: courier new,monospace;"> Filter: (server_id = $0)</span><br style="font-family: courier new,monospace;"/><br /><br />explain analyze output:<br /><br /><span style="font-family: courier new,monospace;"> QUERY PLAN</span><brstyle="font-family: courier new,monospace;" /><span style="font-family: courier new,monospace;">------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------</span><br style="font-family:courier new,monospace;" /><span style="font-family: courier new,monospace;"> Nested Loop (cost=2.26..15.54rows=1 width=8) (actual time=0.236..0.289 rows=1 loops=1)</span><br style="font-family: courier new,monospace;"/><span style="font-family: courier new,monospace;"> -> Seq Scan on tz_test d (cost=0.00..1.62 rows=1width=16) (actual time=0.031..0.072 rows=1 loops=1)</span><br style="font-family: courier new,monospace;" /><span style="font-family:courier new,monospace;"> Filter: (server_id = 5)</span><br style="font-family: courier new,monospace;"/><span style="font-family: courier new,monospace;"> -> Index Scan using tz_test_hist_rec_time_idx ontz_test_history h (cost=2.26..11.64 rows=1 width=16) (actual time=0.103..0.112 rows=1 loops=1)</span><br style="font-family:courier new,monospace;" /><span style="font-family: courier new,monospace;"> Index Cond: (h.recorded_time= (SubPlan 2))</span><br style="font-family: courier new,monospace;" /><span style="font-family: couriernew,monospace;"> Filter: (h.server_id = 5)</span><br style="font-family: courier new,monospace;" /><span style="font-family:courier new,monospace;"> SubPlan 2</span><br style="font-family: courier new,monospace;" /><spanstyle="font-family: courier new,monospace;"> -> Result (cost=2.25..2.26 rows=1 width=0) (actual time=0.078..0.080rows=1 loops=1)</span><br style="font-family: courier new,monospace;" /><span style="font-family: couriernew,monospace;"> InitPlan 1 (returns $2)</span><br style="font-family: courier new,monospace;" /><spanstyle="font-family: courier new,monospace;"> -> Limit (cost=0.00..2.25 rows=1 width=8) (actualtime=0.064..0.066 rows=1 loops=1)</span><br style="font-family: courier new,monospace;" /><span style="font-family:courier new,monospace;"> -> Index Scan Backward using tz_test_hist_rec_time_idxon tz_test_history h2 (cost=0.00..10800.38 rows=4800 width=8) (actual time=0.058..0.058 rows=1loops=1)</span><br style="font-family: courier new,monospace;" /><span style="font-family: courier new,monospace;"> Index Cond: ((recorded_time IS NOT NULL) AND (recorded_time < $1))</span><brstyle="font-family: courier new,monospace;" /><span style="font-family: courier new,monospace;"> Filter: (server_id = $0)</span><br style="font-family: courier new,monospace;"/><span style="font-family: courier new,monospace;"> SubPlan 2</span><br style="font-family: couriernew,monospace;" /><span style="font-family: courier new,monospace;"> -> Result (cost=2.25..2.26 rows=1width=0) (actual time=0.078..0.080 rows=1 loops=1)</span><br style="font-family: courier new,monospace;" /><span style="font-family:courier new,monospace;"> InitPlan 1 (returns $2)</span><br style="font-family: couriernew,monospace;" /><span style="font-family: courier new,monospace;"> -> Limit (cost=0.00..2.25rows=1 width=8) (actual time=0.064..0.066 rows=1 loops=1)</span><br style="font-family: courier new,monospace;"/><span style="font-family: courier new,monospace;"> -> Index Scan Backward usingtz_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=1loops=1)</span><br style="font-family: courier new,monospace;" /><span style="font-family: courier new,monospace;"> Index Cond: ((recorded_time IS NOT NULL) AND (recorded_time < $1))</span><brstyle="font-family: courier new,monospace;" /><span style="font-family: courier new,monospace;"> Filter: (server_id = $0)</span><br style="font-family: courier new,monospace;"/><span style="font-family: courier new,monospace;"> Total runtime: 0.525 ms</span><br style="font-family:courier new,monospace;" /><span style="font-family: courier new,monospace;">(21 rows)</span><br style="font-family:courier new,monospace;" /><br />-- <br /><div dir="ltr">Gurjeet Singh<br />EnterpriseDB Corporation<br/>The Enterprise PostgreSQL Company<br /></div><br /></div>
Gurjeet Singh <singh.gurjeet@gmail.com> writes:
> 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?
The reason it looks like that is that the SubPlan is referenced in the
index condition, and there are actually two copies of that (indxqual and
indxqualorig). They both point at the same physical subplan, but there
are two entries in the parent node's subPlan list. In EXPLAIN you only
see one because ExecInitIndexScan skips initializing the indxquals in
EXPLAIN_ONLY mode.
In short: it's cosmetic.
We could probably suppress the duplicate printout when both references
are in the same plan node, but in bitmap scans the indxqual and
indxqualorig expressions are actually in different plan nodes (the
indexscan and heapscan respectively). I'm not sure how we could
suppress the duplicate printout in that case, or whether it would even
make sense to do so --- after all, the subplan can in fact get called by
both nodes.
regards, tom lane
On Fri, May 13, 2011 at 6:02 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
That's a relief
As long as it's not being re-evaluated, it's not a big deal.
It does confuse the casual onlooker, though; and if there's any automatic tool to parse and report explain analyze output, it might get its numbers quite wrong.
Regards,
-- Gurjeet Singh <singh.gurjeet@gmail.com> writes:The reason it looks like that is that the SubPlan is referenced in the
> 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?
index condition, and there are actually two copies of that (indxqual and
indxqualorig). They both point at the same physical subplan, but there
are two entries in the parent node's subPlan list. In EXPLAIN you only
see one because ExecInitIndexScan skips initializing the indxquals in
EXPLAIN_ONLY mode.
In short: it's cosmetic.
That's a relief
We could probably suppress the duplicate printout when both references
are in the same plan node, but in bitmap scans the indxqual and
indxqualorig expressions are actually in different plan nodes (the
indexscan and heapscan respectively). I'm not sure how we could
suppress the duplicate printout in that case, or whether it would even
make sense to do so --- after all, the subplan can in fact get called by
both nodes.
As long as it's not being re-evaluated, it's not a big deal.
It does confuse the casual onlooker, though; and if there's any automatic tool to parse and report explain analyze output, it might get its numbers quite wrong.
Regards,
Gurjeet Singh
EnterpriseDB Corporation
The Enterprise PostgreSQL Company
EnterpriseDB Corporation
The Enterprise PostgreSQL Company