Hash join on int takes 8..114 seconds

Query below seems to use indexes everywhere in most optimal way.
dokumnr column is of type int

Speed of this query varies rapidly:

In live db fastest response I have got is 8 seconds.
Re-running same query  after 10 seconds may take 60 seconds.
Re-running it again after 10 seconds may take 114 seconds.

Any idea how to speed it up ?

Is it possible to optimize it, will upgrading to 8.3.5 help or should I
require to add more RAM, disk or CPU speed ?

Real query contains column list instead of sum(1) used in test below.

Andrus.


explain analyze
SELECT sum(1)
   FROM dok JOIN rid USING (dokumnr)
   JOIN toode USING (toode)
   LEFT JOIN artliik using(grupp,liik)
   WHERE rid.toode='X05' AND dok.kuupaev>='2008-09-01'

longest response time:

"Aggregate  (cost=234278.53..234278.54 rows=1 width=0) (actual
time=114479.933..114479.936 rows=1 loops=1)"
"  ->  Hash Left Join  (cost=52111.20..234218.21 rows=24126 width=0) (actual
time=100435.523..114403.293 rows=20588 loops=1)"
"        Hash Cond: (("outer".grupp = "inner".grupp) AND ("outer".liik =
"inner".liik))"
"        ->  Nested Loop  (cost=52103.94..233735.35 rows=24126 width=19)
(actual time=100405.258..114207.387 rows=20588 loops=1)"
"              ->  Index Scan using toode_pkey on toode  (cost=0.00..6.01
rows=1 width=43) (actual time=18.312..18.325 rows=1 loops=1)"
"                    Index Cond: ('X05'::bpchar = toode)"
"              ->  Hash Join  (cost=52103.94..233488.08 rows=24126 width=24)
(actual time=100386.921..114037.986 rows=20588 loops=1)"
"                    Hash Cond: ("outer".dokumnr = "inner".dokumnr)"
"                    ->  Bitmap Heap Scan on rid  (cost=4127.51..175020.84
rows=317003 width=28) (actual time=11119.932..76225.918 rows=277294
loops=1)"
"                          Recheck Cond: (toode = 'X05'::bpchar)"
"                          ->  Bitmap Index Scan on rid_toode_idx
(cost=0.00..4127.51 rows=317003 width=0) (actual time=11105.807..11105.807
rows=280599 loops=1)"
"                                Index Cond: (toode = 'X05'::bpchar)"
"                    ->  Hash  (cost=47376.82..47376.82 rows=93444 width=4)
(actual time=35082.427..35082.427 rows=105202 loops=1)"
"                          ->  Index Scan using dok_kuupaev_idx on dok
(cost=0.00..47376.82 rows=93444 width=4) (actual time=42.110..34586.331
rows=105202 loops=1)"
"                                Index Cond: (kuupaev >=
'2008-09-01'::date)"
"        ->  Hash  (cost=6.84..6.84 rows=84 width=19) (actual
time=30.220..30.220 rows=84 loops=1)"
"              ->  Seq Scan on artliik  (cost=0.00..6.84 rows=84 width=19)
(actual time=20.104..29.845 rows=84 loops=1)"
"Total runtime: 114480.373 ms"

Same query in other runs:


"Aggregate  (cost=234278.53..234278.54 rows=1 width=0) (actual
time=62164.496..62164.500 rows=1 loops=1)"
"  ->  Hash Left Join  (cost=52111.20..234218.21 rows=24126 width=0) (actual
time=46988.005..62088.379 rows=20588 loops=1)"
"        Hash Cond: (("outer".grupp = "inner".grupp) AND ("outer".liik =
"inner".liik))"
"        ->  Nested Loop  (cost=52103.94..233735.35 rows=24126 width=19)
(actual time=46957.750..61893.613 rows=20588 loops=1)"
"              ->  Index Scan using toode_pkey on toode  (cost=0.00..6.01
rows=1 width=43) (actual time=146.530..146.543 rows=1 loops=1)"
"                    Index Cond: ('X05'::bpchar = toode)"
"              ->  Hash Join  (cost=52103.94..233488.08 rows=24126 width=24)
(actual time=46811.194..61595.560 rows=20588 loops=1)"
"                    Hash Cond: ("outer".dokumnr = "inner".dokumnr)"
"                    ->  Bitmap Heap Scan on rid  (cost=4127.51..175020.84
rows=317003 width=28) (actual time=1870.209..55864.237 rows=277294 loops=1)"
"                          Recheck Cond: (toode = 'X05'::bpchar)"
"                          ->  Bitmap Index Scan on rid_toode_idx
(cost=0.00..4127.51 rows=317003 width=0) (actual time=1863.713..1863.713
rows=280599 loops=1)"
"                                Index Cond: (toode = 'X05'::bpchar)"
"                    ->  Hash  (cost=47376.82..47376.82 rows=93444 width=4)
(actual time=1650.823..1650.823 rows=105202 loops=1)"
"                          ->  Index Scan using dok_kuupaev_idx on dok
(cost=0.00..47376.82 rows=93444 width=4) (actual time=0.091..1190.962
rows=105202 loops=1)"
"                                Index Cond: (kuupaev >=
'2008-09-01'::date)"
"        ->  Hash  (cost=6.84..6.84 rows=84 width=19) (actual
time=30.210..30.210 rows=84 loops=1)"
"              ->  Seq Scan on artliik  (cost=0.00..6.84 rows=84 width=19)
(actual time=20.069..29.836 rows=84 loops=1)"
"Total runtime: 62164.789 ms"



"Aggregate  (cost=234278.53..234278.54 rows=1 width=0) (actual
time=40185.499..40185.503 rows=1 loops=1)"
"  ->  Hash Left Join  (cost=52111.20..234218.21 rows=24126 width=0) (actual
time=32646.761..40109.470 rows=20585 loops=1)"
"        Hash Cond: (("outer".grupp = "inner".grupp) AND ("outer".liik =
"inner".liik))"
"        ->  Nested Loop  (cost=52103.94..233735.35 rows=24126 width=19)
(actual time=32645.933..39944.242 rows=20585 loops=1)"
"              ->  Index Scan using toode_pkey on toode  (cost=0.00..6.01
rows=1 width=43) (actual time=0.072..0.085 rows=1 loops=1)"
"                    Index Cond: ('X05'::bpchar = toode)"
"              ->  Hash Join  (cost=52103.94..233488.08 rows=24126 width=24)
(actual time=32645.839..39793.180 rows=20585 loops=1)"
"                    Hash Cond: ("outer".dokumnr = "inner".dokumnr)"
"                    ->  Bitmap Heap Scan on rid  (cost=4127.51..175020.84
rows=317003 width=28) (actual time=1823.542..36318.419 rows=277291 loops=1)"
"                          Recheck Cond: (toode = 'X05'::bpchar)"
"                          ->  Bitmap Index Scan on rid_toode_idx
(cost=0.00..4127.51 rows=317003 width=0) (actual time=1817.053..1817.053
rows=280596 loops=1)"
"                                Index Cond: (toode = 'X05'::bpchar)"
"                    ->  Hash  (cost=47376.82..47376.82 rows=93444 width=4)
(actual time=1242.785..1242.785 rows=105195 loops=1)"
"                          ->  Index Scan using dok_kuupaev_idx on dok
(cost=0.00..47376.82 rows=93444 width=4) (actual time=0.088..788.399
rows=105195 loops=1)"
"                                Index Cond: (kuupaev >=
'2008-09-01'::date)"
"        ->  Hash  (cost=6.84..6.84 rows=84 width=19) (actual
time=0.786..0.786 rows=84 loops=1)"
"              ->  Seq Scan on artliik  (cost=0.00..6.84 rows=84 width=19)
(actual time=0.019..0.419 rows=84 loops=1)"
"Total runtime: 40186.102 ms"


"Aggregate  (cost=234278.53..234278.54 rows=1 width=0) (actual
time=29650.398..29650.402 rows=1 loops=1)"
"  ->  Hash Left Join  (cost=52111.20..234218.21 rows=24126 width=0) (actual
time=23513.713..29569.448 rows=20588 loops=1)"
"        Hash Cond: (("outer".grupp = "inner".grupp) AND ("outer".liik =
"inner".liik))"
"        ->  Nested Loop  (cost=52103.94..233735.35 rows=24126 width=19)
(actual time=23512.808..29388.712 rows=20588 loops=1)"
"              ->  Index Scan using toode_pkey on toode  (cost=0.00..6.01
rows=1 width=43) (actual time=61.813..61.825 rows=1 loops=1)"
"                    Index Cond: ('X05'::bpchar = toode)"
"              ->  Hash Join  (cost=52103.94..233488.08 rows=24126 width=24)
(actual time=23450.970..29163.774 rows=20588 loops=1)"
"                    Hash Cond: ("outer".dokumnr = "inner".dokumnr)"
"                    ->  Bitmap Heap Scan on rid  (cost=4127.51..175020.84
rows=317003 width=28) (actual time=2098.630..24362.104 rows=277294 loops=1)"
"                          Recheck Cond: (toode = 'X05'::bpchar)"
"                          ->  Bitmap Index Scan on rid_toode_idx
(cost=0.00..4127.51 rows=317003 width=0) (actual time=2086.772..2086.772
rows=280599 loops=1)"
"                                Index Cond: (toode = 'X05'::bpchar)"
"                    ->  Hash  (cost=47376.82..47376.82 rows=93444 width=4)
(actual time=2860.088..2860.088 rows=105202 loops=1)"
"                          ->  Index Scan using dok_kuupaev_idx on dok
(cost=0.00..47376.82 rows=93444 width=4) (actual time=0.088..2365.063
rows=105202 loops=1)"
"                                Index Cond: (kuupaev >=
'2008-09-01'::date)"
"        ->  Hash  (cost=6.84..6.84 rows=84 width=19) (actual
time=0.861..0.861 rows=84 loops=1)"
"              ->  Seq Scan on artliik  (cost=0.00..6.84 rows=84 width=19)
(actual time=0.039..0.458 rows=84 loops=1)"
"Total runtime: 29650.696 ms"


"Aggregate  (cost=234278.53..234278.54 rows=1 width=0) (actual
time=11131.392..11131.396 rows=1 loops=1)"
"  ->  Hash Left Join  (cost=52111.20..234218.21 rows=24126 width=0) (actual
time=9179.703..11043.906 rows=20588 loops=1)"
"        Hash Cond: (("outer".grupp = "inner".grupp) AND ("outer".liik =
"inner".liik))"
"        ->  Nested Loop  (cost=52103.94..233735.35 rows=24126 width=19)
(actual time=9178.827..10858.383 rows=20588 loops=1)"
"              ->  Index Scan using toode_pkey on toode  (cost=0.00..6.01
rows=1 width=43) (actual time=10.252..10.264 rows=1 loops=1)"
"                    Index Cond: ('X05'::bpchar = toode)"
"              ->  Hash Join  (cost=52103.94..233488.08 rows=24126 width=24)
(actual time=9168.552..10675.424 rows=20588 loops=1)"
"                    Hash Cond: ("outer".dokumnr = "inner".dokumnr)"
"                    ->  Bitmap Heap Scan on rid  (cost=4127.51..175020.84
rows=317003 width=28) (actual time=2129.814..7152.618 rows=277294 loops=1)"
"                          Recheck Cond: (toode = 'X05'::bpchar)"
"                          ->  Bitmap Index Scan on rid_toode_idx
(cost=0.00..4127.51 rows=317003 width=0) (actual time=2123.223..2123.223
rows=280599 loops=1)"
"                                Index Cond: (toode = 'X05'::bpchar)"
"                    ->  Hash  (cost=47376.82..47376.82 rows=93444 width=4)
(actual time=1414.254..1414.254 rows=105202 loops=1)"
"                          ->  Index Scan using dok_kuupaev_idx on dok
(cost=0.00..47376.82 rows=93444 width=4) (actual time=0.092..895.533
rows=105202 loops=1)"
"                                Index Cond: (kuupaev >=
'2008-09-01'::date)"
"        ->  Hash  (cost=6.84..6.84 rows=84 width=19) (actual
time=0.833..0.833 rows=84 loops=1)"
"              ->  Seq Scan on artliik  (cost=0.00..6.84 rows=84 width=19)
(actual time=0.043..0.465 rows=84 loops=1)"
"Total runtime: 11131.694 ms"


Environment:

3-8 concurrent users

"PostgreSQL 8.1.4 on i686-pc-linux-gnu, compiled by GCC
i686-pc-linux-gnu-gcc (GCC) 3.4.6 (Gentoo 3.4.6-r1, ssp-3.4.5-1.0,
pie-8.7.9)"

# free
             total       used       free     shared    buffers     cached
Mem:       2075828    2008228      67600          0          0    1904552
-/+ buffers/cache:     103676    1972152
Swap:      3911816         76    3911740