Thread: [GENERAL] Queries are taking way longer in 9.6 than 9.5

On 01/17/2017 11:31 AM, Ravi Tammineni wrote:
> Hi,
>
>
>
> We have recently upgraded to 9.6 and few queries are performing very
> poorly. Query execution time has increased more 4 or 5 times in 9.6.
> Qeruy execution plan is also completely changed. I am not sure whether
> its because of Parallel feature or any bug in 9.6. There are few similar
> kind of queries and all of them are taking more time in 9.6.

How did you upgrade from 9.5 --> 9.6?

Did you run ANALYZE on the tables after the upgrade?

Tend to doubt parallel query is at issue here, as it is turned off by
default:

https://www.postgresql.org/docs/9.6/static/runtime-config-resource.html#GUC-MAX-PARALLEL-WORKERS-PER-GATHER

For more info:

https://www.postgresql.org/docs/9.6/static/parallel-query.html
>
>
>
> Following query is taking 70ms in 9.5 and the same query is taking 2
> minutes in 9.6. Execution plan is totally different in 9.6 and seems
> like there is a major flaw while generating the execution plan. Instead
> of filtering the low cardinality, its filtering from biggest table.
> Somehow nested loop joins are screwed up.
>
>
>
>
>
> I really appreciate your help.
>
>
>
> explain analyze
>
> SELECT count(*)
>
> FROM
>
>     tblCnPatientOrderMap po
>
>     JOIN tblPuOrderStatus os ON po.vip_order_id = os.vip_order_id
>
>     JOIN tblPuOrderStatusHistory osh ON os.order_status_history_id =
> osh.order_status_history_id
>
> WHERE
>
>     exists(SELECT 1
>
>            FROM
>
>                tblCnDoctorPatientMap d
>
>            WHERE d.vip_patient_id = po.vip_patient_id
>
>                  AND exists(SELECT 1
>
>                             FROM
>
>                                 tblCnAccounts a
>
>                             WHERE a.master_user_id = d.master_user_id AND
>
>                                   a.user_name = 'dddddd'))
>
>     AND osh.vip_order_type IN (17)--assist
>
>     --AND osh.tx_submit_date IS NOT NULL
>
>     AND osh.cancelled_date IS NULL
>
>     AND osh.cc_accept_date IS NOT NULL;
>
>
>
>
>
> ##########################  9.5 Execution plan
>
>
>
>
> QUERY PLAN
>
>
-----------------------------------------------------------------------------------------------------------------------------------------------------
>
> Aggregate  (cost=1177.25..1177.26 rows=1 width=0)
>
>    ->  Nested Loop  (cost=67.83..1177.25 rows=5 width=0)
>
>          ->  Nested Loop  (cost=67.71..254.81 rows=1322 width=4)
>
>                ->  Nested Loop  (cost=67.63..104.45 rows=1322 width=4)
>
>                      ->  HashAggregate  (cost=67.54..68.12 rows=192 width=4)
>
>                            Group Key: d.vip_patient_id
>
>
>
>                            ->  Nested Loop  (cost=0.17..67.44 rows=192
> width=4)
>
>                                  ->  Index Scan using unq_user_name on
> tblcnaccounts a  (cost=0.08..4.09 rows=1 width=4)
>
>                                        Index Cond: ((user_name)::text =
> 'dddddd'::text)
>
>
>
>                                  ->  Index Only Scan using
> idx_tblcndoctorpatientmap on tblcndoctorpatientmap d  (cost=0.09..62.78
> rows=192 width=8)
>
>                                        Index Cond: (master_user_id =
> a.master_user_id)
>
>                      ->  Index Scan using idx_tblcnpatientordermap on
> tblcnpatientordermap po  (cost=0.09..0.17 rows=7 width=8)
>
>                            Index Cond: (vip_patient_id = d.vip_patient_id)
>
>                ->  Index Scan using tblpuorderstatus_pkey on
> tblpuorderstatus os  (cost=0.09..0.11 rows=1 width=8)
>
>                      Index Cond: (vip_order_id = po.vip_order_id)
>
>          ->  Index Scan using tblpuorderstatushistory_pkey on
> tblpuorderstatushistory osh  (cost=0.11..0.69 rows=1 width=4)
>
>                Index Cond: (order_status_history_id =
> os.order_status_history_id)
>
>                Filter: ((cancelled_date IS NULL) AND (cc_accept_date IS
> NOT NULL) AND (vip_order_type = 17))
>
>
>
>
#####################################################################################################################################
>
>
>
> ##########################  9.6 Execution plan
>
>                                                              QUERY PLAN
>
>
-------------------------------------------------------------------------------------------------------------------------------------
>
> Aggregate  (cost=3185034.17..3185034.17 rows=1 width=8)
>
>    ->  Nested Loop Semi Join  (cost=3012833.92..3185010.91 rows=46511
> width=0)
>
>
>
>          ->  Nested Loop  (cost=3012833.75..3137291.51 rows=46511 width=4)
>
>
>
>                ->  Hash Join  (cost=3012833.67..3117860.77 rows=46511
> width=4)
>
>                      Hash Cond: (os.order_status_history_id =
> osh.order_status_history_id)
>
>
>
>                      ->  Seq Scan on tblpuorderstatus os
> (cost=0.00..96498.46 rows=11185486 width=8)
>
>                      ->  Hash  (cost=3010979.77..3010979.77 rows=529686
> width=4)
>
>                            ->  Gather  (cost=1000.00..3010979.77
> rows=529686 width=4)
>
>                                  Workers Planned: 2
>
>                                  ->  Parallel Seq Scan on
> tblpuorderstatushistory osh  (cost=0.00..2957011.17 rows=220702 width=4)
>
>
>
>                                        Filter: ((cancelled_date IS NULL)
> AND (cc_accept_date IS NOT NULL) AND (vip_order_type = 17))
>
>
>
>                ->  Index Scan using tblcnpatientordermap_pkey on
> tblcnpatientordermap po  (cost=0.09..0.41 rows=1 width=8)
>
>
>
>                      Index Cond: (vip_order_id = os.vip_order_id)
>
>
>
>          ->  Nested Loop Semi Join  (cost=0.17..1.02 rows=1 width=4)
>
>                ->  Index Scan using tblcndoctorpatientmap_pkey on
> tblcndoctorpatientmap d  (cost=0.09..0.39 rows=1 width=8)
>
>                      Index Cond: (vip_patient_id = po.vip_patient_id)
>
>                ->  Index Scan using tblcnaccounts_pkey on tblcnaccounts
> a  (cost=0.08..0.36 rows=1 width=4)
>
>                      Index Cond: (master_user_id = d.master_user_id)
>
>                      Filter: ((user_name)::text = 'dddddd'::text)
>
> (19 rows)
>
>
>
>
>
> Regards,
>
> ravi
>


--
Adrian Klaver
adrian.klaver@aklaver.com

Hi Adrain,

We have deployed our databases in Heroku and we have followed the upgrade option that they have provided to us. Here is
thecommand. 

heroku pg:upgrade --app <app_name>

I am not sure whether they are doing the vacuum after the upgrade or not. I have disabled the parallel execution; still
executionplan is not correct. 

                                                          QUERY PLAN

-------------------------------------------------------------------------------------------------------------------------------
Aggregate  (cost=3391172.70..3391172.71 rows=1 width=8)
   ->  Nested Loop Semi Join  (cost=3218963.06..3391149.45 rows=46513 width=0)
         ->  Nested Loop  (cost=3218962.89..3343428.74 rows=46513 width=4)
               ->  Hash Join  (cost=3218962.80..3323993.25 rows=46513 width=4)
                     Hash Cond: (os.order_status_history_id = osh.order_status_history_id)
                     ->  Seq Scan on tblpuorderstatus os  (cost=0.00..96501.53 rows=11185842 width=8)
                     ->  Hash  (cost=3217108.89..3217108.89 rows=529689 width=4)
                           ->  Seq Scan on tblpuorderstatushistory osh  (cost=0.00..3217108.89 rows=529689 width=4)
                                 Filter: ((cancelled_date IS NULL) AND (cc_accept_date IS NOT NULL) AND (vip_order_type
=17)) 
               ->  Index Scan using tblcnpatientordermap_pkey on tblcnpatientordermap po  (cost=0.09..0.41 rows=1
width=8)
                     Index Cond: (vip_order_id = os.vip_order_id)
         ->  Nested Loop Semi Join  (cost=0.17..1.02 rows=1 width=4)
               ->  Index Scan using tblcndoctorpatientmap_pkey on tblcndoctorpatientmap d  (cost=0.09..0.39 rows=1
width=8)
                     Index Cond: (vip_patient_id = po.vip_patient_id)
               ->  Index Scan using tblcnaccounts_pkey on tblcnaccounts a  (cost=0.08..0.36 rows=1 width=4)
                     Index Cond: (master_user_id = d.master_user_id)
                     Filter: ((user_name)::text = 'rdoyleda'::text)
(17 rows)

Thanks
ravi



-----Original Message-----
From: Adrian Klaver [mailto:adrian.klaver@aklaver.com]
Sent: Tuesday, January 17, 2017 11:42 AM
To: Ravi Tammineni <rtammineni@partner.aligntech.com>; pgsql-admin@postgresql.org; pgsql-general@postgresql.org;
pgadmin-support@postgresql.org
Subject: Re: [GENERAL] Queries are taking way longer in 9.6 than 9.5

On 01/17/2017 11:31 AM, Ravi Tammineni wrote:
> Hi,
>
>
>
> We have recently upgraded to 9.6 and few queries are performing very
> poorly. Query execution time has increased more 4 or 5 times in 9.6.
> Qeruy execution plan is also completely changed. I am not sure whether
> its because of Parallel feature or any bug in 9.6. There are few
> similar kind of queries and all of them are taking more time in 9.6.

How did you upgrade from 9.5 --> 9.6?

Did you run ANALYZE on the tables after the upgrade?

Tend to doubt parallel query is at issue here, as it is turned off by
default:

https://www.postgresql.org/docs/9.6/static/runtime-config-resource.html#GUC-MAX-PARALLEL-WORKERS-PER-GATHER

For more info:

https://www.postgresql.org/docs/9.6/static/parallel-query.html
>
>
>
> Following query is taking 70ms in 9.5 and the same query is taking 2
> minutes in 9.6. Execution plan is totally different in 9.6 and seems
> like there is a major flaw while generating the execution plan.
> Instead of filtering the low cardinality, its filtering from biggest table.
> Somehow nested loop joins are screwed up.
>
>
>
>
>
> I really appreciate your help.
>
>
>
> explain analyze
>
> SELECT count(*)
>
> FROM
>
>     tblCnPatientOrderMap po
>
>     JOIN tblPuOrderStatus os ON po.vip_order_id = os.vip_order_id
>
>     JOIN tblPuOrderStatusHistory osh ON os.order_status_history_id =
> osh.order_status_history_id
>
> WHERE
>
>     exists(SELECT 1
>
>            FROM
>
>                tblCnDoctorPatientMap d
>
>            WHERE d.vip_patient_id = po.vip_patient_id
>
>                  AND exists(SELECT 1
>
>                             FROM
>
>                                 tblCnAccounts a
>
>                             WHERE a.master_user_id = d.master_user_id
> AND
>
>                                   a.user_name = 'dddddd'))
>
>     AND osh.vip_order_type IN (17)--assist
>
>     --AND osh.tx_submit_date IS NOT NULL
>
>     AND osh.cancelled_date IS NULL
>
>     AND osh.cc_accept_date IS NOT NULL;
>
>
>
>
>
> ##########################  9.5 Execution plan
>
>
>
>
> QUERY PLAN
>
> ----------------------------------------------------------------------
> ----------------------------------------------------------------------
> ---------
>
> Aggregate  (cost=1177.25..1177.26 rows=1 width=0)
>
>    ->  Nested Loop  (cost=67.83..1177.25 rows=5 width=0)
>
>          ->  Nested Loop  (cost=67.71..254.81 rows=1322 width=4)
>
>                ->  Nested Loop  (cost=67.63..104.45 rows=1322 width=4)
>
>                      ->  HashAggregate  (cost=67.54..68.12 rows=192
> width=4)
>
>                            Group Key: d.vip_patient_id
>
>
>
>                            ->  Nested Loop  (cost=0.17..67.44 rows=192
> width=4)
>
>                                  ->  Index Scan using unq_user_name on
> tblcnaccounts a  (cost=0.08..4.09 rows=1 width=4)
>
>                                        Index Cond: ((user_name)::text
> =
> 'dddddd'::text)
>
>
>
>                                  ->  Index Only Scan using
> idx_tblcndoctorpatientmap on tblcndoctorpatientmap d
> (cost=0.09..62.78
> rows=192 width=8)
>
>                                        Index Cond: (master_user_id =
> a.master_user_id)
>
>                      ->  Index Scan using idx_tblcnpatientordermap on
> tblcnpatientordermap po  (cost=0.09..0.17 rows=7 width=8)
>
>                            Index Cond: (vip_patient_id =
> d.vip_patient_id)
>
>                ->  Index Scan using tblpuorderstatus_pkey on
> tblpuorderstatus os  (cost=0.09..0.11 rows=1 width=8)
>
>                      Index Cond: (vip_order_id = po.vip_order_id)
>
>          ->  Index Scan using tblpuorderstatushistory_pkey on
> tblpuorderstatushistory osh  (cost=0.11..0.69 rows=1 width=4)
>
>                Index Cond: (order_status_history_id =
> os.order_status_history_id)
>
>                Filter: ((cancelled_date IS NULL) AND (cc_accept_date
> IS NOT NULL) AND (vip_order_type = 17))
>
>
>
> ######################################################################
> ###############################################################
>
>
>
> ##########################  9.6 Execution plan
>
>                                                              QUERY
> PLAN
>
> ----------------------------------------------------------------------
> ---------------------------------------------------------------
>
> Aggregate  (cost=3185034.17..3185034.17 rows=1 width=8)
>
>    ->  Nested Loop Semi Join  (cost=3012833.92..3185010.91 rows=46511
> width=0)
>
>
>
>          ->  Nested Loop  (cost=3012833.75..3137291.51 rows=46511
> width=4)
>
>
>
>                ->  Hash Join  (cost=3012833.67..3117860.77 rows=46511
> width=4)
>
>                      Hash Cond: (os.order_status_history_id =
> osh.order_status_history_id)
>
>
>
>                      ->  Seq Scan on tblpuorderstatus os
> (cost=0.00..96498.46 rows=11185486 width=8)
>
>                      ->  Hash  (cost=3010979.77..3010979.77
> rows=529686
> width=4)
>
>                            ->  Gather  (cost=1000.00..3010979.77
> rows=529686 width=4)
>
>                                  Workers Planned: 2
>
>                                  ->  Parallel Seq Scan on
> tblpuorderstatushistory osh  (cost=0.00..2957011.17 rows=220702
> width=4)
>
>
>
>                                        Filter: ((cancelled_date IS
> NULL) AND (cc_accept_date IS NOT NULL) AND (vip_order_type = 17))
>
>
>
>                ->  Index Scan using tblcnpatientordermap_pkey on
> tblcnpatientordermap po  (cost=0.09..0.41 rows=1 width=8)
>
>
>
>                      Index Cond: (vip_order_id = os.vip_order_id)
>
>
>
>          ->  Nested Loop Semi Join  (cost=0.17..1.02 rows=1 width=4)
>
>                ->  Index Scan using tblcndoctorpatientmap_pkey on
> tblcndoctorpatientmap d  (cost=0.09..0.39 rows=1 width=8)
>
>                      Index Cond: (vip_patient_id = po.vip_patient_id)
>
>                ->  Index Scan using tblcnaccounts_pkey on
> tblcnaccounts a  (cost=0.08..0.36 rows=1 width=4)
>
>                      Index Cond: (master_user_id = d.master_user_id)
>
>                      Filter: ((user_name)::text = 'dddddd'::text)
>
> (19 rows)
>
>
>
>
>
> Regards,
>
> ravi
>


--
Adrian Klaver
adrian.klaver@aklaver.com

Hi.

> explain analyze
>
> SELECT count(*)
>
> [...]

>                                                                      QUERY PLAN
>
>
-----------------------------------------------------------------------------------------------------------------------------------------------------
>
> Aggregate  (cost=1177.25..1177.26 rows=1 width=0)
>
> [...]

I'm not seeing the "(actual ... )" part here.
THe plan you show is from an explain, not an explain analyze...

Can you provide the explain analyze output?

Bye,
Chris.

On 01/17/2017 08:31 PM, Ravi Tammineni wrote:
> Hi,
>
> We have recently upgraded to 9.6 and few queries are performing very
> poorly. Query execution time has increased more 4 or 5 times in 9.6.
> Qeruy execution plan is also completely changed. I am not sure whether
> its because of Parallel feature or any bug in 9.6. There are few similar
> kind of queries and all of them are taking more time in 9.6.
>
> Following query is taking 70ms in 9.5 and the same query is taking 2
> minutes in 9.6. Execution plan is totally different in 9.6 and seems
> like there is a major flaw while generating the execution plan. Instead
> of filtering the low cardinality, its filtering from biggest table.
> Somehow nested loop joins are screwed up.
>
> I really appreciate your help.
>
> explain analyze
> SELECT count(*)
> ...

You say "explain analyze" but have only provided EXPLAIN output. We need
to see the EXPLAIN ANALYZE to see how accurate the estimates are.

Others already recommended doing ANALYZE to collect statistics on the
upgraded database - if Heroku doesn't do that automatically, I'd
recommend reporting that as a bug to them.

If that does not resolve the issue, run this on both machines and send
the results to the mailing list:

     select name, setting from pg_settings where source != 'default';

That'll tell us how was the configuration modified.


regards

--
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Chris,

Here is the explain analyze plan.

                                                                                QUERY PLAN

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=3391172.70..3391172.71 rows=1 width=8) (actual time=128011.913..128011.913 rows=1 loops=1)
   ->  Nested Loop Semi Join  (cost=3218963.06..3391149.45 rows=46513 width=0) (actual time=128011.907..128011.907
rows=0loops=1) 
         ->  Nested Loop  (cost=3218962.89..3343428.74 rows=46513 width=4) (actual time=123465.298..126884.739
rows=162974loops=1) 
               ->  Hash Join  (cost=3218962.80..3323993.25 rows=46513 width=4) (actual time=123465.275..126323.155
rows=162974loops=1) 
                     Hash Cond: (os.order_status_history_id = osh.order_status_history_id)
                     ->  Seq Scan on tblpuorderstatus os  (cost=0.00..96501.53 rows=11185842 width=8) (actual
time=0.011..822.937rows=11182962 loops=1) 
                     ->  Hash  (cost=3217108.89..3217108.89 rows=529689 width=4) (actual time=123134.119..123134.119
rows=595652loops=1) 
                           Buckets: 1048576  Batches: 1  Memory Usage: 29133kB
                           ->  Seq Scan on tblpuorderstatushistory osh  (cost=0.00..3217108.89 rows=529689 width=4)
(actualtime=0.026..122867.714 rows=595652 loops=1) 
                                 Filter: ((cancelled_date IS NULL) AND (cc_accept_date IS NOT NULL) AND (vip_order_type
=17)) 
                                 Rows Removed by Filter: 126867211
               ->  Index Scan using tblcnpatientordermap_pkey on tblcnpatientordermap po  (cost=0.09..0.41 rows=1
width=8)(actual time=0.003..0.003 rows=1 loops=162974) 
                     Index Cond: (vip_order_id = os.vip_order_id)
         ->  Nested Loop Semi Join  (cost=0.17..1.02 rows=1 width=4) (actual time=0.007..0.007 rows=0 loops=162974)
               ->  Index Scan using tblcndoctorpatientmap_pkey on tblcndoctorpatientmap d  (cost=0.09..0.39 rows=1
width=8)(actual time=0.003..0.003 rows=1 loops=162974) 
                     Index Cond: (vip_patient_id = po.vip_patient_id)
               ->  Index Scan using tblcnaccounts_pkey on tblcnaccounts a  (cost=0.08..0.36 rows=1 width=4) (actual
time=0.003..0.003rows=0 loops=162974) 
                     Index Cond: (master_user_id = d.master_user_id)
                     Filter: ((user_name)::text = 'rdoyleda'::text)
                     Rows Removed by Filter: 1

Thanks
ravi

-----Original Message-----
From: Chris Mair [mailto:chris@1006.org]
Sent: Tuesday, January 17, 2017 12:39 PM
To: Ravi Tammineni <rtammineni@partner.aligntech.com>
Cc: pgsql-general@postgresql.org
Subject: Re: [GENERAL] Queries are taking way longer in 9.6 than 9.5

Hi.

> explain analyze
>
> SELECT count(*)
>
> [...]

>                                                                      QUERY PLAN
>
>
-----------------------------------------------------------------------------------------------------------------------------------------------------
>
> Aggregate  (cost=1177.25..1177.26 rows=1 width=0)
>
> [...]

I'm not seeing the "(actual ... )" part here.
THe plan you show is from an explain, not an explain analyze...

Can you provide the explain analyze output?

Bye,
Chris.

Hi,

after looking at the explain plans again, I very much doubt those come
from the same query. The reason is the 9.5 plan contains this part:

     ->  HashAggregate  (cost=67.54..68.12 rows=192 width=4)
           Group Key: d.vip_patient_id
           ->  Nested Loop  (cost=0.17..67.44 rows=192 width=4)
                 ->  Index Scan using unq_user_name on tblcnaccounts ...
                       Index Cond: ((user_name)::text = 'dddddd'::text)
                 ->  Index Only Scan using idx_tblcndoctorpatientmap ...
                       Index Cond: (master_user_id = a.master_user_id)

while the 9.6 plan does not include anything like that, i.e. there's
only a single aggregate at the top level, without any group keys. Also,
the SQL query you've provided does not include any GROUP BY clause, so I
claim that those plans are from two different queries.

regards
Tomas

--
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 17/01/17 23:21, Tomas Vondra wrote:
> Hi,
>
> after looking at the explain plans again, I very much doubt those come from the same query. The reason is the 9.5
plancontains this part: 
>
>     ->  HashAggregate  (cost=67.54..68.12 rows=192 width=4)
>           Group Key: d.vip_patient_id
>           ->  Nested Loop  (cost=0.17..67.44 rows=192 width=4)
>                 ->  Index Scan using unq_user_name on tblcnaccounts ...
>                       Index Cond: ((user_name)::text = 'dddddd'::text)
>                 ->  Index Only Scan using idx_tblcndoctorpatientmap ...
>                       Index Cond: (master_user_id = a.master_user_id)
>
> while the 9.6 plan does not include anything like that, i.e. there's only a single aggregate at the top level,
withoutany group keys. Also, the SQL query you've provided does not include any GROUP BY clause, so I claim that those
plansare from two different queries. 

There's also a user_name = 'dddddd' that has become a user_name = 'rdoyleda' ...

Ravi, could you please send the current query you're testing and the explain analyze of that query on 9.5 and 9.6?

Bye,
Chris.

Hi Chris,

Here is the query and execution plan in 9.5 and 9.6.


explain analyze
SELECT count(*)
FROM
    tblCnPatientOrderMap po
    JOIN tblPuOrderStatus os ON po.vip_order_id = os.vip_order_id
    JOIN tblPuOrderStatusHistory osh ON os.order_status_history_id = osh.order_status_history_id
WHERE
    exists(SELECT 1
           FROM
               tblCnDoctorPatientMap d
           WHERE d.vip_patient_id = po.vip_patient_id
                 AND exists(SELECT 1
                            FROM
                                tblCnAccounts a
                            WHERE a.master_user_id = d.master_user_id AND
                                  a.user_name = 'rdoyleda'))
    AND osh.vip_order_type IN (17)--assist
    --AND osh.tx_submit_date IS NOT NULL
    AND osh.cancelled_date IS NULL
    AND osh.cc_accept_date IS NOT NULL;



====== 9.5 Execution plan
                                                                                        QUERY PLAN

-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=2647.00..2647.00 rows=1 width=0) (actual time=2260.155..2260.155 rows=1 loops=1)
   ->  Nested Loop  (cost=381.14..2646.99 rows=6 width=0) (actual time=112.561..2259.992 rows=74 loops=1)
         ->  Nested Loop  (cost=381.02..1161.54 rows=1390 width=4) (actual time=63.396..1360.848 rows=1298 loops=1)
               ->  Nested Loop  (cost=380.94..624.53 rows=1390 width=4) (actual time=60.818..471.681 rows=1298 loops=1)
                     ->  HashAggregate  (cost=380.85..381.43 rows=193 width=4) (actual time=59.442..60.245 rows=850
loops=1)
                           Group Key: d.vip_patient_id
                           ->  Nested Loop  (cost=2.47..380.75 rows=193 width=4) (actual time=22.383..58.777 rows=850
loops=1)
                                 ->  Index Scan using unq_user_name on tblcnaccounts a  (cost=0.08..4.09 rows=1
width=4)(actual time=6.544..6.547 rows=1 loops=1) 
                                       Index Cond: ((user_name)::text = 'rdoyleda'::text)
                                 ->  Bitmap Heap Scan on tblcndoctorpatientmap d  (cost=2.39..376.08 rows=193 width=8)
(actualtime=15.830..51.978 rows=850 loops=1) 
                                       Recheck Cond: (master_user_id = a.master_user_id)
                                       Heap Blocks: exact=549
                                       ->  Bitmap Index Scan on idx_tblcndoctorpatientmap_master_user_id
(cost=0.00..2.38rows=193 width=0) (actual time=14.981..14.981 rows=850 loops=1) 
                                             Index Cond: (master_user_id = a.master_user_id)
                     ->  Index Scan using idx_tblcnpatientordermap_vip_patient_id on tblcnpatientordermap po
(cost=0.09..1.24rows=7 width=8) (actual time=0.293..0.482 rows=2 loops=850) 
                           Index Cond: (vip_patient_id = d.vip_patient_id)
               ->  Index Scan using tblpuorderstatus_pkey on tblpuorderstatus os  (cost=0.09..0.38 rows=1 width=8)
(actualtime=0.681..0.683 rows=1 loops=1298) 
                     Index Cond: (vip_order_id = po.vip_order_id)
         ->  Index Scan using tblpuorderstatushistory_pkey on tblpuorderstatushistory osh  (cost=0.11..1.07 rows=1
width=4)(actual time=0.691..0.691 rows=0 loops=1298) 
               Index Cond: (order_status_history_id = os.order_status_history_id)
               Filter: ((cancelled_date IS NULL) AND (cc_accept_date IS NOT NULL) AND (vip_order_type = 17))
               Rows Removed by Filter: 1
 Planning time: 6.186 ms
 Execution time: 2260.408 ms
(24 rows)



#####################################################################################################################################
====== 9.6 Execution plan

                                                                                      QUERY PLAN

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=3185084.45..3185084.45 rows=1 width=8) (actual time=392961.743..392961.743 rows=1 loops=1)
   ->  Nested Loop Semi Join  (cost=3012858.88..3185061.19 rows=46515 width=0) (actual time=392961.739..392961.739
rows=0loops=1) 
         ->  Nested Loop  (cost=3012858.71..3137330.17 rows=46515 width=4) (actual time=369631.475..380887.445
rows=162974loops=1) 
               ->  Hash Join  (cost=3012858.62..3117894.07 rows=46515 width=4) (actual time=369629.678..374021.198
rows=162974loops=1) 
                     Hash Cond: (os.order_status_history_id = osh.order_status_history_id)
                     ->  Seq Scan on tblpuorderstatus os  (cost=0.00..96506.12 rows=11186375 width=8) (actual
time=0.007..2570.551rows=11183027 loops=1) 
                     ->  Hash  (cost=3011004.71..3011004.71 rows=529690 width=4) (actual time=368764.059..368764.059
rows=595653loops=1) 
                           Buckets: 1048576  Batches: 1  Memory Usage: 29133kB
                           ->  Gather  (cost=1000.00..3011004.71 rows=529690 width=4) (actual time=2.713..368445.460
rows=595653loops=1) 
                                 Workers Planned: 2
                                 Workers Launched: 2
                                 ->  Parallel Seq Scan on tblpuorderstatushistory osh  (cost=0.00..2957035.71
rows=220704width=4) (actual time=1.482..368455.487 rows=198551 loops=3) 
                                       Filter: ((cancelled_date IS NULL) AND (cc_accept_date IS NOT NULL) AND
(vip_order_type= 17)) 
                                       Rows Removed by Filter: 42289131
               ->  Index Scan using tblcnpatientordermap_pkey on tblcnpatientordermap po  (cost=0.09..0.41 rows=1
width=8)(actual time=0.041..0.042 rows=1 loops=162974) 
                     Index Cond: (vip_order_id = os.vip_order_id)
         ->  Nested Loop Semi Join  (cost=0.17..1.02 rows=1 width=4) (actual time=0.074..0.074 rows=0 loops=162974)
               ->  Index Scan using tblcndoctorpatientmap_pkey on tblcndoctorpatientmap d  (cost=0.09..0.39 rows=1
width=8)(actual time=0.068..0.068 rows=1 loops=162974) 
                     Index Cond: (vip_patient_id = po.vip_patient_id)
               ->  Index Scan using tblcnaccounts_pkey on tblcnaccounts a  (cost=0.08..0.36 rows=1 width=4) (actual
time=0.005..0.005rows=0 loops=162974) 
                     Index Cond: (master_user_id = d.master_user_id)
                     Filter: ((user_name)::text = 'rdoyleda'::text)
                     Rows Removed by Filter: 1
 Planning time: 3.155 ms
 Execution time: 392962.600 ms
(25 rows)

Thanks
ravi



-----Original Message-----
From: Chris Mair [mailto:chris@1006.org]
Sent: Tuesday, January 17, 2017 4:22 PM
To: Tomas Vondra <tomas.vondra@2ndquadrant.com>; Ravi Tammineni <rtammineni@partner.aligntech.com>
Cc: pgsql-general@postgresql.org
Subject: Re: [GENERAL] Queries are taking way longer in 9.6 than 9.5

On 17/01/17 23:21, Tomas Vondra wrote:
> Hi,
>
> after looking at the explain plans again, I very much doubt those come from the same query. The reason is the 9.5
plancontains this part: 
>
>     ->  HashAggregate  (cost=67.54..68.12 rows=192 width=4)
>           Group Key: d.vip_patient_id
>           ->  Nested Loop  (cost=0.17..67.44 rows=192 width=4)
>                 ->  Index Scan using unq_user_name on tblcnaccounts ...
>                       Index Cond: ((user_name)::text = 'dddddd'::text)
>                 ->  Index Only Scan using idx_tblcndoctorpatientmap ...
>                       Index Cond: (master_user_id = a.master_user_id)
>
> while the 9.6 plan does not include anything like that, i.e. there's only a single aggregate at the top level,
withoutany group keys. Also, the SQL query you've provided does not include any GROUP BY clause, so I claim that those
plansare from two different queries. 

There's also a user_name = 'dddddd' that has become a user_name = 'rdoyleda' ...

Ravi, could you please send the current query you're testing and the explain analyze of that query on 9.5 and 9.6?

Bye,
Chris.

On Wed, Jan 18, 2017 at 1:04 PM, Ravi Tammineni
<rtammineni@partner.aligntech.com> wrote:
> Hi Chris,
>
> Here is the query and execution plan in 9.5 and 9.6.

Can you verify tblpuorderstatus and tblpuorderstatushistory have all
indexes accounted for on both servers?  It seems incredible server
would prefer wading through 11M records to 1298 nestloop.  I'm curious
what plans you get if you try playing around with:

set enable_seqscan=false;
set enable_hashjoin=false;

...but I think we have two possibilities here:
1. schema mismatch
2. planner bug

merlin

On 01/18/2017 08:58 PM, Merlin Moncure wrote:
> On Wed, Jan 18, 2017 at 2:12 PM, Melvin Davidson <melvin6925@gmail.com
> <mailto:melvin6925@gmail.com>> wrote:
>
>
>
>     On Wed, Jan 18, 2017 at 3:06 PM, Merlin Moncure <mmoncure@gmail.com
>     <mailto:mmoncure@gmail.com>> wrote:
>
>         On Wed, Jan 18, 2017 at 1:04 PM, Ravi Tammineni
>         <rtammineni@partner.aligntech.com
>         <mailto:rtammineni@partner.aligntech.com>> wrote:
>         > Hi Chris,
>         >
>         > Here is the query and execution plan in 9.5 and 9.6.
>
>         Can you verify tblpuorderstatus and tblpuorderstatushistory have all
>         indexes accounted for on both servers?  It seems incredible server
>         would prefer wading through 11M records to 1298 nestloop.  I'm
>         curious
>         what plans you get if you try playing around with:
>
>         set enable_seqscan=false;
>         set enable_hashjoin=false;
>
>         ...but I think we have two possibilities here:
>         1. schema mismatch
>         2. planner bug
>
>         merlin
>
>
>         --
>         Sent via pgsql-general mailing list
>         (pgsql-general@postgresql.org <mailto:pgsql-general@postgresql.org>)
>         To make changes to your subscription:
>         http://www.postgresql.org/mailpref/pgsql-general
>         <http://www.postgresql.org/mailpref/pgsql-general>
>
>
>     *I never got an answer to my question.
>     *
>     *Have you verified that postgresql.conf is the same of both 9.5 & 9.6?*
>
>
> This is not verified, but I can't think of an influential planner
> variable that would push planner cost from 2600 to millions; abrupt
> increase in plan cost roles out a knife edge plan choice and the
> statistic look relatively correct on rows.  Unless planner choices are
> disabled in postgresql.conf, this suggests something is preventing
> planner from choosing a particular kind of plan for this query, which is
> suggesting bug to me.

I am still working out the parallel query feature in 9.6 but I am seeing
the below in the 9.6 EXPLAIN ANALYZE:

  ->  Gather  (cost=1000.00..3011004.71 rows=529690 width=4) (actual
time=2.713..368445.460 rows=595653 loops=1)
                                  Workers Planned: 2
                                  Workers Launched: 2

Does that not indicate parallel query has been turned on?

Would not turning it off be a better apple-to-apple comparison to the
9.5 plan?

>
> OP, if you want to contribute to the investigation of fix, "git bisect"
> is the way to proceed...is that feasible?
>
> merlin


--
Adrian Klaver
adrian.klaver@aklaver.com

On Wed, Jan 18, 2017 at 11:10 PM, Adrian Klaver
<adrian.klaver@aklaver.com> wrote:
> On 01/18/2017 08:58 PM, Merlin Moncure wrote:
>>
>> On Wed, Jan 18, 2017 at 2:12 PM, Melvin Davidson <melvin6925@gmail.com
>> <mailto:melvin6925@gmail.com>> wrote:
>>
>>
>>
>>     On Wed, Jan 18, 2017 at 3:06 PM, Merlin Moncure <mmoncure@gmail.com
>>     <mailto:mmoncure@gmail.com>> wrote:
>>
>>         On Wed, Jan 18, 2017 at 1:04 PM, Ravi Tammineni
>>         <rtammineni@partner.aligntech.com
>>         <mailto:rtammineni@partner.aligntech.com>> wrote:
>>         > Hi Chris,
>>         >
>>         > Here is the query and execution plan in 9.5 and 9.6.
>>
>>         Can you verify tblpuorderstatus and tblpuorderstatushistory have
>> all
>>         indexes accounted for on both servers?  It seems incredible server
>>         would prefer wading through 11M records to 1298 nestloop.  I'm
>>         curious
>>         what plans you get if you try playing around with:
>>
>>         set enable_seqscan=false;
>>         set enable_hashjoin=false;
>>
>>         ...but I think we have two possibilities here:
>>         1. schema mismatch
>>         2. planner bug
>>
>>         merlin
>>
>>
>>         --
>>         Sent via pgsql-general mailing list
>>         (pgsql-general@postgresql.org
>> <mailto:pgsql-general@postgresql.org>)
>>         To make changes to your subscription:
>>         http://www.postgresql.org/mailpref/pgsql-general
>>         <http://www.postgresql.org/mailpref/pgsql-general>
>>
>>
>>     *I never got an answer to my question.
>>     *
>>     *Have you verified that postgresql.conf is the same of both 9.5 &
>> 9.6?*
>>
>>
>> This is not verified, but I can't think of an influential planner
>> variable that would push planner cost from 2600 to millions; abrupt
>> increase in plan cost roles out a knife edge plan choice and the
>> statistic look relatively correct on rows.  Unless planner choices are
>> disabled in postgresql.conf, this suggests something is preventing
>> planner from choosing a particular kind of plan for this query, which is
>> suggesting bug to me.
>
>
> I am still working out the parallel query feature in 9.6 but I am seeing the
> below in the 9.6 EXPLAIN ANALYZE:
>
>  ->  Gather  (cost=1000.00..3011004.71 rows=529690 width=4) (actual
> time=2.713..368445.460 rows=595653 loops=1)
>                                  Workers Planned: 2
>                                  Workers Launched: 2
>
> Does that not indicate parallel query has been turned on?
>
> Would not turning it off be a better apple-to-apple comparison to the 9.5
> plan?

yes.  Either way, I would like to very much understand how server is
preferring 3m cost plan to 2.6k cost plan or is otherwise unable to
access the cheap plan.

merlin

On 01/19/2017 06:21 AM, Merlin Moncure wrote:
 >
...
>
> yes.  Either way, I would like to very much understand how server is
> preferring 3m cost plan to 2.6k cost plan or is otherwise unable to
> access the cheap plan.
>

Perhaps it doesn't even see the 2.6k cost - it may not generate the plan
for some reason, or it arrives to different estimates.

The OP was repeatedly asked for details of the configuration, I've even
sent a query for doing that a few days back. It's difficult to help when
such basic info is not provided, though.

It'd also be interesting to see the statistics for the tables involved,
so something like

    SELECT * FROM pg_stats WHERE tablename IN (... tables ...)

and

    SELECT relname, relpages, reltuples, relallvisible
      FROM pg_class WHERE relame IN (... tables ...)

might shed some light on what the planner assumes about the data.

Of course, there are other things we might need to know. For example if
there are foreign keys between the tables, 9.6 is using that for the
estimates (unlike 9.5). And so on.

regards

--
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On Thu, Jan 19, 2017 at 1:28 AM, Tomas Vondra
<tomas.vondra@2ndquadrant.com> wrote:
> On 01/19/2017 06:21 AM, Merlin Moncure wrote:
>>
> ...
>>
>>
>> yes.  Either way, I would like to very much understand how server is
>> preferring 3m cost plan to 2.6k cost plan or is otherwise unable to
>> access the cheap plan.
>>
>
> Perhaps it doesn't even see the 2.6k cost - it may not generate the plan for
> some reason, or it arrives to different estimates.
>
> The OP was repeatedly asked for details of the configuration, I've even sent
> a query for doing that a few days back. It's difficult to help when such
> basic info is not provided, though.
>
> It'd also be interesting to see the statistics for the tables involved, so
> something like
>
>    SELECT * FROM pg_stats WHERE tablename IN (... tables ...)
>
> and
>
>    SELECT relname, relpages, reltuples, relallvisible
>      FROM pg_class WHERE relame IN (... tables ...)
>
> might shed some light on what the planner assumes about the data.
>
> Of course, there are other things we might need to know. For example if
> there are foreign keys between the tables, 9.6 is using that for the
> estimates (unlike 9.5). And so on.

Maybe. This smells like bug or missing index.  Key for me is:
  ->  Seq Scan on tblpuorderstatus os  (cost=0.00..96501.53
rows=11185842 width=8) (actual time=0.011..822.937 rows=11182962

I can't see why any reasonable plan path would choose this unless the
index on "vip_order_id" is missing  (my money is on this actually)  or
there is a gross preference to prefer parallel scans over traditional
plan choices irrespective of cost.

I'm rolling out 9.6 next week and so have a particular interest in
this.  :-)  I tend also utilize a lot of cascading semi-joins and so
am curious to see where this turns up.

Ravi, if you can arrange for screen share or some similar way of
looking at this system I'd be happy to help you trouble shoot, gratis.

merlin