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

Hi Melvin,

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. 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

From: Melvin Davidson [mailto:melvin6925(at)gmail(dot)com]
Sent: Tuesday, January 17, 2017 11:36 AM
To: Ravi Tammineni <rtammineni(at)partner(dot)aligntech(dot)com>
Cc: 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 Tue, Jan 17, 2017 at 2:31 PM, Ravi Tammineni <rtammineni(at)partner(dot)aligntech(dot)com<mailto:rtammineni(at)partner(dot)aligntech(dot)com>> 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(*)
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

1. Have you run ANALYZE on the database after upgrading?
2. Have you insured that the proper changed were done to the postgresql.conf in 9.6?

--
Melvin Davidson
I reserve the right to fantasize. Whether or not you
wish to share my fantasy is entirely up to you. [Image removed by sender.]