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

2017-01-19 Thread Merlin Moncure 
On Thu, Jan 19, 2017 at 1:28 AM, Tomas Vondra
 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

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

2017-01-18 Thread Tomas Vondra 

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

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

2017-01-18 Thread Merlin Moncure 
On Wed, Jan 18, 2017 at 11:10 PM, Adrian Klaver
 wrote:
> On 01/18/2017 08:58 PM, Merlin Moncure wrote:
>>
>> On Wed, Jan 18, 2017 at 2:12 PM, Melvin Davidson > > wrote:
>>
>>
>>
>> On Wed, Jan 18, 2017 at 3:06 PM, Merlin Moncure > > wrote:
>>
>> On Wed, Jan 18, 2017 at 1:04 PM, Ravi Tammineni
>> > > 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.
>
>
> 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

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

2017-01-18 Thread Adrian Klaver 

On 01/18/2017 08:58 PM, Merlin Moncure wrote:

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



On Wed, Jan 18, 2017 at 3:06 PM, Merlin Moncure mailto:mmonc...@gmail.com>> wrote:

On Wed, Jan 18, 2017 at 1:04 PM, Ravi Tammineni
mailto:rtammin...@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.


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

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

2017-01-18 Thread Merlin Moncure 
On Wed, Jan 18, 2017 at 2:12 PM, Melvin Davidson 
wrote:

>
>
> On Wed, Jan 18, 2017 at 3:06 PM, Merlin Moncure 
> wrote:
>
>> On Wed, Jan 18, 2017 at 1:04 PM, Ravi Tammineni
>>  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

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

2017-01-18 Thread Melvin Davidson 
On Wed, Jan 18, 2017 at 3:06 PM, Merlin Moncure  wrote:

> On Wed, Jan 18, 2017 at 1:04 PM, Ravi Tammineni
>  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.

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

2017-01-18 Thread Merlin Moncure 
On Wed, Jan 18, 2017 at 1:04 PM, Ravi Tammineni
 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

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

2017-01-18 Thread Ravi Tammineni 
ps=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:ch...@1006.org] 
Sent: Tuesday, January 17, 2017 4:22 PM
To: Tomas Vondra ; Ravi Tammineni 

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 = 'dd'::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 = 'dd' 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

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

2017-01-17 Thread Chris Mair 

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 = 'dd'::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 = 'dd' 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

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

2017-01-17 Thread Tomas Vondra 

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 = 'dd'::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

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

2017-01-17 Thread Ravi Tammineni 
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:ch...@1006.org] 
Sent: Tuesday, January 17, 2017 12:39 PM
To: Ravi Tammineni 
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

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

2017-01-17 Thread Tomas Vondra 

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

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

2017-01-17 Thread Chris Mair 

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

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

2017-01-17 Thread Melvin Davidson 
On Tue, Jan 17, 2017 at 3:12 PM, Ravi Tammineni <
rtammin...@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 
>
> 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.kla...@aklaver.com]
> Sent: Tuesday, January 17, 2017 11:42 AM
> To: Ravi Tammineni ;
> pgsql-ad...@postgresql.org; pgsql-general@postgresql.org;
> pgadmin-supp...@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
> >
> >

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

2017-01-17 Thread Ravi Tammineni 
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 

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.kla...@aklaver.com] 
Sent: Tuesday, January 17, 2017 11:42 AM
To: Ravi Tammineni ; 
pgsql-ad...@postgresql.org; pgsql-general@postgresql.org; 
pgadmin-supp...@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 = 'dd'))
>
> 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.2

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

2017-01-17 Thread Ravi Tammineni 
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 

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:melvin6...@gmail.com]
Sent: Tuesday, January 17, 2017 11:36 AM
To: Ravi Tammineni 
Cc: pgsql-ad...@postgresql.org; pgsql-general@postgresql.org; 
pgadmin-supp...@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 
mailto:rtammin...@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 = 'dd'))
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 = 
'dd'::text)

 ->  Index O

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

2017-01-17 Thread Adrian Klaver 

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 = 'dd'))

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 =
'dd'::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)

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

2017-01-17 Thread Melvin Davidson 
On Tue, Jan 17, 2017 at 2:31 PM, Ravi Tammineni <
rtammin...@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 = 'dd'))
>
> 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 =
> 'dd'::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)
>
>
>
>