I just upgraded my database server from 8.0.1 to 8.2.4
Most things went very well, but I have a couple of queries that really slowed
down with the new server.
On 8.0.1 the query took less then 3 seconds to complete. On 8.2.4 the same query
(I vacuumed the database before running the query) takes 60 seconds (10 minutes
with Explain Analyze).
The data is exactly the same on the 2 servers.
To test for hardware differences, I loaded 8.0.11 onto a test server restored
the database and ran the query.
It took about 3 seconds. I then uninstalled postgresql and installed version
8.2.4 and restored the database
and the query took about 60 seconds.
On the 8.2.4 the CPU usage (as seen from top) goes up to about 97% for most of
the 60 seconds of query.
On 8.0.1, it didn't.
I have the explain from both databases, if someone could help me walk through
this, I would much appreciate it.
----------------------------------------------------------------------------------------------------------------------
Explain 8.0.1 Fast query
Subquery Scan assemblycanbuild (cost=8495.27..8509.34 rows=13 width=36)
(actual time=3585.026..3753.339 rows=83 loops=1)
-> GroupAggregate (cost=8495.27..8509.21 rows=13 width=32) (actual
time=3585.015..3752.729 rows=83 loops=1)
-> Subquery Scan assembliesstockbatchpriorexpected
(cost=8495.27..8508.30 rows=13 width=32) (actual time=3584.912..3729.404 rows=3684
loops=1)
-> GroupAggregate (cost=8495.27..8508.17 rows=13 width=112)
(actual time=3584.900..3699.779 rows=3684 loops=1)
-> Sort (cost=8495.27..8496.23 rows=382 width=112)
(actual time=3584.836..3613.432 rows=7400 loops=1)
Sort Key: a.assembliesbatchid, a.duedate,
a.assemblyid, a.assemblyname, a.ownerid, a.partid, a.quantity, a.stock,
a.prioruse, a.units, a.qtyperunit
-> Hash Left Join (cost=8220.13..8478.89 rows=382
width=112) (actual time=2902.740..3407.342 rows=7400 loops=1)
Hash Cond: ("outer".partid = "inner".partid)
-> Subquery Scan a (cost=6877.75..6920.40
rows=125 width=88) (actual time=2700.471..3140.321 rows=3684 loops=1)
-> GroupAggregate
(cost=6877.75..6919.15 rows=125 width=85) (actual time=2700.456..3106.694
rows=3684 loops=1)
-> Sort (cost=6877.75..6880.86
rows=1245 width=85) (actual time=2700.414..2839.777 rows=36876 loops=1)
Sort Key:
a.assembliesbatchid, a.duedate, a.assemblyid, a.assemblyname, a.ownerid,
a.partid, a.quantity, a.stock, a.units, a.qtyperunit, a.leadfree
-> Hash Left Join
(cost=6582.30..6813.74 rows=1245 width=85) (actual time=1458.482..1887.078
rows=36876 loops=1)
Hash Cond: (("outer".partid =
"inner".partid) AND ("outer".leadfree = "inner".leadfree))
Join Filter: ((COALESCE("outer".ownerid, 1) = 1) AND (("outer".duedate >
"inner".duedate) OR (("outer".duedate = "inner".duedate) AND ("outer".assembliesbatchid >
"inner".assembliesbatchid))))
-> Subquery Scan a
(cost=6012.11..6068.13 rows=1245 width=81) (actual time=1252.814..1340.992
rows=3684 loops=1)
->
GroupAggregate (cost=6012.11..6055.68 rows=1245 width=82) (actual
time=1252.799..1307.969 rows=3684 loops=1)
-> Sort
(cost=6012.11..6015.22 rows=1245 width=82) (actual time=1252.759..1265.317
rows=3685 loops=1)
Sort
Key: d.assembliesbatchid, d.duedate, a.assemblyid, a.assemblyname, c.ownerid,
e.partid, COALESCE(c.stock, 0::bigint), d.units, e.quantity, a.leadfree
->
Merge Left Join (cost=5816.85..5948.10 rows=1245 width=82) (actual
time=1169.837..1220.895 rows=3685 loops=1)
Merge Cond: (("outer".batchid
= "inner".refid) AND ("outer".partid = "inner".partid))
Filter:
(COALESCE("inner".commited, false) = false)
-> Sort (cost=2382.11..2385.22 rows=1245 width=86) (actual
time=682.055..694.675 rows=3684 loops=1)
Sort Key: d.batchid, e.partid
-> Hash Left Join (cost=737.64..2318.10 rows=1245 width=86) (actual
time=250.089..665.021 rows=3684 loops=1)
Hash
Cond: ("outer".partid = "inner".partid)
Join
Filter: leadcompcheck_ab("outer".leadfree, "inner".leadstateid)
-> Merge Right Join (cost=722.62..2296.73 rows=1245 width=74)
(actual time=169.106..506.307 rows=3684 loops=1)
Merge Cond:
(("outer".partid = "inner".partid) AND ("outer".assemblyid =
"inner".assemblyid))
-> Index Scan using idx_u_assidpartid on partsassembly b
(cost=0.00..1396.01 rows=34286 width=16) (actual time=0.147..151.393 rows=34286
loops=1)
-> Sort (cost=722.62..725.74 rows=1245 width=66) (actual
time=168.091..180.485 rows=3684 loops=1)
Sort Key: e.partid, a.assemblyid
-> Hash Join (cost=71.73..658.62 rows=1245 width=66)
(actual time=12.252..148.296 rows=3684 loops=1)
Hash Cond: ("outer".assemblyid = "inner".assemblyid)
-> Hash Join (cost=54.68..622.89 rows=1245
width=32) (actual time=6.377..111.172 rows=3684 loops=1)
Hash Cond: ("outer".assembliesbatchid =
"inner".assembliesbatchid)
-> Seq Scan on allocatedassemblies e
(cost=0.00..460.93 rows=18967 width=12) (actual time=0.032..51.827 rows=11332
loops=1)
Filter: ((- quantity) <> 0)
-> Hash (cost=54.43..54.43 rows=98 width=24)
(actual time=1.364..1.364 rows=0 loops=1)
-> Index Scan using
fki_assembliesbatch_assembliesbatchstatus_id,
fki_assembliesbatch_assembliesbatchstatus_id,
fki_assembliesbatch_assembliesbatchstatus_id,
fki_assembliesbatch_assembliesbatchstatus_id on assembliesbatch d
(cost=0.00..54.43 rows=98 width=24) (actual time=0.105..0.985 rows=99 loops=1)
Index Cond:
((assembliesbatchstatusid = 1) OR (assembliesbatchstatusid = 2) OR
(assembliesbatchstatusid = 4) OR (assembliesbatchstatusid = 7))
-> Hash (cost=15.24..15.24 rows=724 width=38)
(actual time=5.844..5.844 rows=0 loops=1)
-> Seq Scan on assemblies a
(cost=0.00..15.24 rows=724 width=38) (actual time=0.030..3.149 rows=724 loops=1)
-> Hash (cost=15.00..15.00 rows=5 width=20) (actual
time=80.500..80.500 rows=0 loops=1)
-> Function Scan on stockperowner_lead_ab c (cost=0.00..15.00
rows=5 width=20) (actual time=67.238..74.347 rows=1694 loops=1)
Filter: (ownerid = 1)
-> Sort (cost=3434.74..3498.75 rows=25605 width=9) (actual
time=313.138..403.616 rows=25267 loops=1)
Sort Key: f.refid, f.partid
-> Seq Scan on stocklog f (cost=0.00..1559.92 rows=25605 width=9) (actual
time=0.066..146.728 rows=25267 loops=1)
Filter: (transtypeid = 3)
-> Hash
(cost=563.93..563.93 rows=1251 width=21) (actual time=205.583..205.583 rows=0
loops=1)
-> Hash Join
(cost=71.73..563.93 rows=1251 width=21) (actual time=11.923..190.945 rows=3851
loops=1)
Hash Cond:
("outer".assemblyid = "inner".assemblyid)
-> Hash
Join (cost=54.68..528.12 rows=1251 width=24) (actual time=6.159..155.650
rows=3851 loops=1)
Hash Cond:
("outer".assembliesbatchid = "inner".assembliesbatchid)
->
Seq Scan on allocatedassemblies b (cost=0.00..365.62 rows=19062 width=12) (actual
time=0.029..71.287 rows=19062 loops=1)
->
Hash (cost=54.43..54.43 rows=98 width=16) (actual time=1.287..1.287 rows=0
loops=1)
-> Index Scan using fki_assembliesbatch_assembliesbatchstatus_id,
fki_assembliesbatch_assembliesbatchstatus_id,
fki_assembliesbatch_assembliesbatchstatus_id,
fki_assembliesbatch_assembliesbatchstatus_id on assembliesbatch c
(cost=0.00..54.43 rows=98 width=16) (actual time=0.090..0.921 rows=99 loops=1)
Index Cond: ((assembliesbatchstatusid = 1) OR (assembliesbatchstatusid =
2) OR (assembliesbatchstatusid = 4) OR (assembliesbatchstatusid = 7))
-> Hash
(cost=15.24..15.24 rows=724 width=5) (actual time=5.733..5.733 rows=0 loops=1)
->
Seq Scan on assemblies q (cost=0.00..15.24 rows=724 width=5) (actual
time=0.040..3.081 rows=724 loops=1)
-> Hash (cost=1332.57..1332.57 rows=3924
width=28) (actual time=202.198..202.198 rows=0 loops=1)
-> Hash Join (cost=592.15..1332.57
rows=3924 width=28) (actual time=66.119..199.853 rows=593 loops=1)
Hash Cond: ("outer".pnid =
"inner".pnid)
-> Hash Join
(cost=377.64..1019.94 rows=3925 width=32) (actual time=11.525..139.401 rows=593
loops=1)
Hash Cond: ("outer".poid =
"inner".poid)
-> Seq Scan on poparts e
(cost=0.00..476.60 rows=16860 width=32) (actual time=0.037..65.660 rows=16860
loops=1)
-> Hash
(cost=373.59..373.59 rows=1620 width=8) (actual time=11.348..11.348 rows=0 loops=1)
-> Seq Scan on pos f
(cost=0.00..373.59 rows=1620 width=8) (actual time=0.124..10.621 rows=183 loops=1)
Filter: ((postatusid
>= 20) AND (postatusid <= 59) AND (isrfq = false))
-> Hash (cost=197.01..197.01
rows=7001 width=4) (actual time=54.561..54.561 rows=0 loops=1)
-> Seq Scan on
manufacturerpartpn g (cost=0.00..197.01 rows=7001 width=4) (actual
time=0.035..29.047 rows=7001 loops=1)
Total runtime: 3763.256 ms
---------------------------------------------------------------------------------------------------------------------
8.2.4 Slow query
GroupAggregate (cost=5944.26..5944.50 rows=1 width=32) (actual
time=608067.502..608144.235 rows=83 loops=1)
-> GroupAggregate (cost=5944.26..5944.41 rows=1 width=112) (actual
time=608067.439..608127.305 rows=3684 loops=1)
-> Sort (cost=5944.26..5944.27 rows=3 width=112) (actual
time=608067.381..608083.775 rows=7400 loops=1)
Sort Key: a.assembliesbatchid, a.duedate, a.assemblyid,
a.assemblyname, a.ownerid, a.partid, a.quantity, a.stock, a.prioruse, a.units,
a.qtyperunit
-> Nested Loop Left Join (cost=5311.54..5944.24 rows=3
width=112) (actual time=341040.765..607912.624 rows=7400 loops=1)
Join Filter: (e.partid = a.partid)
-> GroupAggregate (cost=4689.90..4689.96 rows=1 width=85)
(actual time=340891.895..341154.807 rows=3684 loops=1)
-> Sort (cost=4689.90..4689.91 rows=1 width=85)
(actual time=340891.872..340989.892 rows=36876 loops=1)
Sort Key: a.assembliesbatchid, a.duedate,
a.assemblyid, a.assemblyname, a.ownerid, a.partid, a.quantity, a.stock,
a.units, a.qtyperunit, a.leadfree
-> Nested Loop Left Join
(cost=4224.98..4689.89 rows=1 width=85) (actual time=22886.336..340100.378
rows=36876 loops=1)
Join Filter: ((a.partid = b.partid) AND
(COALESCE(a.ownerid, 1) = 1) AND (a.leadfree = q.leadfree) AND ((a.duedate >
c.duedate) OR ((a.duedate = c.duedate) AND (a.assembliesbatchid >
c.assembliesbatchid))))
-> GroupAggregate
(cost=4127.29..4127.34 rows=1 width=82) (actual time=22801.528..22859.419
rows=3684 loops=1)
-> Sort (cost=4127.29..4127.30
rows=1 width=82) (actual time=22801.498..22812.312 rows=3685 loops=1)
Sort Key:
d.assembliesbatchid, d.duedate, a.assemblyid, a.assemblyname, c.ownerid,
e.partid, COALESCE(c.stock, 0::bigint), d.units, e.quantity, a.leadfree
-> Nested Loop Left Join
(cost=3984.15..4127.28 rows=1 width=82) (actual time=360.261..22766.654 rows=3685
loops=1)
-> Nested Loop Left
Join (cost=3984.15..4126.99 rows=1 width=74) (actual time=360.168..22680.414
rows=3685 loops=1)
Join Filter:
((c.partid = e.partid) AND leadcompcheck_ab(a.leadfree, c.leadstateid))
-> Nested Loop
(cost=3984.15..4111.92 rows=1 width=62) (actual time=319.721..411.494 rows=3685
loops=1)
-> Merge
Left Join (cost=3984.15..4111.60 rows=1 width=28) (actual time=319.642..348.285
rows=3685 loops=1)
Merge
Cond: ((d.batchid = f.refid) AND (e.partid = f.partid))
Filter: (NOT COALESCE(f.commited, false))
->
Sort (cost=664.36..667.47 rows=1244 width=32) (actual time=68.579..75.827
rows=3684 loops=1)
Sort Key: d.batchid, e.partid
-> Hash Join (cost=71.92..600.42 rows=1244 width=32) (actual
time=3.199..52.985 rows=3684 loops=1)
Hash Cond: (e.assembliesbatchid = d.assembliesbatchid)
-> Seq Scan on allocatedassemblies e (cost=0.00..444.93 rows=18967
width=12) (actual time=0.060..25.590 rows=11332 loops=1)
Filter: ((- quantity) <> 0)
-> Hash (cost=70.70..70.70 rows=98 width=24) (actual time=0.672..0.672
rows=99 loops=1)
-> Bitmap Heap Scan on assembliesbatch d (cost=17.75..70.70 rows=98
width=24) (actual time=0.149..0.453 rows=99 loops=1)
Recheck Cond: (assembliesbatchstatusid = ANY
('{1,2,4,7}'::integer[]))
-> Bitmap Index Scan on
fki_assembliesbatch_assembliesbatchstatus_id (cost=0.00..17.72 rows=98 width=0)
(actual time=0.121..0.121 rows=99 loops=1)
Index Cond: (assembliesbatchstatusid = ANY
('{1,2,4,7}'::integer[]))
->
Sort (cost=3319.79..3382.16 rows=24951 width=9) (actual time=160.006..210.204
rows=25267 loops=1)
Sort Key: f.refid, f.partid
-> Bitmap Heap Scan on stocklog f (cost=417.63..1497.51 rows=24951 width=9)
(actual time=5.599..63.420 rows=25267 loops=1)
Recheck Cond: (transtypeid = 3)
-> Bitmap Index Scan on targetidsl (cost=0.00..411.39 rows=24951 width=0)
(actual time=5.379..5.379 rows=25267 loops=1)
Index Cond: (transtypeid = 3)
-> Index
Scan using assemblies_pkey on assemblies a (cost=0.00..0.31 rows=1 width=38)
(actual time=0.007..0.009 rows=1 loops=3685)
Index
Cond: (d.assemblyid = a.assemblyid)
-> Function Scan
on stockperowner_lead_ab c (cost=0.00..15.00 rows=5 width=20) (actual
time=0.012..3.162 rows=1694 loops=3685)
Filter:
(ownerid = 1)
-> Index Scan using
idx_u_assidpartid on partsassembly b (cost=0.00..0.27 rows=1 width=16) (actual
time=0.010..0.012 rows=1 loops=3685)
Index Cond:
((e.partid = b.partid) AND (b.assemblyid = a.assemblyid))
-> Hash Join (cost=97.69..531.29
rows=1250 width=21) (actual time=2.395..78.855 rows=3851 loops=3684)
Hash Cond: (b.assembliesbatchid =
c.assembliesbatchid)
-> Seq Scan on allocatedassemblies
b (cost=0.00..349.62 rows=19062 width=12) (actual time=0.009..35.493 rows=19062
loops=3684)
-> Hash (cost=96.47..96.47
rows=98 width=13) (actual time=3.796..3.796 rows=99 loops=1)
-> Hash Join
(cost=42.14..96.47 rows=98 width=13) (actual time=2.939..3.596 rows=99 loops=1)
Hash Cond:
(c.assemblyid = q.assemblyid)
-> Bitmap Heap Scan on
assembliesbatch c (cost=17.85..70.83 rows=98 width=16) (actual time=0.137..0.397
rows=99 loops=1)
Recheck Cond:
((assembliesbatchstatusid = 1) OR (assembliesbatchstatusid = 2) OR
(assembliesbatchstatusid = 4) OR (assembliesbatchstatusid = 7))
-> BitmapOr
(cost=17.85..17.85 rows=99 width=0) (actual time=0.111..0.111 rows=0 loops=1)
-> Bitmap
Index Scan on fki_assembliesbatch_assembliesbatchstatus_id (cost=0.00..4.85
rows=80 width=0) (actual time=0.066..0.066 rows=80 loops=1)
Index
Cond: (assembliesbatchstatusid = 1)
-> Bitmap
Index Scan on fki_assembliesbatch_assembliesbatchstatus_id (cost=0.00..4.26
rows=1 width=0) (actual time=0.006..0.006 rows=0 loops=1)
Index
Cond: (assembliesbatchstatusid = 2)
-> Bitmap
Index Scan on fki_assembliesbatch_assembliesbatchstatus_id (cost=0.00..4.27
rows=3 width=0) (actual time=0.006..0.006 rows=3 loops=1)
Index
Cond: (assembliesbatchstatusid = 4)
-> Bitmap
Index Scan on fki_assembliesbatch_assembliesbatchstatus_id (cost=0.00..4.37
rows=16 width=0) (actual time=0.022..0.022 rows=16 loops=1)
Index
Cond: (assembliesbatchstatusid = 7)
-> Hash
(cost=15.24..15.24 rows=724 width=5) (actual time=2.785..2.785 rows=724 loops=1)
-> Seq Scan on
assemblies q (cost=0.00..15.24 rows=724 width=5) (actual time=0.011..1.356
rows=724 loops=1)
-> Hash Join (cost=621.63..1206.10 rows=3854 width=28)
(actual time=0.074..71.265 rows=593 loops=3684)
Hash Cond: (e.pnid = g.pnid)
-> Hash Join (cost=337.11..839.61 rows=3860
width=32) (actual time=0.057..68.467 rows=593 loops=3684)
Hash Cond: (e.poid = f.poid)
-> Seq Scan on poparts e (cost=0.00..379.60
rows=16860 width=32) (actual time=0.008..34.510 rows=16860 loops=3684)
-> Hash (cost=317.17..317.17 rows=1595
width=8) (actual time=7.266..7.266 rows=183 loops=1)
-> Bitmap Heap Scan on pos f
(cost=54.06..317.17 rows=1595 width=8) (actual time=1.519..6.843 rows=183 loops=1)
Recheck Cond: ((postatusid >= 20) AND
(postatusid <= 59))
Filter: (NOT isrfq)
-> Bitmap Index Scan on
postatusidpo (cost=0.00..53.66 rows=2541 width=0) (actual time=1.418..1.418
rows=2700 loops=1)
Index Cond: ((postatusid >= 20)
AND (postatusid <= 59))
-> Hash (cost=197.01..197.01 rows=7001 width=4)
(actual time=42.248..42.248 rows=7001 loops=1)
-> Seq Scan on manufacturerpartpn g
(cost=0.00..197.01 rows=7001 width=4) (actual time=0.030..19.935 rows=7001 loops=1)
Total runtime: 608146.760 ms
---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?
http://www.postgresql.org/docs/faq
