Received: from maia.hub.org (maia-3.hub.org [200.46.204.243]) by mail.postgresql.org (Postfix) with ESMTP id 6A42F632C31 for ; Thu, 15 Jul 2010 12:13:07 -0300 (ADT) Received: from mail.postgresql.org ([200.46.204.86]) by maia.hub.org (mx1.hub.org [200.46.204.243]) (amavisd-maia, port 10024) with ESMTP id 47876-03 for ; Thu, 15 Jul 2010 15:13:00 +0000 (UTC) X-Greylist: from auto-whitelisted by SQLgrey-1.7.6 Received: from mm-mailstore02.merit.edu (mm-mailstore02.merit.edu [207.74.184.19]) by mail.postgresql.org (Postfix) with ESMTP id BE58363270E for ; Thu, 15 Jul 2010 12:12:59 -0300 (ADT) Received: from localhost (localhost.localdomain [127.0.0.1]) by mm-mailstore02.merit.edu (Postfix) with ESMTP id 32F236800FE4; Thu, 15 Jul 2010 11:12:59 -0400 (EDT) X-Virus-Scanned: amavisd-new at mm-mailstore02.merit.edu Received: from mm-mailstore02.merit.edu ([127.0.0.1]) by localhost (mm-mailstore02.merit.edu [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id q3cQ3t3YJNzN; Thu, 15 Jul 2010 11:12:53 -0400 (EDT) Received: from mm-mailstore02.merit.edu (mm-mailstore02.merit.edu [10.108.2.25]) by mm-mailstore02.merit.edu (Postfix) with ESMTP id B20AE6800FF5; Thu, 15 Jul 2010 11:12:53 -0400 (EDT) Date: Thu, 15 Jul 2010 11:12:53 -0400 (EDT) From: Patrick Donlin To: Kevin Grittner , pgsql-performance@postgresql.org Message-ID: <1123546138.13276371279206773000.JavaMail.root@mm-mailstore02.merit.edu> In-Reply-To: <4C3EDB070200002500033621@gw.wicourts.gov> Subject: Re: Identical query slower on 8.4 vs 8.3 MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----=_Part_447531_499915486.1279206772998" X-Originating-IP: [64.9.158.13] X-Mailer: Zimbra 5.0.21_GA_3150.RHEL5_64 (ZimbraWebClient - FF3.0 (Mac)/5.0.21_GA_3150.RHEL5_64) X-Virus-Scanned: Maia Mailguard 1.0.1 X-Spam-Status: No, hits=-4.199 tagged_above=-10 required=5 tests=BAYES_00=-1.9, HTML_MESSAGE=0.001, RCVD_IN_DNSWL_MED=-2.3 X-Spam-Level: X-Archive-Number: 201007/237 X-Sequence-Number: 39626 ------=_Part_447531_499915486.1279206772998 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit I'll read over that wiki entry, but for now here is the EXPLAIN ANALYZE output assuming I did it correctly. I have run vacuumdb --full --analyze, it actually runs as a nightly cron job. 8.4.4 Sever: "Unique (cost=202950.82..227521.59 rows=702022 width=86) (actual time=21273.371..22429.511 rows=700536 loops=1)" " -> Sort (cost=202950.82..204705.87 rows=702022 width=86) (actual time=21273.368..22015.948 rows=700536 loops=1)" " Sort Key: test.tid, testresult.trscore, testresult.trpossiblescore, testresult.trstart, testresult.trfinish, testresult.trscorebreakdown, testresult.fk_sid, test.tname, qr.qrscore, qr.qrtotalscore, testresult.trid, qr.qrid" " Sort Method: external merge Disk: 71768kB" " -> Hash Join (cost=2300.82..34001.42 rows=702022 width=86) (actual time=64.388..1177.468 rows=700536 loops=1)" " Hash Cond: (qr.fk_trid = testresult.trid)" " -> Seq Scan on questionresult qr (cost=0.00..12182.22 rows=702022 width=16) (actual time=0.090..275.518 rows=702022 loops=1)" " -> Hash (cost=1552.97..1552.97 rows=29668 width=74) (actual time=63.042..63.042 rows=29515 loops=1)" " -> Hash Join (cost=3.35..1552.97 rows=29668 width=74) (actual time=0.227..39.111 rows=29515 loops=1)" " Hash Cond: (testresult.fk_tid = test.tid)" " -> Seq Scan on testresult (cost=0.00..1141.68 rows=29668 width=53) (actual time=0.019..15.622 rows=29668 loops=1)" " -> Hash (cost=2.60..2.60 rows=60 width=21) (actual time=0.088..0.088 rows=60 loops=1)" " -> Seq Scan on test (cost=0.00..2.60 rows=60 width=21) (actual time=0.015..0.044 rows=60 loops=1)" "Total runtime: 22528.820 ms" 8.3.7 Server: "Unique (cost=202950.82..227521.59 rows=702022 width=86) (actual time=22157.714..23343.461 rows=700536 loops=1)" " -> Sort (cost=202950.82..204705.87 rows=702022 width=86) (actual time=22157.706..22942.018 rows=700536 loops=1)" " Sort Key: test.tid, testresult.trscore, testresult.trpossiblescore, testresult.trstart, testresult.trfinish, testresult.trscorebreakdown, testresult.fk_sid, test.tname, qr.qrscore, qr.qrtotalscore, testresult.trid, qr.qrid" " Sort Method: external merge Disk: 75864kB" " -> Hash Join (cost=2300.82..34001.42 rows=702022 width=86) (actual time=72.842..1276.634 rows=700536 loops=1)" " Hash Cond: (qr.fk_trid = testresult.trid)" " -> Seq Scan on questionresult qr (cost=0.00..12182.22 rows=702022 width=16) (actual time=0.112..229.987 rows=702022 loops=1)" " -> Hash (cost=1552.97..1552.97 rows=29668 width=74) (actual time=71.421..71.421 rows=29515 loops=1)" " -> Hash Join (cost=3.35..1552.97 rows=29668 width=74) (actual time=0.398..44.524 rows=29515 loops=1)" " Hash Cond: (testresult.fk_tid = test.tid)" " -> Seq Scan on testresult (cost=0.00..1141.68 rows=29668 width=53) (actual time=0.117..20.890 rows=29668 loops=1)" " -> Hash (cost=2.60..2.60 rows=60 width=21) (actual time=0.112..0.112 rows=60 loops=1)" " -> Seq Scan on test (cost=0.00..2.60 rows=60 width=21) (actual time=0.035..0.069 rows=60 loops=1)" "Total runtime: 23462.639 ms" Thanks for the quick responses and being patient with me not providing enough information. -Patrick ----- Original Message ----- From: "Kevin Grittner" To: "Patrick Donlin" , pgsql-performance@postgresql.org Sent: Thursday, July 15, 2010 10:55:19 AM GMT -05:00 US/Canada Eastern Subject: Re: [PERFORM] Identical query slower on 8.4 vs 8.3 Patrick Donlin wrote: > Anyone have any ideas on where I should start looking to figure > this out? You're going to want to run EXPLAIN ANALYZE for the slow query on both servers. If you want the rest of us to be able to contribute ideas, we'll need a little more information -- please read this page: http://wiki.postgresql.org/wiki/SlowQueryQuestions > I didn't perform any special steps when moving to v8.4, I just did > a pg_dump from the 8.3 server and restored it on the new 8.4 > servers. A database VACUUM ANALYZE by a superuser is a good idea; otherwise that's fine technique. -Kevin ------=_Part_447531_499915486.1279206772998 Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: quoted-printable <= div style=3D'font-family: Arial; font-size: 12pt; color: #000000'>I'll read= over that wiki entry, but for now here is the EXPLAIN ANALYZE=20 output assuming I did it correctly. I have run vacuumdb --full=20 --analyze,  it actually runs as a nightly cron job.

8.4.4 Sever:
"Unique  (cost=3D202950.82..227521.59 rows=3D702022 width=3D86) (actua= l=20 time=3D21273.371..22429.511 rows=3D700536 loops=3D1)"
"  ->  Sort  (cost=3D202950.82..204705.87 rows=3D702022 w= idth=3D86) (actual time=3D21273.368..22015.948 rows=3D700536 loops=3D1)"
"        Sort Key: test.tid, testresult.= trscore,=20 testresult.trpossiblescore, testresult.trstart, testresult.trfinish,=20 testresult.trscorebreakdown, testresult.fk_sid, test.tname, qr.qrscore,=20 qr.qrtotalscore, testresult.trid, qr.qrid"
"        Sort Method:  external mer= ge  Disk: 71768kB"
"        ->  Hash Join  (co= st=3D2300.82..34001.42 rows=3D702022 width=3D86) (actual time=3D64.388..1177.468 rows=3D700536 loops=3D1)"
"            &n= bsp; Hash Cond: (qr.fk_trid =3D testresult.trid)"
"            &n= bsp; ->  Seq Scan on questionresult qr =20 (cost=3D0.00..12182.22 rows=3D702022 width=3D16) (actual time=3D0.090..275.= 518=20 rows=3D702022 loops=3D1)"
"            &n= bsp; ->  Hash  (cost=3D1552.97..1552.97 rows=3D29668 width=3D7= 4)=20 (actual time=3D63.042..63.042 rows=3D29515 loops=3D1)"
"            &n= bsp;       ->  Hash Join  (cost= =3D3.35..1552.97 rows=3D29668=20 width=3D74) (actual time=3D0.227..39.111 rows=3D29515 loops=3D1)"
"            &n= bsp;            = ; Hash Cond: (testresult.fk_tid =3D test.tid)"
"            &n= bsp;            = ; ->  Seq Scan on testresult =20 (cost=3D0.00..1141.68 rows=3D29668 width=3D53) (actual time=3D0.019..15.622= =20 rows=3D29668 loops=3D1)"
"            &n= bsp;            = ; ->  Hash  (cost=3D2.60..2.60 rows=3D60=20 width=3D21) (actual time=3D0.088..0.088 rows=3D60 loops=3D1)"
"            &n= bsp;            = ;       ->  Seq Scan on test =20 (cost=3D0.00..2.60 rows=3D60 width=3D21) (actual time=3D0.015..0.044 rows= =3D60=20 loops=3D1)"
"Total runtime: 22528.820 ms"

8.3.7 Server:
"Unique  (cost=3D202950.82..227521.59 rows=3D702022 width=3D86) (actua= l=20 time=3D22157.714..23343.461 rows=3D700536 loops=3D1)"
"  ->  Sort  (cost=3D202950.82..204705.87 rows=3D702022 w= idth=3D86) (actual time=3D22157.706..22942.018 rows=3D700536 loops=3D1)"
"        Sort Key: test.tid, testresult.= trscore,=20 testresult.trpossiblescore, testresult.trstart, testresult.trfinish,=20 testresult.trscorebreakdown, testresult.fk_sid, test.tname, qr.qrscore,=20 qr.qrtotalscore, testresult.trid, qr.qrid"
"        Sort Method:  external mer= ge  Disk: 75864kB"
"        ->  Hash Join  (co= st=3D2300.82..34001.42 rows=3D702022 width=3D86) (actual time=3D72.842..1276.634 rows=3D700536 loops=3D1)"
"            &n= bsp; Hash Cond: (qr.fk_trid =3D testresult.trid)"
"            &n= bsp; ->  Seq Scan on questionresult qr =20 (cost=3D0.00..12182.22 rows=3D702022 width=3D16) (actual time=3D0.112..229.= 987=20 rows=3D702022 loops=3D1)"
"            &n= bsp; ->  Hash  (cost=3D1552.97..1552.97 rows=3D29668 width=3D7= 4)=20 (actual time=3D71.421..71.421 rows=3D29515 loops=3D1)"
"            &n= bsp;       ->  Hash Join  (cost= =3D3.35..1552.97 rows=3D29668=20 width=3D74) (actual time=3D0.398..44.524 rows=3D29515 loops=3D1)"
"            &n= bsp;            = ; Hash Cond: (testresult.fk_tid =3D test.tid)"
"            &n= bsp;            = ; ->  Seq Scan on testresult =20 (cost=3D0.00..1141.68 rows=3D29668 width=3D53) (actual time=3D0.117..20.890= =20 rows=3D29668 loops=3D1)"
"            &n= bsp;            = ; ->  Hash  (cost=3D2.60..2.60 rows=3D60=20 width=3D21) (actual time=3D0.112..0.112 rows=3D60 loops=3D1)"
"            &n= bsp;            = ;       ->  Seq Scan on test =20 (cost=3D0.00..2.60 rows=3D60 width=3D21) (actual time=3D0.035..0.069 rows= =3D60=20 loops=3D1)"
"Total runtime: 23462.639 ms"


Thanks for the quick responses and being patient with me not providing=20 enough information.
-Patrick

----- Original Message -----
From: "Kevin Grittner" <= Kevin.Grittner@wicourts.gov>
To: "Patrick Donlin" <pdonlin@oaisd.o= rg>, pgsql-performance@postgresql.org
Sent: Thursday, July 15, 2010 1= 0:55:19 AM GMT -05:00 US/Canada Eastern
Subject: Re: [PERFORM] Identical= query slower on 8.4 vs 8.3

Patrick Donlin <pdonlin@oaisd.org>= wrote:
 
> Anyone have any ideas on where I should start loo= king to figure
> this out?
 
You're going to want to run E= XPLAIN ANALYZE for the slow query on
both servers.  If you want the= rest of us to be able to contribute
ideas, we'll need a little more inf= ormation -- please read this
page:
 
http://wiki.postgresql.o= rg/wiki/SlowQueryQuestions
 
> I didn't perform any special s= teps when moving to v8.4, I just did
> a pg_dump from the 8.3 server = and restored it on the new 8.4
> servers.
 
A database VAC= UUM ANALYZE by a superuser is a good idea; otherwise
that's fine techniq= ue.
 
-Kevin
------=_Part_447531_499915486.1279206772998--