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.

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

--
Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin

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<mailto: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. [Image removed by sender.]

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

--
Sent via pgsql-admin mailing list (pgsql-admin@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-admin

On Tue, Jan 17, 2017 at 3:12 PM, Ravi Tammineni <
rtammineni@partner.aligntech.com> wrote:

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

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

So just run an ANALYZE on the database!

--
*Melvin Davidson*
I reserve the right to fantasize. Whether or not you
wish to share my fantasy is entirely up to you.

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.

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

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

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

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=0 loops=1)
-> Nested Loop (cost=3218962.89..3343428.74 rows=46513 width=4) (actual time=123465.298..126884.739 rows=162974 loops=1)
-> Hash Join (cost=3218962.80..3323993.25 rows=46513 width=4) (actual time=123465.275..126323.155 rows=162974 loops=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.937 rows=11182962 loops=1)
-> Hash (cost=3217108.89..3217108.89 rows=529689 width=4) (actual time=123134.119..123134.119 rows=595652 loops=1)
Buckets: 1048576 Batches: 1 Memory Usage: 29133kB
-> Seq Scan on tblpuorderstatushistory osh (cost=0.00..3217108.89 rows=529689 width=4) (actual time=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.003 rows=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.

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

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

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

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

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.

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

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) (actual time=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.38 rows=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.24 rows=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) (actual time=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=0 loops=1)
-> Nested Loop (cost=3012858.71..3137330.17 rows=46515 width=4) (actual time=369631.475..380887.445 rows=162974 loops=1)
-> Hash Join (cost=3012858.62..3117894.07 rows=46515 width=4) (actual time=369629.678..374021.198 rows=162974 loops=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.551 rows=11183027 loops=1)
-> Hash (cost=3011004.71..3011004.71 rows=529690 width=4) (actual time=368764.059..368764.059 rows=595653 loops=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=595653 loops=1)
Workers Planned: 2
Workers Launched: 2
-> Parallel Seq Scan on tblpuorderstatushistory osh (cost=0.00..2957035.71 rows=220704 width=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.005 rows=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 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.

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.

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

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

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?*

--
*Melvin Davidson*
I reserve the right to fantasize. Whether or not you
wish to share my fantasy is entirely up to you.

On Wed, Jan 18, 2017 at 2:12 PM, Melvin Davidson <melvin6925@gmail.com>
wrote:

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?*

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.

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

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&gt;

*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

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

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&gt;

*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

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

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

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

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

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general