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

Hi Adrain,

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

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 execution plan 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(dot)klaver(at)aklaver(dot)com]
Sent: Tuesday, January 17, 2017 11:42 AM
To: Ravi Tammineni <rtammineni(at)partner(dot)aligntech(dot)com>; pgsql-admin(at)postgresql(dot)org; pgsql-general(at)postgresql(dot)org; pgadmin-support(at)postgresql(dot)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(dot)klaver(at)aklaver(dot)com