Re: Queries are taking way longer in 9.6 than 9.5

From: Melvin Davidson <melvin6925(at)gmail(dot)com>
To: Ravi Tammineni <rtammineni(at)partner(dot)aligntech(dot)com>
Cc: Adrian Klaver <adrian(dot)klaver(at)aklaver(dot)com>, "pgsql-admin(at)postgresql(dot)org" <pgsql-admin(at)postgresql(dot)org>, "pgsql-general(at)postgresql(dot)org" <pgsql-general(at)postgresql(dot)org>, "pgadmin-support(at)postgresql(dot)org" <pgadmin-support(at)postgresql(dot)org>
Subject: Re: Queries are taking way longer in 9.6 than 9.5
Date: 2017-01-17 20:21:27
Message-ID: CANu8Fix4gEDmu+aTnP08BW5TSEY5C3YR0AR_aj5hs3xMSNFBbw@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgadmin-support pgsql-admin pgsql-general

On Tue, Jan 17, 2017 at 3:12 PM, Ravi Tammineni <
rtammineni(at)partner(dot)aligntech(dot)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(dot)klaver(at)aklaver(dot)com]
> Sent: Tuesday, January 17, 2017 11:42 AM
> To: Ravi Tammineni <rtammineni(at)partner(dot)aligntech(dot)com>;
> pgsql-admin(at)postgresql(dot)org; pgsql-general(at)postgresql(dot)org;
> pgadmin-support(at)postgresql(dot)org
> Subject: Re: [GENERAL] Queries are taking way longer in 9.6 than 9.5
>
> On 01/17/2017 11:31 AM, Ravi Tammineni wrote:
> > Hi,
> >
> >
> >
> > We have recently upgraded to 9.6 and few queries are performing very
> > poorly. Query execution time has increased more 4 or 5 times in 9.6.
> > Qeruy execution plan is also completely changed. I am not sure whether
> > its because of Parallel feature or any bug in 9.6. There are few
> > similar kind of queries and all of them are taking more time in 9.6.
>
> How did you upgrade from 9.5 --> 9.6?
>
> Did you run ANALYZE on the tables after the upgrade?
>
> Tend to doubt parallel query is at issue here, as it is turned off by
> default:
>
> https://www.postgresql.org/docs/9.6/static/runtime-config-
> resource.html#GUC-MAX-PARALLEL-WORKERS-PER-GATHER
>
> For more info:
>
> https://www.postgresql.org/docs/9.6/static/parallel-query.html
> >
> >
> >
> > Following query is taking 70ms in 9.5 and the same query is taking 2
> > minutes in 9.6. Execution plan is totally different in 9.6 and seems
> > like there is a major flaw while generating the execution plan.
> > Instead of filtering the low cardinality, its filtering from biggest
> table.
> > Somehow nested loop joins are screwed up.
> >
> >
> >
> >
> >
> > I really appreciate your help.
> >
> >
> >
> > explain analyze
> >
> > SELECT count(*)
> >
> > FROM
> >
> > tblCnPatientOrderMap po
> >
> > JOIN tblPuOrderStatus os ON po.vip_order_id = os.vip_order_id
> >
> > JOIN tblPuOrderStatusHistory osh ON os.order_status_history_id =
> > osh.order_status_history_id
> >
> > WHERE
> >
> > exists(SELECT 1
> >
> > FROM
> >
> > tblCnDoctorPatientMap d
> >
> > WHERE d.vip_patient_id = po.vip_patient_id
> >
> > AND exists(SELECT 1
> >
> > FROM
> >
> > tblCnAccounts a
> >
> > WHERE a.master_user_id = d.master_user_id
> > AND
> >
> > a.user_name = 'dddddd'))
> >
> > AND osh.vip_order_type IN (17)--assist
> >
> > --AND osh.tx_submit_date IS NOT NULL
> >
> > AND osh.cancelled_date IS NULL
> >
> > AND osh.cc_accept_date IS NOT NULL;
> >
> >
> >
> >
> >
> > ########################## 9.5 Execution plan
> >
> >
> >
> >
> > QUERY PLAN
> >
> > ----------------------------------------------------------------------
> > ----------------------------------------------------------------------
> > ---------
> >
> > Aggregate (cost=1177.25..1177.26 rows=1 width=0)
> >
> > -> Nested Loop (cost=67.83..1177.25 rows=5 width=0)
> >
> > -> Nested Loop (cost=67.71..254.81 rows=1322 width=4)
> >
> > -> Nested Loop (cost=67.63..104.45 rows=1322 width=4)
> >
> > -> HashAggregate (cost=67.54..68.12 rows=192
> > width=4)
> >
> > Group Key: d.vip_patient_id
> >
> >
> >
> > -> Nested Loop (cost=0.17..67.44 rows=192
> > width=4)
> >
> > -> Index Scan using unq_user_name on
> > tblcnaccounts a (cost=0.08..4.09 rows=1 width=4)
> >
> > Index Cond: ((user_name)::text
> > =
> > 'dddddd'::text)
> >
> >
> >
> > -> Index Only Scan using
> > idx_tblcndoctorpatientmap on tblcndoctorpatientmap d
> > (cost=0.09..62.78
> > rows=192 width=8)
> >
> > Index Cond: (master_user_id =
> > a.master_user_id)
> >
> > -> Index Scan using idx_tblcnpatientordermap on
> > tblcnpatientordermap po (cost=0.09..0.17 rows=7 width=8)
> >
> > Index Cond: (vip_patient_id =
> > d.vip_patient_id)
> >
> > -> Index Scan using tblpuorderstatus_pkey on
> > tblpuorderstatus os (cost=0.09..0.11 rows=1 width=8)
> >
> > Index Cond: (vip_order_id = po.vip_order_id)
> >
> > -> Index Scan using tblpuorderstatushistory_pkey on
> > tblpuorderstatushistory osh (cost=0.11..0.69 rows=1 width=4)
> >
> > Index Cond: (order_status_history_id =
> > os.order_status_history_id)
> >
> > Filter: ((cancelled_date IS NULL) AND (cc_accept_date
> > IS NOT NULL) AND (vip_order_type = 17))
> >
> >
> >
> > ######################################################################
> > ###############################################################
> >
> >
> >
> > ########################## 9.6 Execution plan
> >
> > QUERY
> > PLAN
> >
> > ----------------------------------------------------------------------
> > ---------------------------------------------------------------
> >
> > Aggregate (cost=3185034.17..3185034.17 rows=1 width=8)
> >
> > -> Nested Loop Semi Join (cost=3012833.92..3185010.91 rows=46511
> > width=0)
> >
> >
> >
> > -> Nested Loop (cost=3012833.75..3137291.51 rows=46511
> > width=4)
> >
> >
> >
> > -> Hash Join (cost=3012833.67..3117860.77 rows=46511
> > width=4)
> >
> > Hash Cond: (os.order_status_history_id =
> > osh.order_status_history_id)
> >
> >
> >
> > -> Seq Scan on tblpuorderstatus os
> > (cost=0.00..96498.46 rows=11185486 width=8)
> >
> > -> Hash (cost=3010979.77..3010979.77
> > rows=529686
> > width=4)
> >
> > -> Gather (cost=1000.00..3010979.77
> > rows=529686 width=4)
> >
> > Workers Planned: 2
> >
> > -> Parallel Seq Scan on
> > tblpuorderstatushistory osh (cost=0.00..2957011.17 rows=220702
> > width=4)
> >
> >
> >
> > Filter: ((cancelled_date IS
> > NULL) AND (cc_accept_date IS NOT NULL) AND (vip_order_type = 17))
> >
> >
> >
> > -> Index Scan using tblcnpatientordermap_pkey on
> > tblcnpatientordermap po (cost=0.09..0.41 rows=1 width=8)
> >
> >
> >
> > Index Cond: (vip_order_id = os.vip_order_id)
> >
> >
> >
> > -> Nested Loop Semi Join (cost=0.17..1.02 rows=1 width=4)
> >
> > -> Index Scan using tblcndoctorpatientmap_pkey on
> > tblcndoctorpatientmap d (cost=0.09..0.39 rows=1 width=8)
> >
> > Index Cond: (vip_patient_id = po.vip_patient_id)
> >
> > -> Index Scan using tblcnaccounts_pkey on
> > tblcnaccounts a (cost=0.08..0.36 rows=1 width=4)
> >
> > Index Cond: (master_user_id = d.master_user_id)
> >
> > Filter: ((user_name)::text = 'dddddd'::text)
> >
> > (19 rows)
> >
> >
> >
> >
> >
> > Regards,
> >
> > ravi
> >
>
>
> --
> Adrian Klaver
> adrian(dot)klaver(at)aklaver(dot)com
>
>
> --
> Sent via pgsql-general mailing list (pgsql-general(at)postgresql(dot)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.

In response to

Browse pgadmin-support by date

  From Date Subject
Next Message Chris Mair 2017-01-17 20:38:59 Re: Queries are taking way longer in 9.6 than 9.5
Previous Message Ravi Tammineni 2017-01-17 20:12:17 Re: [GENERAL] Queries are taking way longer in 9.6 than 9.5

Browse pgsql-admin by date

  From Date Subject
Next Message Chris Mair 2017-01-17 20:38:59 Re: Queries are taking way longer in 9.6 than 9.5
Previous Message Ravi Tammineni 2017-01-17 20:12:17 Re: [GENERAL] Queries are taking way longer in 9.6 than 9.5

Browse pgsql-general by date

  From Date Subject
Next Message Chris Mair 2017-01-17 20:38:59 Re: Queries are taking way longer in 9.6 than 9.5
Previous Message Ravi Tammineni 2017-01-17 20:12:17 Re: [GENERAL] Queries are taking way longer in 9.6 than 9.5