Re: Hash join on int takes 8..114 seconds - Mailing list pgsql-performance

Tomas,

> OK, what was the number of unused pointer items in the VACUUM output?

I posted it in this thread:

VACUUM FULL ANALYZE VERBOSE;
...
INFO:  free space map contains 14353 pages in 314 relations
DETAIL:  A total of 20000 page slots are in use (including overhead).
89664 page slots are required to track all free space.
Current limits are:  20000 page slots, 1000 relations, using 182 KB.
NOTICE:  number of page slots needed (89664) exceeds max_fsm_pages (20000)
HINT:  Consider increasing the configuration parameter "max_fsm_pages" to a
value over 89664.

Query returned successfully with no result in 10513335 ms.

> The query performance is still the same as when the tables were bloated?

Seems to be the same.
However I improved yesterday after previous message other queries not to
scan whole
product orders (rid) table.
Now there is only few disk activity after 5-300 seconds which seems not to
affect to those query results. So issue in this thread has been gone away.

Now this query runs using constant time 8 seconds:

explain analyze
SELECT sum(1)
   FROM dok JOIN rid USING (dokumnr)
   JOIN toode USING (toode)
   WHERE rid.toode = 'X05' AND dok.kuupaev>='2008-09-01'
"Aggregate  (cost=182210.77..182210.78 rows=1 width=0) (actual
time=8031.600..8031.604 rows=1 loops=1)"
"  ->  Nested Loop  (cost=74226.74..182149.27 rows=24598 width=0) (actual
time=2602.474..7948.121 rows=21711 loops=1)"
"        ->  Index Scan using toode_pkey on toode  (cost=0.00..6.01 rows=1
width=24) (actual time=0.077..0.089 rows=1 loops=1)"
"              Index Cond: ('X05'::bpchar = toode)"
"        ->  Hash Join  (cost=74226.74..181897.28 rows=24598 width=24)
(actual time=2602.378..7785.315 rows=21711 loops=1)"
"              Hash Cond: ("outer".dokumnr = "inner".dokumnr)"
"              ->  Bitmap Heap Scan on rid  (cost=4084.54..101951.60
rows=270725 width=28) (actual time=1129.925..4686.601 rows=278417 loops=1)"
"                    Recheck Cond: (toode = 'X05'::bpchar)"
"                    ->  Bitmap Index Scan on rid_toode_idx
(cost=0.00..4084.54 rows=270725 width=0) (actual time=1123.202..1123.202
rows=278426 loops=1)"
"                          Index Cond: (toode = 'X05'::bpchar)"
"              ->  Hash  (cost=69419.29..69419.29 rows=112766 width=4)
(actual time=1251.496..1251.496 rows=111088 loops=1)"
"                    ->  Bitmap Heap Scan on dok  (cost=1492.68..69419.29
rows=112766 width=4) (actual time=70.837..776.249 rows=111088 loops=1)"
"                          Recheck Cond: (kuupaev >= '2008-09-01'::date)"
"                          ->  Bitmap Index Scan on dok_kuupaev_idx
(cost=0.00..1492.68 rows=112766 width=0) (actual time=64.177..64.177
rows=111343 loops=1)"
"                                Index Cond: (kuupaev >=
'2008-09-01'::date)"
"Total runtime: 8031.905 ms"


Interestingly using like is 80 times faster:

explain analyze
SELECT sum(1)
   FROM dok JOIN rid USING (dokumnr)
   JOIN toode USING (toode)
   WHERE rid.toode like 'X05' AND dok.kuupaev>='2008-09-01'
"Aggregate  (cost=88178.69..88178.70 rows=1 width=0) (actual
time=115.335..115.339 rows=1 loops=1)"
"  ->  Hash Join  (cost=71136.22..88117.36 rows=24532 width=0) (actual
time=115.322..115.322 rows=0 loops=1)"
"        Hash Cond: ("outer".toode = "inner".toode)"
"        ->  Hash Join  (cost=70163.36..86253.20 rows=24598 width=24)
(actual time=0.046..0.046 rows=0 loops=1)"
"              Hash Cond: ("outer".dokumnr = "inner".dokumnr)"
"              ->  Bitmap Heap Scan on rid  (cost=21.16..6307.52 rows=270725
width=28) (actual time=0.037..0.037 rows=0 loops=1)"
"                    Filter: (toode ~~ 'X05'::text)"
"                    ->  Bitmap Index Scan on rid_toode_pattern_idx
(cost=0.00..21.16 rows=1760 width=0) (actual time=0.028..0.028 rows=0
loops=1)"
"                          Index Cond: (toode ~=~ 'X05'::bpchar)"
"              ->  Hash  (cost=69419.29..69419.29 rows=112766 width=4)
(never executed)"
"                    ->  Bitmap Heap Scan on dok  (cost=1492.68..69419.29
rows=112766 width=4) (never executed)"
"                          Recheck Cond: (kuupaev >= '2008-09-01'::date)"
"                          ->  Bitmap Index Scan on dok_kuupaev_idx
(cost=0.00..1492.68 rows=112766 width=0) (never executed)"
"                                Index Cond: (kuupaev >=
'2008-09-01'::date)"
"        ->  Hash  (cost=853.29..853.29 rows=13429 width=24) (actual
time=114.757..114.757 rows=13412 loops=1)"
"              ->  Seq Scan on toode  (cost=0.00..853.29 rows=13429
width=24) (actual time=0.014..58.319 rows=13412 loops=1)"
"Total runtime: 115.505 ms"

I posted also a test script in other thread which shows also that like is
magitude faster than equality check.

rid.toode = 'X05'

and

rid.toode like 'X05'

are exactly the same conditions, there are indexes for both conditions.

So I do'nt understand why results are so different.

In other sample which I posted in thread "Increasing pattern index query
speed" like is 4 times slower:

SELECT sum(1)
   FROM dok JOIN rid USING (dokumnr)
   JOIN toode USING (toode)
   WHERE rid.toode = '99000010' AND dok.kuupaev BETWEEN '2008-11-21' AND
'2008-11-21'
          AND dok.yksus  LIKE 'ORISSAARE%'

"Aggregate  (cost=43.09..43.10 rows=1 width=0) (actual
time=12674.675..12674.679 rows=1 loops=1)"
"  ->  Nested Loop  (cost=29.57..43.08 rows=1 width=0) (actual
time=2002.045..12673.645 rows=19 loops=1)"
"        ->  Nested Loop  (cost=29.57..37.06 rows=1 width=24) (actual
time=2001.922..12672.344 rows=19 loops=1)"
"              ->  Index Scan using dok_kuupaev_idx on dok  (cost=0.00..3.47
rows=1 width=4) (actual time=342.812..9810.627 rows=319 loops=1)"
"                    Index Cond: ((kuupaev >= '2008-11-21'::date) AND
(kuupaev <= '2008-11-21'::date))"
"                    Filter: (yksus ~~ 'ORISSAARE%'::text)"
"              ->  Bitmap Heap Scan on rid  (cost=29.57..33.58 rows=1
width=28) (actual time=8.948..8.949 rows=0 loops=319)"
"                    Recheck Cond: (("outer".dokumnr = rid.dokumnr) AND
(rid.toode = '99000010'::bpchar))"
"                    ->  BitmapAnd  (cost=29.57..29.57 rows=1 width=0)
(actual time=8.930..8.930 rows=0 loops=319)"
"                          ->  Bitmap Index Scan on rid_dokumnr_idx
(cost=0.00..2.52 rows=149 width=0) (actual time=0.273..0.273 rows=2
loops=319)"
"                                Index Cond: ("outer".dokumnr =
rid.dokumnr)"
"                          ->  Bitmap Index Scan on rid_toode_idx
(cost=0.00..26.79 rows=1941 width=0) (actual time=8.596..8.596 rows=15236
loops=319)"
"                                Index Cond: (toode = '99000010'::bpchar)"
"        ->  Index Scan using toode_pkey on toode  (cost=0.00..6.01 rows=1
width=24) (actual time=0.043..0.048 rows=1 loops=19)"
"              Index Cond: ('99000010'::bpchar = toode)"
"Total runtime: 12675.191 ms"

explain analyze SELECT sum(1)
   FROM dok JOIN rid USING (dokumnr)
   JOIN toode USING (toode)
   WHERE rid.toode like '99000010%' AND dok.kuupaev BETWEEN '2008-11-21' AND
'2008-11-21'
          AND dok.yksus  LIKE 'ORISSAARE%'

"Aggregate  (cost=17.99..18.00 rows=1 width=0) (actual
time=46465.609..46465.613 rows=1 loops=1)"
"  ->  Nested Loop  (cost=0.00..17.98 rows=1 width=0) (actual
time=3033.947..46465.462 rows=19 loops=1)"
"        ->  Nested Loop  (cost=0.00..11.96 rows=1 width=24) (actual
time=3033.890..46464.310 rows=19 loops=1)"
"              Join Filter: ("outer".dokumnr = "inner".dokumnr)"
"              ->  Index Scan using dok_kuupaev_idx on dok  (cost=0.00..5.93
rows=1 width=4) (actual time=0.044..5.419 rows=319 loops=1)"
"                    Index Cond: ((kuupaev >= '2008-11-21'::date) AND
(kuupaev <= '2008-11-21'::date))"
"                    Filter: (yksus ~~ 'ORISSAARE%'::text)"
"              ->  Index Scan using rid_toode_pattern_idx on rid
(cost=0.00..6.01 rows=1 width=28) (actual time=0.025..88.046 rows=15322
loops=319)"
"                    Index Cond: ((toode ~>=~ '99000010'::bpchar) AND (toode
~<~ '99000011'::bpchar))"
"                    Filter: (toode ~~ '99000010%'::text)"
"        ->  Index Scan using toode_pkey on toode  (cost=0.00..6.01 rows=1
width=24) (actual time=0.034..0.039 rows=1 loops=19)"
"              Index Cond: ("outer".toode = toode.toode)"
"Total runtime: 46465.833 ms"


> What are the outputs of iostat/vmstat/dstat/top when running the query?

iostat and dstat are not installed in Gentoo.
For last like query which constantly takes 46 seconds vmstat 5  shows:

procs -----------memory---------- ---swap-- -----io---- --system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in    cs us sy id
wa
 0  0    216 124780      0 1899236    0    0    10    13  277    78  3  1 95
0
 0  0    216 124656      0 1899248    0    0     2     8  267    59  2  0 98
0
 1  0    216 124664      0 1899244    0    0     0     7  266    62  2  0 97
0
 0  0    216 124788      0 1899248    0    0     0     8  273    73  3  1 96
0
 0  0    216 124656      0 1899252    0    0     0     2  265    54  2  0 97
0
 1  0    216 124656      0 1899252    0    0     0    22  268    63 14 39 48
0  <-------- start of query
 1  0    216 124656      0 1899252    0    0     0    62  267    61 25 75  0
0
 1  0    216 124656      0 1899252    0    0     0     2  266    55 28 72  0
0
 1  0    216 124664      0 1899256    0    0     0     5  265    56 26 74  0
0
 1  0    216 124788      0 1899256    0    0     0    10  271    67 25 75  0
0
 1  0    216 124664      0 1899256    0    0     0     3  265    54 25 75  0
0
 1  0    216 124160      0 1899260    0    0     0     1  265    57 28 72  0
0
 1  0    216 125020      0 1899260    0    0     0    21  272    60 28 72  0
0
 1  0    216 124020      0 1899264    0    0     0     0  271    73 29 71  0
0
 0  0    216 124260      0 1899268    0    0     0     3  266    61 19 59 22
0 <------ end of query
 1  0    216 125268      0 1899260    0    0     0     9  268    59  2  0 97
0
 0  0    216 124912      0 1899268    0    0     0     5  270    59  3  0 96
0
 0  0    216 124656      0 1899272    0    0     0     5  267    64  2  0 98
0
 0  0    216 124664      0 1899272    0    0     0     0  263    50  2  0 98
0

top shows single postmaster process activity:

top - 23:07:49 up 27 days,  4:20,  1 user,  load average: 0.25, 0.22, 0.12
Tasks:  50 total,   3 running,  47 sleeping,   0 stopped,   0 zombie
Cpu(s): 29.3% us, 70.7% sy,  0.0% ni,  0.0% id,  0.0% wa,  0.0% hi,  0.0% si
Mem:   2075828k total,  1951604k used,   124224k free,        0k buffers
Swap:  3911816k total,      216k used,  3911600k free,  1899348k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
29687 postgres  25   0  144m 124m 121m R 96.3  6.2   8:18.04 postmaster
 8147 root      16   0  4812 1628 1316 S  1.0  0.1   0:00.03 sshd
 8141 root      15   0  5080 1892 1528 S  0.7  0.1   0:00.02 sshd
 8145 sshd      15   0  4816 1220  912 S  0.3  0.1   0:00.01 sshd
 8151 sshd      15   0  4812 1120  816 S  0.3  0.1   0:00.01 sshd
    1 root      16   0  1480  508  444 S  0.0  0.0   0:01.89 init
    2 root      34  19     0    0    0 S  0.0  0.0   0:00.01 ksoftirqd/0
    3 root      10  -5     0    0    0 S  0.0  0.0   0:00.00 events/0
    4 root      10  -5     0    0    0 S  0.0  0.0   0:00.63 khelper
    5 root      10  -5     0    0    0 S  0.0  0.0   0:00.00 kthread
    7 root      10  -5     0    0    0 S  0.0  0.0   2:21.73 kblockd/0
    8 root      20  -5     0    0    0 S  0.0  0.0   0:00.00 kacpid
  115 root      13  -5     0    0    0 S  0.0  0.0   0:00.00 aio/0
  114 root      15   0     0    0    0 S  0.0  0.0   9:21.41 kswapd0
  116 root      10  -5     0    0    0 S  0.0  0.0   0:12.06 xfslogd/0
  117 root      10  -5     0    0    0 S  0.0  0.0   1:36.43 xfsdatad/0
  706 root      10  -5     0    0    0 S  0.0  0.0   0:00.00 kseriod
  723 root      13  -5     0    0    0 S  0.0  0.0   0:00.00 kpsmoused
  738 root      11  -5     0    0    0 S  0.0  0.0   0:00.00 ata/0
  740 root      11  -5     0    0    0 S  0.0  0.0   0:00.00 scsi_eh_0
  741 root      11  -5     0    0    0 S  0.0  0.0   0:00.00 scsi_eh_1
  742 root      11  -5     0    0    0 S  0.0  0.0   0:00.00 scsi_eh_2
  743 root      11  -5     0    0    0 S  0.0  0.0   0:00.00 scsi_eh_3
  762 root      10  -5     0    0    0 S  0.0  0.0   0:18.64 xfsbufd
  763 root      10  -5     0    0    0 S  0.0  0.0   0:00.79 xfssyncd
  963 root      16  -4  1712  528  336 S  0.0  0.0   0:00.24 udevd
 6677 root      15   0  1728  572  400 S  0.0  0.0   0:10.14 syslog-ng
 7183 root      15   0  3472  828  672 S  0.0  0.0   0:08.50 sshd
 7222 root      16   0  1736  672  556 S  0.0  0.0   0:00.03 cron
 7237 root      16   0  1620  712  608 S  0.0  0.0   0:00.00 agetty
 7238 root      17   0  1616  712  608 S  0.0  0.0   0:00.00 agetty
 7239 root      16   0  1616  712  608 S  0.0  0.0   0:00.00 agetty
 7240 root      16   0  1616  708  608 S  0.0  0.0   0:00.00 agetty
 7241 root      16   0  1616  708  608 S  0.0  0.0   0:00.00 agetty
31873 root      15   0  1616  712  608 S  0.0  0.0   0:00.00 agetty
14908 postgres  16   0  141m  10m 9936 S  0.0  0.5   0:01.44 postmaster
14915 postgres  16   0  8468 1360  896 S  0.0  0.1   0:00.36 postmaster

Andrus.