Hi all,
on our PostgreSQL 8.3.1 (CentOS 5.3 64-bit) two different query plans
for one of our (weird) queries are generated. One of the query plans
seems to be good (and is used most of the time). The other one is bad -
the query takes about 2 minutes and the database process, which is
executing the query, is cpu bound during this time.
After several tries I was able to reproduce the problem when executing
the query with EXPLAIN ANALYZE. The bad query plan was generated only
seconds after the good one was used when executing the query. What's the
reasond for the different query plans? Statistics are up to date.
Good:
EXPLAIN ANALYZE SELECT DISTINCT t6.objid
FROM ataggval q1_1,
atobjval t6,
atobjval t7,
atobjval t8,
atobjval t9,
cooobject t10
WHERE q1_1.objid = t6.objid AND
q1_1.attrid = 285774255985993 AND
q1_1.aggrid = 0 AND
t6.aggrid = q1_1.aggval AND
t7.aggrid = 0 AND
t7.objid = t6.objid AND
t8.aggrid = 0 AND
t8.objid = t6.objid AND
t9.aggrid = 0 AND
t9.objid = t6.objid AND
t10.objid = t6.objid AND
t6.objval = 285774255985589 AND
t6.attrid=285774255985991 AND
t7.objval = 625445988202446985 AND
t7.attrid=285774255985855 AND
t8.objval = 625445988286355913 AND
t8.attrid=285774255985935 AND
t9.objval = 625445988269570350 AND
t9.attrid=285774255985938 AND
t10.objclassid = 285774255985894 ORDER BY t6.objid;
QUERY PLAN
------------------------------------------------------------------------
------------------------------------------------------------------------
----------------------------
Unique (cost=66.58..66.59 rows=1 width=8) (actual
time=1548.207..1548.208 rows=1 loops=1)
-> Sort (cost=66.58..66.58 rows=1 width=8) (actual
time=1548.206..1548.207 rows=1 loops=1)
Sort Key: t6.objid
Sort Method: quicksort Memory: 25kB
-> Nested Loop (cost=0.00..66.57 rows=1 width=8) (actual
time=1044.759..1548.190 rows=1 loops=1)
Join Filter: (t6.objid = t7.objid)
-> Nested Loop (cost=0.00..54.52 rows=1 width=40)
(actual time=21.938..1541.633 rows=350 loops=1)
Join Filter: (t6.objid = t8.objid)
-> Nested Loop (cost=0.00..42.47 rows=1 width=32)
(actual time=21.907..1422.710 rows=364 loops=1)
Join Filter: (t6.objid = t9.objid)
-> Nested Loop (cost=0.00..30.42 rows=1
width=24) (actual time=0.151..920.873 rows=775 loops=1)
-> Nested Loop (cost=0.00..21.97
rows=1 width=16) (actual time=0.065..915.387 rows=775 loops=1)
Join Filter: (q1_1.objid =
t6.objid)
-> Index Scan using ind_atobjval
on atobjval t6 (cost=0.00..12.04 rows=1 width=12) (actual
time=0.031..0.863 rows=775 loops=1)
Index Cond: ((attrid =
285774255985991::bigint) AND (objval = 285774255985589::bigint))
-> Index Scan using ind_ataggval
on ataggval q1_1 (cost=0.00..9.92 rows=1 width=12) (actual
time=0.006..0.897 rows=1243 loops=775)
Index Cond: ((q1_1.attrid =
285774255985993::bigint) AND (q1_1.aggval = t6.aggrid))
Filter: (q1_1.aggrid = 0)
-> Index Scan using cooobjectix on
cooobject t10 (cost=0.00..8.44 rows=1 width=8) (actual
time=0.005..0.006 rows=1 loops=775)
Index Cond: (t10.objid =
t6.objid)
Filter: (t10.objclassid =
285774255985894::bigint)
-> Index Scan using ind_atobjval on atobjval
t9 (cost=0.00..12.04 rows=1 width=8) (actual time=0.007..0.490 rows=694
loops=775)
Index Cond: ((t9.attrid =
285774255985938::bigint) AND (t9.objval = 625445988269570350::bigint))
Filter: (t9.aggrid = 0)
-> Index Scan using ind_atobjval on atobjval t8
(cost=0.00..12.04 rows=1 width=8) (actual time=0.007..0.248 rows=350
loops=364)
Index Cond: ((t8.attrid =
285774255985935::bigint) AND (t8.objval = 625445988286355913::bigint))
Filter: (t8.aggrid = 0)
-> Index Scan using ind_atobjval on atobjval t7
(cost=0.00..12.04 rows=1 width=8) (actual time=0.005..0.015 rows=13
loops=350)
Index Cond: ((t7.attrid = 285774255985855::bigint)
AND (t7.objval = 625445988202446985::bigint))
Filter: (t7.aggrid = 0)
Total runtime: 1548.339 ms
(31 rows)
Bad:
EXPLAIN ANALYZE SELECT DISTINCT t6.objid
FROM ataggval q1_1,
atobjval t6,
atobjval t7,
atobjval t8,
atobjval t9,
cooobject t10
WHERE q1_1.objid = t6.objid AND
q1_1.attrid = 285774255985993 AND
q1_1.aggrid = 0 AND
t6.aggrid = q1_1.aggval AND
t7.aggrid = 0 AND
t7.objid = t6.objid AND
t8.aggrid = 0 AND
t8.objid = t6.objid AND
t9.aggrid = 0 AND
t9.objid = t6.objid AND
t10.objid = t6.objid AND
t6.objval = 285774255985589 AND
t6.attrid=285774255985991 AND
t7.objval = 625445988202446985 AND
t7.attrid=285774255985855 AND
t8.objval = 625445988286355913 AND
t8.attrid=285774255985935 AND
t9.objval = 625445988269570350 AND
t9.attrid=285774255985938 AND
t10.objclassid = 285774255985894 ORDER BY t6.objid;
QUERY PLAN
------------------------------------------------------------------------
------------------------------------------------------------------------
----------------------
Unique (cost=66.58..66.59 rows=1 width=8) (actual
time=172984.132..172984.133 rows=1 loops=1)
-> Sort (cost=66.58..66.59 rows=1 width=8) (actual
time=172984.129..172984.129 rows=1 loops=1)
Sort Key: t6.objid
Sort Method: quicksort Memory: 25kB
-> Nested Loop (cost=0.00..66.57 rows=1 width=8) (actual
time=118105.762..172984.109 rows=1 loops=1)
Join Filter: (t6.objid = t7.objid)
-> Nested Loop (cost=0.00..54.52 rows=1 width=40)
(actual time=2362.708..172976.313 rows=350 loops=1)
Join Filter: (t6.objid = q1_1.objid)
-> Nested Loop (cost=0.00..44.59 rows=1 width=36)
(actual time=2362.628..172487.721 rows=350 loops=1)
Join Filter: (t6.objid = t8.objid)
-> Nested Loop (cost=0.00..20.49 rows=1
width=20) (actual time=0.054..7.144 rows=775 loops=1)
-> Index Scan using ind_atobjval on
atobjval t6 (cost=0.00..12.04 rows=1 width=12) (actual
time=0.032..0.953 rows=775 loops=1)
Index Cond: ((attrid =
285774255985991::bigint) AND (objval = 285774255985589::bigint))
-> Index Scan using cooobjectix on
cooobject t10 (cost=0.00..8.44 rows=1 width=8) (actual
time=0.006..0.007 rows=1 loops=775)
Index Cond: (t10.objid =
t6.objid)
Filter: (t10.objclassid =
285774255985894::bigint)
-> Nested Loop (cost=0.00..24.09 rows=1
width=16) (actual time=0.019..222.445 rows=350 loops=775)
Join Filter: (t8.objid = t9.objid)
-> Index Scan using ind_atobjval on
atobjval t8 (cost=0.00..12.04 rows=1 width=8) (actual time=0.009..0.296
rows=350 loops=775)
Index Cond: ((attrid =
285774255985935::bigint) AND (objval = 625445988286355913::bigint))
Filter: (aggrid = 0)
-> Index Scan using ind_atobjval on
atobjval t9 (cost=0.00..12.04 rows=1 width=8) (actual time=0.009..0.475
rows=694 loops=271250)
Index Cond: ((t9.attrid =
285774255985938::bigint) AND (t9.objval = 625445988269570350::bigint))
Filter: (t9.aggrid = 0)
-> Index Scan using ind_ataggval on ataggval q1_1
(cost=0.00..9.92 rows=1 width=12) (actual time=0.009..1.114 rows=1248
loops=350)
Index Cond: ((q1_1.attrid =
285774255985993::bigint) AND (q1_1.aggval = t6.aggrid))
Filter: (q1_1.aggrid = 0)
-> Index Scan using ind_atobjval on atobjval t7
(cost=0.00..12.04 rows=1 width=8) (actual time=0.007..0.018 rows=13
loops=350)
Index Cond: ((t7.attrid = 285774255985855::bigint)
AND (t7.objval = 625445988202446985::bigint))
Filter: (t7.aggrid = 0)
Total runtime: 172984.235 ms
(31 rows)
Thanks
Robert
--
Sent via pgsql-performance mailing list (pgsql-performance@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
