Re: Identical query slower on 8.4 vs 8.3

> -----Original Message-----
> From: Patrick Donlin [mailto:pdonlin@oaisd.org]
> Sent: Thursday, July 15, 2010 11:13 AM
> To: Kevin Grittner; pgsql-performance@postgresql.org
> Subject: Re: Identical query slower on 8.4 vs 8.3
>
> 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
>

Well, now that you've got similar runtime on both 8.4.4 and 8.3.7, here
is a suggestion to improve performance of this query based on EXPLAIN
ANALYZE you proveded (should have done it in your first e-mail).

EXPLAIN ANALYZE shows that most of the time (22015 ms on 8.4.4) spent on
sorting you result set.
And according to this: "Sort Method:  external merge  Disk: 71768kB" -
sorting is done using disk, meaning your work_mem setting is not
sufficient to do this sort in memory (I didn't go back through this
thread far enough, to see if you provided info on how it is set).

I'd suggest to increase the value up to ~80MB, if not for the system,
may be just for the session running this query.
Then see if performance improved.

And, with query performance issues always start with EXPLAIN ANALYZE.

Regards,
Igor Neyman