Re: Hash join on int takes 8..114 seconds

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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.


--
Sent via pgsql-performance mailing list (pgsql-performance@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance

[Postgresql General]     [Postgresql PHP]     [PHP Users]     [PHP Home]     [PHP on Windows]     [Kernel Newbies]     [PHP Classes]     [PHP Books]     [PHP Databases]     [Yosemite]

  Powered by Linux