Re: Identical query slower on 8.4 vs 8.3

On Thu, Jul 15, 2010 at 11:12 AM, Patrick Donlin <pdonlin(at)oaisd(dot)org> wrote:
> 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"

your plans are identical as is the runtime basically. this means you
might want to consider the following possibilities:
*) operator error :-)
*) cache effects
*) environmental factors on the server at the time
*) network/client issues

I say network issues because if your explain analyze (which actually
does run the entire query) is significantly faster than the full
query, then we have to consider that the formatting and transfer of
the data back to the client (even if it's on the same box) becomes
suspicious. If you've eliminated other possibilities, try running
other big, trivially planned, mucho result returning queries (like
select * from table) on both servers and comparing times.

merlin