Обсуждение: [GENERAL] Queries are taking way longer in 9.6 than 9.5
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
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?
--
I reserve the right to fantasize. Whether or not you
wish to share my fantasy is entirely up to you.
![](http://us.i1.yimg.com/us.yimg.com/i/mesg/tsmileys2/01.gif)
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
Re: [pgadmin-support] [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@gmail.com]
Sent: Tuesday, January 17, 2017 11:36 AM
To: Ravi Tammineni <rtammineni@partner.aligntech.com>
Cc: 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 Tue, Jan 17, 2017 at 2:31 PM, Ravi Tammineni <rtammineni@partner.aligntech.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.
Вложения
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 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.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.5On 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
--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general
>I am not sure whether they are doing the vacuum after the upgrade or not
--
I reserve the right to fantasize. Whether or not you
wish to share my fantasy is entirely up to you.
![](http://us.i1.yimg.com/us.yimg.com/i/mesg/tsmileys2/01.gif)
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 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
--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general
--
I reserve the right to fantasize. Whether or not you
wish to share my fantasy is entirely up to you.
![](http://us.i1.yimg.com/us.yimg.com/i/mesg/tsmileys2/01.gif)
On Wed, Jan 18, 2017 at 3:06 PM, Merlin Moncure <mmoncure@gmail.com> wrote: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
--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
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?
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