Thread: strange explain in upstream - subplan 1 twice - is it bug?
Hi
When I tested some queries, I found strange planpostgres=# explain analyze select s.nazev, o.nazev, o.pocet_obyvatel from (select nazev, array(select id from obce_pocet_obyvatel where okresy.id = okres_id order by pocet_obyvatel desc limit 3) as obceids from okresy) s join obce_pocet_obyvatel o on o.id = ANY(obceids) order by 1, 3 desc;
┌─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│ QUERY PLAN │
╞═════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════════╡
│ Sort (cost=840.37..842.29 rows=769 width=24) (actual time=5.518..5.554 rows=227 loops=1) │
│ Sort Key: okresy.nazev, ((obce.pocet_muzu + obce.pocet_zen)) DESC │
│ Sort Method: quicksort Memory: 44kB │
│ -> Nested Loop (cost=4.09..803.51 rows=769 width=24) (actual time=0.132..4.735 rows=227 loops=1) │
│ -> Seq Scan on okresy (cost=0.00..1.77 rows=77 width=17) (actual time=0.020..0.071 rows=77 loops=1) │
│ -> Index Scan using _obce_pkey on obce (cost=4.09..10.29 rows=10 width=22) (actual time=0.007..0.018 rows=3 loops=77) │
│ Index Cond: (id = ANY ((SubPlan 1))) │
│ SubPlan 1 │
│ -> Limit (cost=0.28..3.81 rows=3 width=8) (actual time=0.025..0.029 rows=3 loops=77) │
│ -> Index Scan using obce_okres_id_expr_idx on obce obce_1 (cost=0.28..95.43 rows=81 width=8) (actual time=0.024..0.027 rows=3 loops=77) │
│ Index Cond: (okresy.id = (okres_id)::text) │
│ SubPlan 1 │
│ -> Limit (cost=0.28..3.81 rows=3 width=8) (actual time=0.025..0.029 rows=3 loops=77) │
│ -> Index Scan using obce_okres_id_expr_idx on obce obce_1 (cost=0.28..95.43 rows=81 width=8) (actual time=0.024..0.027 rows=3 loops=77) │
│ Index Cond: (okresy.id = (okres_id)::text) │
│ Planning time: 0.815 ms │
│ Execution time: 5.693 ms │
└─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘
(17 rows)
Attachment
On Wed, Jun 1, 2016 at 7:29 AM, Pavel Stehule <pavel.stehule@gmail.com> wrote: > Hi > > When I tested some queries, I found strange plan > > postgres=# explain analyze select s.nazev, o.nazev, o.pocet_obyvatel from > (select nazev, array(select id from obce_pocet_obyvatel where okresy.id = > okres_id order by pocet_obyvatel desc limit 3) as obceids from okresy) s > join obce_pocet_obyvatel o on o.id = ANY(obceids) order by 1, 3 desc; The EXPLAIN plan you posted certainly looks weird, since I wouldn't expect SubPlan 1 to be displayed twice, but I'm wondering if it's a display artifact rather than an actual defect in the plan. Just out of curiosity, what does the output look like with FORMAT JSON or similar? -- Robert Haas EnterpriseDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company
2016-07-07 21:57 GMT+02:00 Robert Haas <robertmhaas@gmail.com>:
┌──────────────────────────────────────────────────────────────────────────────────────┐
│ QUERY PLAN │
╞══════════════════════════════════════════════════════════════════════════════════════╡
│ [ ↵│
│ { ↵│
│ "Plan": { ↵│
│ "Node Type": "Sort", ↵│
│ "Startup Cost": 1599.86, ↵│
│ "Total Cost": 1601.79, ↵│
│ "Plan Rows": 769, ↵│
│ "Plan Width": 24, ↵│
│ "Actual Startup Time": 9.525, ↵│
│ "Actual Total Time": 9.547, ↵│
│ "Actual Rows": 227, ↵│
│ "Actual Loops": 1, ↵│
│ "Sort Key": ["okresy.nazev", "((obce.pocet_muzu + obce.pocet_zen)) DESC"], ↵│
│ "Sort Method": "quicksort", ↵│
│ "Sort Space Used": 44, ↵│
│ "Sort Space Type": "Memory", ↵│
│ "Plans": [ ↵│
│ { ↵│
│ "Node Type": "Nested Loop", ↵│
│ "Parent Relationship": "Outer", ↵│
│ "Join Type": "Inner", ↵│
│ "Startup Cost": 13.95, ↵│
│ "Total Cost": 1563.00, ↵│
│ "Plan Rows": 769, ↵│
│ "Plan Width": 24, ↵│
│ "Actual Startup Time": 0.212, ↵│
│ "Actual Total Time": 8.991, ↵│
│ "Actual Rows": 227, ↵│
│ "Actual Loops": 1, ↵│
│ "Plans": [ ↵│
│ { ↵│
│ "Node Type": "Seq Scan", ↵│
│ "Parent Relationship": "Outer", ↵│
│ "Relation Name": "okresy", ↵│
│ "Alias": "okresy", ↵│
│ "Startup Cost": 0.00, ↵│
│ "Total Cost": 1.77, ↵│
│ "Plan Rows": 77, ↵│
│ "Plan Width": 17, ↵│
│ "Actual Startup Time": 0.016, ↵│
│ "Actual Total Time": 0.042, ↵│
│ "Actual Rows": 77, ↵│
│ "Actual Loops": 1 ↵│
│ }, ↵│
│ { ↵│
│ "Node Type": "Index Scan", ↵│
│ "Parent Relationship": "Inner", ↵│
│ "Scan Direction": "Forward", ↵│
│ "Index Name": "_obce_pkey", ↵│
│ "Relation Name": "obce", ↵│
│ "Alias": "obce", ↵│
│ "Startup Cost": 13.95, ↵│
│ "Total Cost": 20.15, ↵│
│ "Plan Rows": 10, ↵│
│ "Plan Width": 22, ↵│
│ "Actual Startup Time": 0.005, ↵│
│ "Actual Total Time": 0.012, ↵│
│ "Actual Rows": 3, ↵│
│ "Actual Loops": 77, ↵│
│ "Index Cond": "(id = ANY ((SubPlan 1)))", ↵│
│ "Rows Removed by Index Recheck": 0, ↵│
│ "Plans": [ ↵│
│ { ↵│
│ "Node Type": "Limit", ↵│
│ "Parent Relationship": "SubPlan", ↵│
│ "Subplan Name": "SubPlan 1", ↵│
│ "Startup Cost": 13.66, ↵│
│ "Total Cost": 13.67, ↵│
│ "Plan Rows": 3, ↵│
│ "Plan Width": 8, ↵│
│ "Actual Startup Time": 0.094, ↵│
│ "Actual Total Time": 0.095, ↵│
│ "Actual Rows": 3, ↵│
│ "Actual Loops": 77, ↵│
│ "Plans": [ ↵│
│ { ↵│
│ "Node Type": "Sort", ↵│
│ "Parent Relationship": "Outer", ↵│
│ "Startup Cost": 13.66, ↵│
│ "Total Cost": 13.86, ↵│
│ "Plan Rows": 81, ↵│
│ "Plan Width": 8, ↵│
│ "Actual Startup Time": 0.092, ↵│
│ "Actual Total Time": 0.093, ↵│
│ "Actual Rows": 3, ↵│
│ "Actual Loops": 77, ↵│
│ "Sort Key": ["((obce_1.pocet_muzu + obce_1.pocet_zen)) DESC"],↵│
│ "Sort Method": "quicksort", ↵│
│ "Sort Space Used": 25, ↵│
│ "Sort Space Type": "Memory", ↵│
│ "Plans": [ ↵│
│ { ↵│
│ "Node Type": "Index Scan", ↵│
│ "Parent Relationship": "Outer", ↵│
│ "Scan Direction": "Forward", ↵│
│ "Index Name": "obce_okres_id_idx", ↵│
│ "Relation Name": "obce", ↵│
│ "Alias": "obce_1", ↵│
│ "Startup Cost": 0.28, ↵│
│ "Total Cost": 12.62, ↵│
│ "Plan Rows": 81, ↵│
│ "Plan Width": 8, ↵│
│ "Actual Startup Time": 0.015, ↵│
│ "Actual Total Time": 0.065, ↵│
│ "Actual Rows": 81, ↵│
│ "Actual Loops": 77, ↵│
│ "Index Cond": "(okresy.id = (okres_id)::text)", ↵│
│ "Rows Removed by Index Recheck": 0 ↵│
│ } ↵│
│ ] ↵│
│ } ↵│
│ ] ↵│
│ }, ↵│
│ { ↵│
│ "Node Type": "Limit", ↵│
│ "Parent Relationship": "SubPlan", ↵│
│ "Subplan Name": "SubPlan 1", ↵│
│ "Startup Cost": 13.66, ↵│
│ "Total Cost": 13.67, ↵│
│ "Plan Rows": 3, ↵│
│ "Plan Width": 8, ↵│
│ "Actual Startup Time": 0.094, ↵│
│ "Actual Total Time": 0.095, ↵│
│ "Actual Rows": 3, ↵│
│ "Actual Loops": 77, ↵│
│ "Plans": [ ↵│
│ { ↵│
│ "Node Type": "Sort", ↵│
│ "Parent Relationship": "Outer", ↵│
│ "Startup Cost": 13.66, ↵│
│ "Total Cost": 13.86, ↵│
│ "Plan Rows": 81, ↵│
│ "Plan Width": 8, ↵│
│ "Actual Startup Time": 0.092, ↵│
│ "Actual Total Time": 0.093, ↵│
│ "Actual Rows": 3, ↵│
│ "Actual Loops": 77, ↵│
│ "Sort Key": ["((obce_1.pocet_muzu + obce_1.pocet_zen)) DESC"],↵│
│ "Sort Method": "quicksort", ↵│
│ "Sort Space Used": 25, ↵│
│ "Sort Space Type": "Memory", ↵│
│ "Plans": [ ↵│
│ { ↵│
│ "Node Type": "Index Scan", ↵│
│ "Parent Relationship": "Outer", ↵│
│ "Scan Direction": "Forward", ↵│
│ "Index Name": "obce_okres_id_idx", ↵│
│ "Relation Name": "obce", ↵│
│ "Alias": "obce_1", ↵│
│ "Startup Cost": 0.28, ↵│
│ "Total Cost": 12.62, ↵│
│ "Plan Rows": 81, ↵│
│ "Plan Width": 8, ↵│
│ "Actual Startup Time": 0.015, ↵│
│ "Actual Total Time": 0.065, ↵│
│ "Actual Rows": 81, ↵│
│ "Actual Loops": 77, ↵│
│ "Index Cond": "(okresy.id = (okres_id)::text)", ↵│
│ "Rows Removed by Index Recheck": 0 ↵│
│ } ↵│
│ ] ↵│
│ } ↵│
│ ] ↵│
│ } ↵│
│ ] ↵│
│ } ↵│
│ ] ↵│
│ } ↵│
│ ] ↵│
│ }, ↵│
│ "Planning Time": 0.496, ↵│
│ "Triggers": [ ↵│
│ ], ↵│
│ "Execution Time": 9.634 ↵│
│ } ↵│
│ ] │
└──────────────────────────────────────────────────────────────────────────────────────┘
(1 row)
On Wed, Jun 1, 2016 at 7:29 AM, Pavel Stehule <pavel.stehule@gmail.com> wrote:
> Hi
>
> When I tested some queries, I found strange plan
>
> postgres=# explain analyze select s.nazev, o.nazev, o.pocet_obyvatel from
> (select nazev, array(select id from obce_pocet_obyvatel where okresy.id =
> okres_id order by pocet_obyvatel desc limit 3) as obceids from okresy) s
> join obce_pocet_obyvatel o on o.id = ANY(obceids) order by 1, 3 desc;
The EXPLAIN plan you posted certainly looks weird, since I wouldn't
expect SubPlan 1 to be displayed twice, but I'm wondering if it's a
display artifact rather than an actual defect in the plan.
Just out of curiosity, what does the output look like with FORMAT JSON
or similar?
The test case was wrong, the view "" is necessary
create view obce_pocet_obyvatel as select id, okres_id, nazev, pocet_muzu + pocet_zen as pocet_obyvatel from obce;
create view obce_pocet_obyvatel as select id, okres_id, nazev, pocet_muzu + pocet_zen as pocet_obyvatel from obce;
But the result is same (explain is ok, explain analyze is broken):
┌──────────────────────────────────────────────────────────────────────────────────────┐
│ QUERY PLAN │
╞══════════════════════════════════════════════════════════════════════════════════════╡
│ [ ↵│
│ { ↵│
│ "Plan": { ↵│
│ "Node Type": "Sort", ↵│
│ "Startup Cost": 1599.86, ↵│
│ "Total Cost": 1601.79, ↵│
│ "Plan Rows": 769, ↵│
│ "Plan Width": 24, ↵│
│ "Actual Startup Time": 9.525, ↵│
│ "Actual Total Time": 9.547, ↵│
│ "Actual Rows": 227, ↵│
│ "Actual Loops": 1, ↵│
│ "Sort Key": ["okresy.nazev", "((obce.pocet_muzu + obce.pocet_zen)) DESC"], ↵│
│ "Sort Method": "quicksort", ↵│
│ "Sort Space Used": 44, ↵│
│ "Sort Space Type": "Memory", ↵│
│ "Plans": [ ↵│
│ { ↵│
│ "Node Type": "Nested Loop", ↵│
│ "Parent Relationship": "Outer", ↵│
│ "Join Type": "Inner", ↵│
│ "Startup Cost": 13.95, ↵│
│ "Total Cost": 1563.00, ↵│
│ "Plan Rows": 769, ↵│
│ "Plan Width": 24, ↵│
│ "Actual Startup Time": 0.212, ↵│
│ "Actual Total Time": 8.991, ↵│
│ "Actual Rows": 227, ↵│
│ "Actual Loops": 1, ↵│
│ "Plans": [ ↵│
│ { ↵│
│ "Node Type": "Seq Scan", ↵│
│ "Parent Relationship": "Outer", ↵│
│ "Relation Name": "okresy", ↵│
│ "Alias": "okresy", ↵│
│ "Startup Cost": 0.00, ↵│
│ "Total Cost": 1.77, ↵│
│ "Plan Rows": 77, ↵│
│ "Plan Width": 17, ↵│
│ "Actual Startup Time": 0.016, ↵│
│ "Actual Total Time": 0.042, ↵│
│ "Actual Rows": 77, ↵│
│ "Actual Loops": 1 ↵│
│ }, ↵│
│ { ↵│
│ "Node Type": "Index Scan", ↵│
│ "Parent Relationship": "Inner", ↵│
│ "Scan Direction": "Forward", ↵│
│ "Index Name": "_obce_pkey", ↵│
│ "Relation Name": "obce", ↵│
│ "Alias": "obce", ↵│
│ "Startup Cost": 13.95, ↵│
│ "Total Cost": 20.15, ↵│
│ "Plan Rows": 10, ↵│
│ "Plan Width": 22, ↵│
│ "Actual Startup Time": 0.005, ↵│
│ "Actual Total Time": 0.012, ↵│
│ "Actual Rows": 3, ↵│
│ "Actual Loops": 77, ↵│
│ "Index Cond": "(id = ANY ((SubPlan 1)))", ↵│
│ "Rows Removed by Index Recheck": 0, ↵│
│ "Plans": [ ↵│
│ { ↵│
│ "Node Type": "Limit", ↵│
│ "Parent Relationship": "SubPlan", ↵│
│ "Subplan Name": "SubPlan 1", ↵│
│ "Startup Cost": 13.66, ↵│
│ "Total Cost": 13.67, ↵│
│ "Plan Rows": 3, ↵│
│ "Plan Width": 8, ↵│
│ "Actual Startup Time": 0.094, ↵│
│ "Actual Total Time": 0.095, ↵│
│ "Actual Rows": 3, ↵│
│ "Actual Loops": 77, ↵│
│ "Plans": [ ↵│
│ { ↵│
│ "Node Type": "Sort", ↵│
│ "Parent Relationship": "Outer", ↵│
│ "Startup Cost": 13.66, ↵│
│ "Total Cost": 13.86, ↵│
│ "Plan Rows": 81, ↵│
│ "Plan Width": 8, ↵│
│ "Actual Startup Time": 0.092, ↵│
│ "Actual Total Time": 0.093, ↵│
│ "Actual Rows": 3, ↵│
│ "Actual Loops": 77, ↵│
│ "Sort Key": ["((obce_1.pocet_muzu + obce_1.pocet_zen)) DESC"],↵│
│ "Sort Method": "quicksort", ↵│
│ "Sort Space Used": 25, ↵│
│ "Sort Space Type": "Memory", ↵│
│ "Plans": [ ↵│
│ { ↵│
│ "Node Type": "Index Scan", ↵│
│ "Parent Relationship": "Outer", ↵│
│ "Scan Direction": "Forward", ↵│
│ "Index Name": "obce_okres_id_idx", ↵│
│ "Relation Name": "obce", ↵│
│ "Alias": "obce_1", ↵│
│ "Startup Cost": 0.28, ↵│
│ "Total Cost": 12.62, ↵│
│ "Plan Rows": 81, ↵│
│ "Plan Width": 8, ↵│
│ "Actual Startup Time": 0.015, ↵│
│ "Actual Total Time": 0.065, ↵│
│ "Actual Rows": 81, ↵│
│ "Actual Loops": 77, ↵│
│ "Index Cond": "(okresy.id = (okres_id)::text)", ↵│
│ "Rows Removed by Index Recheck": 0 ↵│
│ } ↵│
│ ] ↵│
│ } ↵│
│ ] ↵│
│ }, ↵│
│ { ↵│
│ "Node Type": "Limit", ↵│
│ "Parent Relationship": "SubPlan", ↵│
│ "Subplan Name": "SubPlan 1", ↵│
│ "Startup Cost": 13.66, ↵│
│ "Total Cost": 13.67, ↵│
│ "Plan Rows": 3, ↵│
│ "Plan Width": 8, ↵│
│ "Actual Startup Time": 0.094, ↵│
│ "Actual Total Time": 0.095, ↵│
│ "Actual Rows": 3, ↵│
│ "Actual Loops": 77, ↵│
│ "Plans": [ ↵│
│ { ↵│
│ "Node Type": "Sort", ↵│
│ "Parent Relationship": "Outer", ↵│
│ "Startup Cost": 13.66, ↵│
│ "Total Cost": 13.86, ↵│
│ "Plan Rows": 81, ↵│
│ "Plan Width": 8, ↵│
│ "Actual Startup Time": 0.092, ↵│
│ "Actual Total Time": 0.093, ↵│
│ "Actual Rows": 3, ↵│
│ "Actual Loops": 77, ↵│
│ "Sort Key": ["((obce_1.pocet_muzu + obce_1.pocet_zen)) DESC"],↵│
│ "Sort Method": "quicksort", ↵│
│ "Sort Space Used": 25, ↵│
│ "Sort Space Type": "Memory", ↵│
│ "Plans": [ ↵│
│ { ↵│
│ "Node Type": "Index Scan", ↵│
│ "Parent Relationship": "Outer", ↵│
│ "Scan Direction": "Forward", ↵│
│ "Index Name": "obce_okres_id_idx", ↵│
│ "Relation Name": "obce", ↵│
│ "Alias": "obce_1", ↵│
│ "Startup Cost": 0.28, ↵│
│ "Total Cost": 12.62, ↵│
│ "Plan Rows": 81, ↵│
│ "Plan Width": 8, ↵│
│ "Actual Startup Time": 0.015, ↵│
│ "Actual Total Time": 0.065, ↵│
│ "Actual Rows": 81, ↵│
│ "Actual Loops": 77, ↵│
│ "Index Cond": "(okresy.id = (okres_id)::text)", ↵│
│ "Rows Removed by Index Recheck": 0 ↵│
│ } ↵│
│ ] ↵│
│ } ↵│
│ ] ↵│
│ } ↵│
│ ] ↵│
│ } ↵│
│ ] ↵│
│ } ↵│
│ ] ↵│
│ }, ↵│
│ "Planning Time": 0.496, ↵│
│ "Triggers": [ ↵│
│ ], ↵│
│ "Execution Time": 9.634 ↵│
│ } ↵│
│ ] │
└──────────────────────────────────────────────────────────────────────────────────────┘
(1 row)
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
On Thu, Jul 7, 2016 at 4:13 PM, Pavel Stehule <pavel.stehule@gmail.com> wrote: > 2016-07-07 21:57 GMT+02:00 Robert Haas <robertmhaas@gmail.com>: >> On Wed, Jun 1, 2016 at 7:29 AM, Pavel Stehule <pavel.stehule@gmail.com> >> wrote: >> > Hi >> > >> > When I tested some queries, I found strange plan >> > >> > postgres=# explain analyze select s.nazev, o.nazev, o.pocet_obyvatel >> > from >> > (select nazev, array(select id from obce_pocet_obyvatel where okresy.id >> > = >> > okres_id order by pocet_obyvatel desc limit 3) as obceids from okresy) s >> > join obce_pocet_obyvatel o on o.id = ANY(obceids) order by 1, 3 desc; >> >> The EXPLAIN plan you posted certainly looks weird, since I wouldn't >> expect SubPlan 1 to be displayed twice, but I'm wondering if it's a >> display artifact rather than an actual defect in the plan. >> >> Just out of curiosity, what does the output look like with FORMAT JSON >> or similar? > > The test case was wrong, the view "" is necessary > > create view obce_pocet_obyvatel as select id, okres_id, nazev, pocet_muzu + > pocet_zen as pocet_obyvatel from obce; > > But the result is same (explain is ok, explain analyze is broken): Hmm, so it looks like the subplan is somehow getting into it's parents subPlan list twice. I guess ExecInitExpr must reach that subplan twice via two different paths, but I'm not quite sure how that's happening. -- Robert Haas EnterpriseDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company
Robert Haas <robertmhaas@gmail.com> writes: > On Wed, Jun 1, 2016 at 7:29 AM, Pavel Stehule <pavel.stehule@gmail.com> wrote: >> When I tested some queries, I found strange plan >> postgres=# explain analyze select s.nazev, o.nazev, o.pocet_obyvatel from >> (select nazev, array(select id from obce_pocet_obyvatel where okresy.id = >> okres_id order by pocet_obyvatel desc limit 3) as obceids from okresy) s >> join obce_pocet_obyvatel o on o.id = ANY(obceids) order by 1, 3 desc; > The EXPLAIN plan you posted certainly looks weird, since I wouldn't > expect SubPlan 1 to be displayed twice, but I'm wondering if it's a > display artifact rather than an actual defect in the plan. It is an artifact. The reason is that the same SubPlan appears in both indexqual and indexqualorig of the IndexScan node. (I'm not sure it's physically the same SubPlan node both places, and indeed that might vary depending on whether the plan tree had gotten copied; but they've got the same plan_id and thus refer to the same sub-plan within the PlannedStmt's subplans list.) We run ExecInitExpr on both, so we end up with two SubPlanState nodes that are both linked into the IndexScanState's subPlan list, and that's what explain.c prints from. They're pointing at the same subplan state tree, which is why you always see identical stats. The reason you don't see two copies without ANALYZE is that in EXPLAIN_ONLY mode, ExecInitIndexScan quits before doing ExecIndexBuildScanKeys, so the indexqual copy isn't ExecInitExpr'd. A crude way to improve this would be to have ExplainSubPlans check for duplicate plan_id values and not print the same plan_id more than once. I think we might have to do that globally across the whole plan tree, not just per invocation of ExplainSubPlans, because in bitmap scan cases the "indexqualorig" equivalent is in the parent BitmapHeapScan node while the "indexqual" equivalent is in the child BitmapIndexScan. So the duplicate subplans might not be in the same plan node's subPlan list. regards, tom lane