8.2.4 serious slowdown

From: Sim Zacks <sim(at)compulab(dot)co(dot)il>
To: pgsql-general(at)postgresql(dot)org
Subject: 8.2.4 serious slowdown
Date: 2008-01-10 14:40:04
Message-ID: fm5asf$1q0v$1@news.hub.org
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general pgsql-hackers

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

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Raymond O'Donnell 2008-01-10 14:42:54 Re: Installation problem: failed to initialize lc_messages to ""
Previous Message Merlin Moncure 2008-01-10 13:56:11 Re: Query to get column-names in table via PG tables?

Browse pgsql-hackers by date

  From Date Subject
Next Message Pavel Stehule 2008-01-10 14:47:02 Re: to_char incompatibility
Previous Message Roberts, Jon 2008-01-10 13:42:51 Re: to_char incompatibility