8.2.4 serious slowdown - Mailing list pgsql-general
From | Sim Zacks |
---|---|
Subject | 8.2.4 serious slowdown |
Date | |
Msg-id | fm5asf$1q0v$1@news.hub.org Whole thread Raw |
Responses |
Re: 8.2.4 serious slowdown
Re: 8.2.4 serious slowdown Re: 8.2.4 serious slowdown Re: 8.2.4 serious slowdown Re: 8.2.4 serious slowdown |
List | pgsql-general |
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.404rows=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.342rows=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.321rows=3684 loops=1) -> GroupAggregate (cost=6877.75..6919.15 rows=125 width=85) (actual time=2700.456..3106.694rows=3684 loops=1) -> Sort (cost=6877.75..6880.86 rows=1245 width=85) (actual time=2700.414..2839.777rows=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) (actualtime=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=1245width=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=1245width=86) (actual time=682.055..694.675 rows=3684 loops=1) Sort Key: d.batchid, e.partid -> Hash Left Join (cost=737.64..2318.10rows=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.73rows=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_assidpartidon 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.74rows=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.62rows=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) HashCond: ("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.43rows=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.00rows=5 width=20) (actual time=80.500..80.500 rows=0 loops=1) -> Function Scan on stockperowner_lead_abc (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=25605width=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.92rows=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.583rows=0 loops=1) -> Hash Join (cost=71.73..563.93 rows=1251 width=21) (actualtime=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.62rows=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.43rows=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) (actualtime=5.733..5.733 rows=0 loops=1) -> Seq Scan on assemblies q (cost=0.00..15.24rows=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=0loops=1) -> Hash Join (cost=592.15..1332.57 rows=3924 width=28) (actual time=66.119..199.853rows=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.401rows=593 loops=1) Hash Cond: ("outer".poid = "inner".poid) -> Seq Scan on poparts e (cost=0.00..476.60 rows=16860 width=32) (actualtime=0.037..65.660 rows=16860 loops=1) -> Hash (cost=373.59..373.59 rows=1620 width=8) (actual time=11.348..11.348rows=0 loops=1) -> Seq Scan on pos f (cost=0.00..373.59 rows=1620 width=8) (actualtime=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.561rows=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=7400loops=1) Join Filter: (e.partid = a.partid) -> GroupAggregate (cost=4689.90..4689.96 rows=1 width=85) (actual time=340891.895..341154.807 rows=3684loops=1) -> Sort (cost=4689.90..4689.91 rows=1 width=85) (actual time=340891.872..340989.892 rows=36876loops=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.378rows=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.419rows=3684 loops=1) -> Sort (cost=4127.29..4127.30 rows=1 width=82) (actual time=22801.498..22812.312rows=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) (actualtime=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) (actualtime=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=1244width=32) (actual time=3.199..52.985 rows=3684 loops=1) Hash Cond: (e.assembliesbatchid =d.assembliesbatchid) -> Seq Scan on allocatedassembliese (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=98width=24) (actual time=0.672..0.672 rows=99 loops=1) -> Bitmap Heap Scan on assembliesbatchd (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 Scanon fki_assembliesbatch_assembliesbatchstatus_id (cost=0.00..17.72 rows=98 width=0) (actual time=0.121..0.121 rows=99loops=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.51rows=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.00rows=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.27rows=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.855rows=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=99loops=1) -> Hash Join (cost=42.14..96.47 rows=98 width=13) (actual time=2.939..3.596rows=99 loops=1) Hash Cond: (c.assemblyid = q.assemblyid) -> Bitmap Heap Scan on assembliesbatch c (cost=17.85..70.83 rows=98width=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) (actualtime=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.785rows=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.510rows=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.843rows=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.935rows=7001 loops=1) Total runtime: 608146.760 ms
pgsql-general by date: