Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1Zr2UW-0004mk-Rx for pgsql-performance@arkaria.postgresql.org; Tue, 27 Oct 2015 11:32:37 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.84) (envelope-from ) id 1Zr2UW-0006na-9y for pgsql-performance@arkaria.postgresql.org; Tue, 27 Oct 2015 11:32:36 +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) (envelope-from ) id 1Zr2Sq-0004w2-S7 for pgsql-performance@postgresql.org; Tue, 27 Oct 2015 11:30:52 +0000 Received: from newmail.postgrespro.ru ([93.174.131.138] helo=mail.postgrespro.ru) by magus.postgresql.org with esmtp (Exim 4.84) (envelope-from ) id 1Zr2Sj-0006Vv-U4 for pgsql-performance@postgresql.org; Tue, 27 Oct 2015 11:30:52 +0000 Received: from [192.168.27.120] (unknown [192.168.27.1]) by mail.postgrespro.ru (Postfix) with ESMTPSA id 7F52721C3F34; Tue, 27 Oct 2015 14:30:45 +0300 (MSK) Subject: Re: Query planner wants to use seq scan To: Bertrand Paquet References: <562F5B41.7060603@postgrespro.ru> <562F5D66.5010305@postgrespro.ru> Cc: pgsql-performance@postgresql.org From: Alex Ignatov Message-ID: <562F6065.7030204@postgrespro.ru> Date: Tue, 27 Oct 2015 14:30:45 +0300 User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:38.0) Gecko/20100101 Thunderbird/38.3.0 MIME-Version: 1.0 In-Reply-To: Content-Type: multipart/alternative; boundary="------------080802030703080002030906" X-Pg-Spam-Score: -1.9 (-) List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-performance Precedence: bulk Sender: pgsql-performance-owner@postgresql.org This is a multi-part message in MIME format. --------------080802030703080002030906 Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 7bit On 27.10.2015 14:19, Bertrand Paquet wrote: > > relname | n_live_tup | n_dead_tup | > last_vacuum | last_autovacuum | last_analyze > | last_autoanalyze > > ------------------------+------------+------------+-------------------------------+-------------------------------+-------------------------------+------------------------------- > > external_sync_messages | 998105 | 11750 | 2015-10-26 > 20:15:17.484771+00 | 2015-10-02 15:04:25.944479+00 | 2015-10-26 > 20:15:19.465308+00 | 2015-10-22 12:24:26.947616+00 > > (1 row) > > > 2015-10-27 12:17 GMT+01:00 Alex Ignatov >: > > On 27.10.2015 14:10, Bertrand Paquet wrote: >> Yes, I have run VACUUM ANALYZE, no effect. >> >> Bertrand >> >> 2015-10-27 12:08 GMT+01:00 Alex Ignatov > >: >> >> On 27.10.2015 12:35, Bertrand Paquet wrote: >> >> Hi all, >> >> We have a slow query. After analyzing, the planner >> decision seems to be discutable : the query is faster >> when disabling seqscan. See below the two query plan, and >> an extract from pg_stats. >> >> Any idea about what to change to help the planner ? >> >> An information which can be useful : the number on >> distinct value on organization_id is very very low, may >> be the planner does not known that, and take the wrong >> decision. >> >> Regards, >> >> Bertrand >> >> # explain analyze SELECT 1 AS one FROM >> "external_sync_messages" WHERE >> "external_sync_messages"."organization_id" = 1612 AND >> ("external_sync_messages"."status" NOT IN >> ('sent_to_proxy', 'in_progress', 'ok')) AND >> "external_sync_messages"."handled_by" IS NULL LIMIT 1; >> >> QUERY PLAN >> >> -------------------------------------------------------------------------------------------------------------------------------------------- >> >> Limit (cost=0.00..12.39 rows=1 width=0) (actual >> time=232.212..232.213 rows=1 loops=1) >> >> -> Seq Scan on external_sync_messages >> (cost=0.00..79104.69 rows=6385 width=0) (actual >> time=232.209..232.209 rows=1 loops=1) >> >> Filter: ((handled_by IS NULL) AND >> (organization_id = 1612) AND ((status)::text <> ALL >> ('{sent_to_proxy,in_progress,ok}'::text[]))) >> >> Rows Removed by Filter: 600140 >> >> Planning time: 0.490 ms >> >> Execution time: 232.246 ms >> >> (6 rows) >> >> # set enable_seqscan = off; >> >> SET >> >> # explain analyze SELECT 1 AS one FROM >> "external_sync_messages" WHERE >> "external_sync_messages"."organization_id" = 1612 AND >> ("external_sync_messages"."status" NOT IN >> ('sent_to_proxy', 'in_progress', 'ok')) AND >> "external_sync_messages"."handled_by" IS NULL LIMIT 1; >> >> QUERY PLAN >> >> -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- >> >> Limit (cost=0.42..39.88 rows=1 width=0) (actual >> time=0.030..0.030 rows=1 loops=1) >> >> -> Index Scan using >> index_external_sync_messages_on_organization_id on >> external_sync_messages (cost=0.42..251934.05 rows=6385 >> width=0) (actual time=0.028..0.028 rows=1 loops=1) >> >> Index Cond: (organization_id = 1612) >> >> Filter: ((handled_by IS NULL) AND >> ((status)::text <> ALL >> ('{sent_to_proxy,in_progress,ok}'::text[]))) >> >> Planning time: 0.103 ms >> >> Execution time: 0.052 ms >> >> (6 rows) >> >> # SELECT attname, inherited, n_distinct, >> array_to_string(most_common_vals, E'\n') as >> most_common_vals FROM pg_stats WHERE tablename = >> 'external_sync_messages' and attname IN ('status', >> 'organization_id', 'handled_by'); >> >> attname | inherited | n_distinct | most_common_vals >> >> -----------------+-----------+------------+------------------ >> >> handled_by | f | 3 | 3 + >> >> | | | 236140 + >> >> | | | 54413 >> >> organization_id | f | 22 | 1612 + >> >> | | | 287 + >> >> | | | 967 + >> >> | | | 1223 + >> >> | | | 1123 + >> >> | | | 1930 + >> >> | | | 841 + >> >> | | | 1814 + >> >> | | | 711 + >> >> | | | 1513 + >> >> | | | 1794 + >> >> | | | 1246 + >> >> | | | 1673 + >> >> | | | 1552 + >> >> | | | 1747 + >> >> | | | 2611 + >> >> | | | 2217 + >> >> | | | 2448 + >> >> | | | 2133 + >> >> | | | 1861 + >> >> | | | 2616 + >> >> | | | 2796 >> >> status | f | 6 | ok + >> >> | | | ignored + >> >> | | | channel_error + >> >> | | | in_progress + >> >> | | | error + >> >> | | | sent_to_proxy >> >> (3 rows) >> >> # select count(*) from external_sync_messages; >> >> count >> >> -------- >> >> 992912 >> >> (1 row) >> >> >> Hello, Bertrand! >> May be statistics on external_sync_messages is wrong? i.e >> planner give us rows=6385 but seq scan give us Rows Removed >> by Filter: 600140 >> Maybe you should recalc it by VACUUM ANALYZE it? >> >> -- >> Alex Ignatov >> Postgres Professional: http://www.postgrespro.com >> The Russian Postgres Company >> >> > What is the result of > select relname,n_live_tup,n_dead_tup, last_vacuum, > last_autovacuum, last_analyze, last_autoanalyze from > pg_stat_user_tables where relname='external_sync_messages' ? > > -- > Alex Ignatov > Postgres Professional:http://www.postgrespro.com > The Russian Postgres Company > > What is yours random_page_cost parameter in postgres config? -- Alex Ignatov Postgres Professional: http://www.postgrespro.com The Russian Postgres Company --------------080802030703080002030906 Content-Type: text/html; charset=utf-8 Content-Transfer-Encoding: 8bit

On 27.10.2015 14:19, Bertrand Paquet wrote:

        relname         | n_live_tup | n_dead_tup |          last_vacuum          |        last_autovacuum        |         last_analyze          |       last_autoanalyze        

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

 external_sync_messages |     998105 |      11750 | 2015-10-26 20:15:17.484771+00 | 2015-10-02 15:04:25.944479+00 | 2015-10-26 20:15:19.465308+00 | 2015-10-22 12:24:26.947616+00

(1 row)


2015-10-27 12:17 GMT+01:00 Alex Ignatov <a.ignatov@postgrespro.ru>:
On 27.10.2015 14:10, Bertrand Paquet wrote:
Yes, I have run VACUUM ANALYZE, no effect.

Bertrand

2015-10-27 12:08 GMT+01:00 Alex Ignatov <a.ignatov@postgrespro.ru>:
On 27.10.2015 12:35, Bertrand Paquet wrote:
Hi all,

We have a slow query. After analyzing, the planner decision seems to be discutable : the query is faster when disabling seqscan. See below the two query plan, and an extract from pg_stats.

Any idea about what to change to help the planner ?

An information which can be useful : the number on distinct value on organization_id is very very low, may be the planner does not known that, and take the wrong decision.

Regards,

Bertrand

# explain analyze SELECT  1 AS one FROM "external_sync_messages"  WHERE "external_sync_messages"."organization_id" = 1612 AND ("external_sync_messages"."status" NOT IN ('sent_to_proxy', 'in_progress', 'ok')) AND "external_sync_messages"."handled_by" IS NULL LIMIT 1;

                              QUERY PLAN

--------------------------------------------------------------------------------------------------------------------------------------------

 Limit  (cost=0.00..12.39 rows=1 width=0) (actual time=232.212..232.213 rows=1 loops=1)

   ->  Seq Scan on external_sync_messages  (cost=0.00..79104.69 rows=6385 width=0) (actual time=232.209..232.209 rows=1 loops=1)

         Filter: ((handled_by IS NULL) AND (organization_id = 1612) AND ((status)::text <> ALL ('{sent_to_proxy,in_progress,ok}'::text[])))

         Rows Removed by Filter: 600140

 Planning time: 0.490 ms

 Execution time: 232.246 ms

(6 rows)

# set enable_seqscan = off;

SET

# explain analyze SELECT  1 AS one FROM "external_sync_messages"  WHERE "external_sync_messages"."organization_id" = 1612 AND ("external_sync_messages"."status" NOT IN ('sent_to_proxy', 'in_progress', 'ok')) AND "external_sync_messages"."handled_by" IS NULL LIMIT 1;

                                                    QUERY PLAN

--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

 Limit  (cost=0.42..39.88 rows=1 width=0) (actual time=0.030..0.030 rows=1 loops=1)

   ->  Index Scan using index_external_sync_messages_on_organization_id on external_sync_messages  (cost=0.42..251934.05 rows=6385 width=0) (actual time=0.028..0.028 rows=1 loops=1)

         Index Cond: (organization_id = 1612)

         Filter: ((handled_by IS NULL) AND ((status)::text <> ALL ('{sent_to_proxy,in_progress,ok}'::text[])))

 Planning time: 0.103 ms

 Execution time: 0.052 ms

(6 rows)

# SELECT attname, inherited, n_distinct, array_to_string(most_common_vals, E'\n') as most_common_vals FROM pg_stats WHERE tablename = 'external_sync_messages' and attname IN ('status', 'organization_id', 'handled_by');

     attname     | inherited | n_distinct | most_common_vals

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

 handled_by      | f         |       3 | 3               +

                 |           |         | 236140          +

                 |           |         | 54413

 organization_id | f         |     22 | 1612            +

                 |           |         | 287             +

                 |           |         | 967             +

                 |           |         | 1223            +

                 |           |         | 1123            +

                 |           |         | 1930            +

                 |           |         | 841             +

                 |           |         | 1814            +

                 |           |         | 711             +

                 |           |         | 1513            +

                 |           |         | 1794            +

                 |           |         | 1246            +

                 |           |         | 1673            +

                 |           |         | 1552            +

                 |           |         | 1747            +

                 |           |         | 2611            +

                 |           |         | 2217            +

                 |           |         | 2448            +

                 |           |         | 2133            +

                 |           |         | 1861            +

                 |           |         | 2616            +

                 |           |         | 2796

 status          | f         |       6 | ok              +

                 |           |         | ignored         +

                 |           |         | channel_error   +

                 |           |         | in_progress     +

                 |           |         | error           +

                 |           |         | sent_to_proxy

(3 rows)

# select count(*) from external_sync_messages;

 count

--------

 992912

(1 row)


Hello, Bertrand!
May be statistics on external_sync_messages is wrong? i.e planner give us rows=6385 but seq scan give us Rows Removed by Filter: 600140
Maybe you should recalc it by VACUUM ANALYZE it?

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


What is the result of
select relname,n_live_tup,n_dead_tup, last_vacuum, last_autovacuum, last_analyze, last_autoanalyze from pg_stat_user_tables where relname='external_sync_messages' ?

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

What is yours random_page_cost  parameter in postgres config?
-- 
Alex Ignatov
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company
--------------080802030703080002030906--