Bad planner results

[Greg Stark]

I think this is just a bad case of "nested loops are costed wrong". But it's a
really really bad case. Like, even without any overlap in records looked up in
the nested loop I cannot imagine it ever being the wrong plan for these stats.
And Postgres is insistent on avoiding it, I have to disable both merge and
hash joins to get the 5ms nested loop join.

db=> EXPLAIN ANALYZE
SELECT distinct foo
FROM t1 join t1_t2 using (t1_id) join t2 using (t2_id)
WHERE bar = 232
;

QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Unique (cost=13036.55..13056.98 rows=33 width=4) (actual time=1040.238..1040.368 rows=11 loops=1)
-> Sort (cost=13036.55..13046.76 rows=4087 width=4) (actual time=1040.234..1040.291 rows=93 loops=1)
Sort Key: t1.foo
-> Hash Join (cost=267.80..12791.39 rows=4087 width=4) (actual time=12.511..1040.084 rows=93 loops=1)
Hash Cond: ("outer".t1_id = "inner".t1_id)
-> Hash Join (cost=125.43..12587.72 rows=4087 width=4) (actual time=1.344..1028.681 rows=93 loops=1)
Hash Cond: ("outer".t2_id = "inner".t2_id)
-> Seq Scan on t1_t2 (cost=0.00..9507.28 rows=582828 width=8) (actual time=0.003..572.865 rows=582828 loops=1)
-> Hash (cost=125.14..125.14 rows=117 width=4) (actual time=0.463..0.463 rows=0 loops=1)
-> Index Scan using idx_t2_bar on t2 (cost=0.00..125.14 rows=117 width=4) (actual time=0.028..0.331 rows=95 loops=1)
Index Cond: (bar = 232)
-> Hash (cost=133.89..133.89 rows=3389 width=8) (actual time=10.537..10.537 rows=0 loops=1)
-> Seq Scan on t1 (cost=0.00..133.89 rows=3389 width=8) (actual time=0.018..6.422 rows=3389 loops=1)
Total runtime: 1040.752 ms
(14 rows)

db=> set enable_hashjoin = false;

QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Unique (cost=15715.48..15735.92 rows=33 width=4) (actual time=98.095..98.230 rows=11 loops=1)
-> Sort (cost=15715.48..15725.70 rows=4087 width=4) (actual time=98.091..98.151 rows=93 loops=1)
Sort Key: t1.foo
-> Merge Join (cost=15233.28..15470.33 rows=4087 width=4) (actual time=85.827..97.943 rows=93 loops=1)
Merge Cond: ("outer".t1_id = "inner".t1_id)
-> Index Scan using t1_pkey on t1 (cost=0.00..167.27 rows=3389 width=8) (actual time=0.025..10.374 rows=3291 loops=1)
-> Sort (cost=15233.28..15243.50 rows=4087 width=4) (actual time=83.872..83.936 rows=93 loops=1)
Sort Key: t1_t2.t1_id
-> Merge Join (cost=129.16..14988.13 rows=4087 width=4) (actual time=13.992..83.729 rows=93 loops=1)
Merge Cond: ("outer".t2_id = "inner".t2_id)
-> Index Scan using t1_t2_all on t1_t2 (cost=0.00..13600.12 rows=582828 width=8) (actual time=0.016..58.722 rows=24533 loops=1)
-> Sort (cost=129.16..129.45 rows=117 width=4) (actual time=0.866..0.974 rows=163 loops=1)
Sort Key: t2.t2_id
-> Index Scan using idx_t2_bar on t2 (cost=0.00..125.14 rows=117 width=4) (actual time=0.024..0.648 rows=95 loops=1)
Index Cond: (bar = 232)
Total runtime: 98.406 ms
(16 rows)

db=> set enable_hashjoin = false;
SET
db=> set enable_mergejoin = false;
SET

QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Unique (cost=42624.09..42644.53 rows=33 width=4) (actual time=4.257..4.390 rows=11 loops=1)
-> Sort (cost=42624.09..42634.31 rows=4087 width=4) (actual time=4.255..4.310 rows=93 loops=1)
Sort Key: t1.foo
-> Nested Loop (cost=0.00..42378.94 rows=4087 width=4) (actual time=0.249..4.095 rows=93 loops=1)
-> Nested Loop (cost=0.00..29219.05 rows=4087 width=4) (actual time=0.220..2.247 rows=93 loops=1)
-> Index Scan using idx_t2_bar on t2 (cost=0.00..125.14 rows=117 width=4) (actual time=0.029..0.372 rows=95 loops=1)
Index Cond: (bar = 232)
-> Index Scan using t1_t2_code on t1_t2 (cost=0.00..245.63 rows=243 width=8) (actual time=0.012..0.015 rows=1 loops=95)
Index Cond: (t1_t2.t2_id = "outer".t2_id)
-> Index Scan using t1_pkey on t1 (cost=0.00..3.21 rows=1 width=8) (actual time=0.012..0.015 rows=1 loops=93)
Index Cond: (t1.t1_id = "outer".t1_id)
Total runtime: 4.564 ms
(12 rows)

--
greg
---------------------------(end of broadcast)---------------------------
TIP 4: Don't 'kill -9' the postmaster

[Tom Lane]

Greg Stark <gs*****@mit.edu> writes:

I think this is just a bad case of "nested loops are costed wrong".

Looks to me like a statistical failure. Why does it think there will be
4000 rows out of that join when there are only 93?

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 5: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faqs/FAQ.html