Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1eHWGK-0007jS-4b for pgsql-performance@arkaria.postgresql.org; Wed, 22 Nov 2017 14:44:29 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1eHWGJ-0005cR-NK for pgsql-performance@arkaria.postgresql.org; Wed, 22 Nov 2017 14:44:27 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1eHWGJ-0005cH-8M for pgsql-performance@lists.postgresql.org; Wed, 22 Nov 2017 14:44:27 +0000 Received: from mail.postgrespro.ru ([93.174.131.138]) by magus.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1eHWGA-000599-U6 for pgsql-performance@postgresql.org; Wed, 22 Nov 2017 14:44:26 +0000 Received: from localhost (localhost [127.0.0.1]) by mail.postgrespro.ru (Postfix) with ESMTP id 5909321C176B; Wed, 22 Nov 2017 17:44:17 +0300 (MSK) X-Virus-Scanned: Debian amavisd-new at postgrespro.ru Received: from inferno (unknown [192.168.27.1]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mail.postgrespro.ru (Postfix) with ESMTPSA id ECABE21C1756; Wed, 22 Nov 2017 17:44:16 +0300 (MSK) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=postgrespro.ru; s=mail; t=1511361857; bh=j12kc+F/r2gJVhjCOvaU4E5AsEXSwg7dVV9MbgytuXM=; h=From:To:Cc:References:In-Reply-To:Subject:Date; b=fq9jGJro6nH/DkjuJb7FKNrVSDt/AWpgTf/jDSzEl9msexp5CVLbfGLh60o7QfNZA eNbgaPoJa8kWI4PqSyOGfBats0oEDP7qPSv9byCBeQe5fdj5D9buUBe3Zyjx7KxI+q OkHy+mN0TBFGC13RmiiZAz+GK2hIFYdzNu8D/nw8= From: "Alex Ignatov" To: "'Dmitry Shalashov'" Cc: References: <1379201d3639d$8b61bcd0$a2253670$@postgrespro.ru> In-Reply-To: Subject: RE: Query became very slow after 9.6 -> 10 upgrade Date: Wed, 22 Nov 2017 17:44:18 +0300 Message-ID: <137da01d363a0$603cc970$20b65c50$@postgrespro.ru> MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----=_NextPart_000_137DB_01D363B9.858B39F0" X-Mailer: Microsoft Outlook 16.0 Thread-Index: AQJHb1HcTOXyxzMxs6YDVgBR4dXi9QB+4RitAZ3p29WiJ3pT4A== Content-Language: ru List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk This is a multipart message in MIME format. ------=_NextPart_000_137DB_01D363B9.858B39F0 Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: quoted-printable Here is my select right after initdb: =20 postgres=3D# select name,setting from pg_settings where name like = '%_cost'; name | setting ----------------------+--------- cpu_index_tuple_cost | 0.005 cpu_operator_cost | 0.0025 cpu_tuple_cost | 0.01 parallel_setup_cost | 1000 parallel_tuple_cost | 0.1 random_page_cost | 4 seq_page_cost | 1 =20 =20 Can you generate plan with random_page_cost =3D 4? =20 =20 -- Alex Ignatov=20 Postgres Professional: = http://www.postgrespro.com=20 The Russian Postgres Company =20 From: Dmitry Shalashov [mailto:skaurus@gmail.com]=20 Sent: Wednesday, November 22, 2017 5:29 PM To: Alex Ignatov Cc: pgsql-performance@postgresql.org Subject: Re: Query became very slow after 9.6 -> 10 upgrade =20 Sure, here it goes: =20 name | setting ----------------------+--------- cpu_index_tuple_cost | 0.005 cpu_operator_cost | 0.0025 cpu_tuple_cost | 0.01 parallel_setup_cost | 1000 parallel_tuple_cost | 0.1 random_page_cost | 1 seq_page_cost | 1 =20 Dmitry Shalashov, relap.io & = surfingbird.ru =20 2017-11-22 17:24 GMT+03:00 Alex Ignatov >: Hello! What about : select name,setting from pg_settings where name like '%_cost'; =20 -- Alex Ignatov=20 Postgres Professional: = http://www.postgrespro.com=20 The Russian Postgres Company =20 =20 From: Dmitry Shalashov [mailto:skaurus@gmail.com = ]=20 Sent: Wednesday, November 22, 2017 5:14 PM To: pgsql-performance@postgresql.org = =20 Subject: Query became very slow after 9.6 -> 10 upgrade =20 Hi! =20 I've seen few letters like this on mailing list and for some reason = thought that probably it won't happen to us, but here I am lol. =20 It's "nestloop hits again" situation. =20 I'll try to provide plan from 9.6 later, but right now I have only plan = from 10.1. =20 Query: https://pastebin.com/9b953tT7 It was running under 3 seconds (it's our default timeout) and now it = runs for 12 minutes. =20 \d adroom: https://pastebin.com/vBrPGtxT (3800 rows) \d adroom_stat: https://pastebin.com/CkBArCC9 (47mln rows, 1.5mln = satisfy condition on day column) \d domains: https://pastebin.com/65hk7YCm (73000 rows) =20 All three tables are analyzed. =20 EXPLAIN ANALYZE: https://pastebin.com/PenHEgf0 EXPLAIN ANALYZE with nestloop off: https://pastebin.com/zX35CPCV (0.8s) =20 Regarding server parameters - it's a mighty beast with 2x E5-2630 v3, = 192Gb of RAM and two very, very fast NVME server class SSD's in RAID1. =20 What can I do with it? =20 =20 Also maybe this will be useful: =20 1st query, runs under 1ms select title, id, groups->0->>'provider' provider, domain_ids from = adroom where groups->0->>'provider' ~ '^target_mail_ru' and not = is_paused and current_timestamp between start_ts and stop_ts =20 2nd query that uses 1st one, runs under 3 ms select distinct unnest(domain_ids) FROM (select title, id, = groups->0->>'provider' provider, domain_ids from adroom where = groups->0->>'provider' ~ '^target_mail_ru' and not is_paused and = current_timestamp between start_ts and stop_ts) t1 =20 3rd query which returns 1.5mln rows, runs in about 0.6s SELECT adroom_id, domain_id, shows, clicks FROM adroom_stat WHERE day = between date_trunc('day', current_timestamp - interval '1 week') and = date_trunc('day', current_timestamp) =20 BUT if I'll add to 3rd query one additional condition, which is = basically 2nd query, it will ran same 12 minutes: SELECT adroom_id, domain_id, shows, clicks FROM adroom_stat WHERE day = between date_trunc('day', current_timestamp - interval '1 week') and = date_trunc('day', current_timestamp) AND domain_id IN (select distinct = unnest(domain_ids) FROM (select title, id, groups->0->>'provider' = provider, domain_ids from adroom where groups->0->>'provider' ~ = '^target_mail_ru' and not is_paused and current_timestamp between = start_ts and stop_ts) t1) =20 Plan of last query: Nested Loop (cost=3D88.63..25617.31 rows=3D491 width=3D16) (actual = time=3D3.512..733248.271 rows=3D1442797 loops=3D1) -> HashAggregate (cost=3D88.06..88.07 rows=3D1 width=3D4) (actual = time=3D3.380..13.561 rows=3D3043 loops=3D1) Group Key: (unnest(adroom.domain_ids)) -> HashAggregate (cost=3D88.03..88.04 rows=3D1 width=3D4) = (actual time=3D2.199..2.607 rows=3D3043 loops=3D1) Group Key: unnest(adroom.domain_ids) -> ProjectSet (cost=3D0.28..87.78 rows=3D100 width=3D4) = (actual time=3D0.701..1.339 rows=3D3173 loops=3D1) -> Index Scan using adroom_active_idx on adroom = (cost=3D0.28..87.27 rows=3D1 width=3D167) (actual time=3D0.688..1.040 = rows=3D4 loops=3D1) Index Cond: ((CURRENT_TIMESTAMP >=3D = start_ts) AND (CURRENT_TIMESTAMP <=3D stop_ts)) Filter: (((groups -> 0) ->> 'provider'::text) = ~ '^target_mail_ru'::text) Rows Removed by Filter: 41 -> Index Scan using = adroom_stat_day_adroom_id_domain_id_url_id_is_wlabp_idx on adroom_stat = (cost=3D0.58..25524.33 rows=3D491 width=3D16) (actual = time=3D104.847..240.846 rows=3D474 loops=3D3043) Index Cond: ((day >=3D date_trunc('day'::text, = (CURRENT_TIMESTAMP - '7 days'::interval))) AND (day <=3D = date_trunc('day'::text, CURRENT_TIMESTAMP)) AND (domain_id =3D = (unnest(adroom.domain_ids)))) Planning time: 1.580 ms Execution time: 733331.740 ms =20 Dmitry Shalashov, relap.io & = surfingbird.ru =20 ------=_NextPart_000_137DB_01D363B9.858B39F0 Content-Type: text/html; charset="utf-8" Content-Transfer-Encoding: quoted-printable

Here is my = select right after initdb:

 

postgres=3D# = select name,setting from pg_settings where name like = '%_cost';

=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 = name=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 | = setting

----------------------+---------

cpu_index_tuple_cost | 0.005

cpu_operator_cost=C2=A0=C2=A0=C2=A0 | = 0.0025

= cpu_tuple_cost=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 | = 0.01

parallel_setup_cost=C2=A0 | = 1000

parallel_tuple_cost=C2=A0 | = 0.1

= random_page_cost=C2=A0=C2=A0=C2=A0=C2=A0 | 4

= seq_page_cost=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0 | = 1

 

 

Can you = generate plan with random_page_cost=C2=A0=C2=A0=C2=A0=C2=A0 =3D = 4?

 

 

--

Alex Ignatov =
Postgres Professional: http://www.postgrespro.com
The = Russian Postgres Company

 

From: = Dmitry Shalashov [mailto:skaurus@gmail.com]
Sent: Wednesday, = November 22, 2017 5:29 PM
To: Alex Ignatov = <a.ignatov@postgrespro.ru>
Cc: = pgsql-performance@postgresql.org
Subject: Re: Query became = very slow after 9.6 -> 10 upgrade

 

Sure, = here it goes:

 

         name    =      | setting

----------------------+---------

 cpu_index_tuple_cost | = 0.005

 cpu_operator_cost    | = 0.0025

 cpu_tuple_cost       | = 0.01

 parallel_setup_cost  | = 1000

 parallel_tuple_cost  | = 0.1

 random_page_cost     | = 1

 seq_page_cost        | = 1


 

Dmitry = Shalashov, relap.io & surfingbird.ru

<= /div>

 

2017-11-22 17:24 GMT+03:00 Alex Ignatov <a.ignatov@postgrespro.ru>:

Hello!<= /o:p>

What about = :

select = name,setting from pg_settings where name like '%_cost';

 <= /o:p>

--

Alex = Ignatov
Postgres Professional: http://www.postgrespro.com
The = Russian Postgres Company

 <= /o:p>

 <= /o:p>

From:= Dmitry Shalashov [mailto:skaurus@gmail.com]
Sent: Wednesday, = November 22, 2017 5:14 PM
To: pgsql-performance@postgresql.org
Subject:= Query became very slow after 9.6 -> 10 = upgrade

 <= /o:p>

Hi!

 <= /o:p>

I've seen = few letters like this on mailing list and for some reason thought that = probably it won't happen to us, but here I am = lol.

 <= /o:p>

It's = "nestloop hits again" situation.

 <= /o:p>

I'll try to = provide plan from 9.6 later, but right now I have only plan from = 10.1.

 <= /o:p>

<= div>

It was = running under 3 seconds (it's our default timeout) and now it runs for = 12 minutes.

 <= /o:p>

\d = adroom: https://pastebin.com/vBrPGtxT (3800 = rows)

\d = adroom_stat: https://pastebin.com/CkBArCC9 (47mln rows, 1.5mln = satisfy condition on day column)

\d = domains: https://pastebin.com/65hk7YCm (73000 = rows)

 <= /o:p>

All three = tables are analyzed.

 <= /o:p>

EXPLAIN = ANALYZE: https://pastebin.com/PenHEgf0

<= div>

EXPLAIN = ANALYZE with nestloop off: https://pastebin.com/zX35CPCV = (0.8s)

 <= /o:p>

Regarding = server parameters - it's a mighty beast with 2x E5-2630 v3, 192Gb = of RAM and two very, very fast NVME server class SSD's in = RAID1.

 <= /o:p>

What can I = do with it?

 <= /o:p>

 <= /o:p>

Also maybe = this will be useful:

 <= /o:p>

1st query, = runs under 1ms

select = title, id, groups->0->>'provider' provider, domain_ids from = adroom where groups->0->>'provider' ~ '^target_mail_ru' and not = is_paused and current_timestamp between start_ts and = stop_ts

 <= /o:p>

2nd query = that uses 1st one, runs under 3 ms

select = distinct unnest(domain_ids) FROM (select title, id, = groups->0->>'provider' provider, domain_ids from adroom where = groups->0->>'provider' ~ '^target_mail_ru' and not is_paused = and current_timestamp between start_ts and stop_ts) = t1

 <= /o:p>

3rd query = which returns 1.5mln rows, runs in about = 0.6s

SELECT = adroom_id, domain_id, shows, clicks FROM adroom_stat WHERE day between = date_trunc('day', current_timestamp - interval '1 week') and = date_trunc('day', current_timestamp)

 <= /o:p>

BUT if I'll = add to 3rd query one additional condition, which is basically 2nd query, = it will ran same 12 minutes:

SELECT = adroom_id, domain_id, shows, clicks FROM adroom_stat WHERE day between = date_trunc('day', current_timestamp - interval '1 week') and = date_trunc('day', current_timestamp) AND domain_id IN (select distinct = unnest(domain_ids) FROM (select title, id, = groups->0->>'provider' provider, domain_ids from adroom where = groups->0->>'provider' ~ '^target_mail_ru' and not is_paused = and current_timestamp between start_ts and stop_ts) = t1)

 <= /o:p>

Plan of = last query:

 Nested= Loop  (cost=3D88.63..25617.31 rows=3D491 width=3D16) (actual = time=3D3.512..733248.271 rows=3D1442797 = loops=3D1)

  =  ->  HashAggregate  (cost=3D88.06..88.07 rows=3D1 = width=3D4) (actual time=3D3.380..13.561 rows=3D3043 = loops=3D1)

  =        Group Key: = (unnest(adroom.domain_ids))

  =        ->  HashAggregate  = (cost=3D88.03..88.04 rows=3D1 width=3D4) (actual time=3D2.199..2.607 = rows=3D3043 loops=3D1)

  =              Group Key: = unnest(adroom.domain_ids)

  =              ->  = ProjectSet  (cost=3D0.28..87.78 rows=3D100 width=3D4) (actual = time=3D0.701..1.339 rows=3D3173 loops=3D1)

  =                   =  ->  Index Scan using adroom_active_idx on adroom  = (cost=3D0.28..87.27 rows=3D1 width=3D167) (actual time=3D0.688..1.040 = rows=3D4 loops=3D1)

  =                     =      Index Cond: ((CURRENT_TIMESTAMP >=3D start_ts) = AND (CURRENT_TIMESTAMP <=3D stop_ts))

  =                     =      Filter: (((groups -> 0) ->> = 'provider'::text) ~ '^target_mail_ru'::text)

  =                     =      Rows Removed by Filter: = 41

  =  ->  Index Scan using = adroom_stat_day_adroom_id_domain_id_url_id_is_wlabp_idx on = adroom_stat  (cost=3D0.58..25524.33 rows=3D491 width=3D16) (actual = time=3D104.847..240.846 rows=3D474 = loops=3D3043)

  =        Index Cond: ((day >=3D = date_trunc('day'::text, (CURRENT_TIMESTAMP - '7 days'::interval))) AND = (day <=3D date_trunc('day'::text, CURRENT_TIMESTAMP)) AND (domain_id = =3D (unnest(adroom.domain_ids))))

 Planni= ng time: 1.580 ms

 Execut= ion time: 733331.740 ms

 <= /o:p>

Dmitry = Shalashov, relap.io & surfingbird.ru

<= /div>
<= /div>

 

------=_NextPart_000_137DB_01D363B9.858B39F0--