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

Hi Chris,

Here is the query and execution plan in 9.5 and 9.6.


explain analyze
SELECT count(*)
FROM
    tblCnPatientOrderMap po
    JOIN tblPuOrderStatus os ON po.vip_order_id = os.vip_order_id
    JOIN tblPuOrderStatusHistory osh ON os.order_status_history_id = osh.order_status_history_id
WHERE
    exists(SELECT 1
           FROM
               tblCnDoctorPatientMap d
           WHERE d.vip_patient_id = po.vip_patient_id
                 AND exists(SELECT 1
                            FROM
                                tblCnAccounts a
                            WHERE a.master_user_id = d.master_user_id AND
                                  a.user_name = 'rdoyleda'))
    AND osh.vip_order_type IN (17)--assist
    --AND osh.tx_submit_date IS NOT NULL
    AND osh.cancelled_date IS NULL
    AND osh.cc_accept_date IS NOT NULL;



====== 9.5 Execution plan
                                                                                        QUERY PLAN

-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=2647.00..2647.00 rows=1 width=0) (actual time=2260.155..2260.155 rows=1 loops=1)
   ->  Nested Loop  (cost=381.14..2646.99 rows=6 width=0) (actual time=112.561..2259.992 rows=74 loops=1)
         ->  Nested Loop  (cost=381.02..1161.54 rows=1390 width=4) (actual time=63.396..1360.848 rows=1298 loops=1)
               ->  Nested Loop  (cost=380.94..624.53 rows=1390 width=4) (actual time=60.818..471.681 rows=1298 loops=1)
                     ->  HashAggregate  (cost=380.85..381.43 rows=193 width=4) (actual time=59.442..60.245 rows=850
loops=1)
                           Group Key: d.vip_patient_id
                           ->  Nested Loop  (cost=2.47..380.75 rows=193 width=4) (actual time=22.383..58.777 rows=850
loops=1)
                                 ->  Index Scan using unq_user_name on tblcnaccounts a  (cost=0.08..4.09 rows=1
width=4)(actual time=6.544..6.547 rows=1 loops=1) 
                                       Index Cond: ((user_name)::text = 'rdoyleda'::text)
                                 ->  Bitmap Heap Scan on tblcndoctorpatientmap d  (cost=2.39..376.08 rows=193 width=8)
(actualtime=15.830..51.978 rows=850 loops=1) 
                                       Recheck Cond: (master_user_id = a.master_user_id)
                                       Heap Blocks: exact=549
                                       ->  Bitmap Index Scan on idx_tblcndoctorpatientmap_master_user_id
(cost=0.00..2.38rows=193 width=0) (actual time=14.981..14.981 rows=850 loops=1) 
                                             Index Cond: (master_user_id = a.master_user_id)
                     ->  Index Scan using idx_tblcnpatientordermap_vip_patient_id on tblcnpatientordermap po
(cost=0.09..1.24rows=7 width=8) (actual time=0.293..0.482 rows=2 loops=850) 
                           Index Cond: (vip_patient_id = d.vip_patient_id)
               ->  Index Scan using tblpuorderstatus_pkey on tblpuorderstatus os  (cost=0.09..0.38 rows=1 width=8)
(actualtime=0.681..0.683 rows=1 loops=1298) 
                     Index Cond: (vip_order_id = po.vip_order_id)
         ->  Index Scan using tblpuorderstatushistory_pkey on tblpuorderstatushistory osh  (cost=0.11..1.07 rows=1
width=4)(actual time=0.691..0.691 rows=0 loops=1298) 
               Index Cond: (order_status_history_id = os.order_status_history_id)
               Filter: ((cancelled_date IS NULL) AND (cc_accept_date IS NOT NULL) AND (vip_order_type = 17))
               Rows Removed by Filter: 1
 Planning time: 6.186 ms
 Execution time: 2260.408 ms
(24 rows)



#####################################################################################################################################
====== 9.6 Execution plan

                                                                                      QUERY PLAN

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=3185084.45..3185084.45 rows=1 width=8) (actual time=392961.743..392961.743 rows=1 loops=1)
   ->  Nested Loop Semi Join  (cost=3012858.88..3185061.19 rows=46515 width=0) (actual time=392961.739..392961.739
rows=0loops=1) 
         ->  Nested Loop  (cost=3012858.71..3137330.17 rows=46515 width=4) (actual time=369631.475..380887.445
rows=162974loops=1) 
               ->  Hash Join  (cost=3012858.62..3117894.07 rows=46515 width=4) (actual time=369629.678..374021.198
rows=162974loops=1) 
                     Hash Cond: (os.order_status_history_id = osh.order_status_history_id)
                     ->  Seq Scan on tblpuorderstatus os  (cost=0.00..96506.12 rows=11186375 width=8) (actual
time=0.007..2570.551rows=11183027 loops=1) 
                     ->  Hash  (cost=3011004.71..3011004.71 rows=529690 width=4) (actual time=368764.059..368764.059
rows=595653loops=1) 
                           Buckets: 1048576  Batches: 1  Memory Usage: 29133kB
                           ->  Gather  (cost=1000.00..3011004.71 rows=529690 width=4) (actual time=2.713..368445.460
rows=595653loops=1) 
                                 Workers Planned: 2
                                 Workers Launched: 2
                                 ->  Parallel Seq Scan on tblpuorderstatushistory osh  (cost=0.00..2957035.71
rows=220704width=4) (actual time=1.482..368455.487 rows=198551 loops=3) 
                                       Filter: ((cancelled_date IS NULL) AND (cc_accept_date IS NOT NULL) AND
(vip_order_type= 17)) 
                                       Rows Removed by Filter: 42289131
               ->  Index Scan using tblcnpatientordermap_pkey on tblcnpatientordermap po  (cost=0.09..0.41 rows=1
width=8)(actual time=0.041..0.042 rows=1 loops=162974) 
                     Index Cond: (vip_order_id = os.vip_order_id)
         ->  Nested Loop Semi Join  (cost=0.17..1.02 rows=1 width=4) (actual time=0.074..0.074 rows=0 loops=162974)
               ->  Index Scan using tblcndoctorpatientmap_pkey on tblcndoctorpatientmap d  (cost=0.09..0.39 rows=1
width=8)(actual time=0.068..0.068 rows=1 loops=162974) 
                     Index Cond: (vip_patient_id = po.vip_patient_id)
               ->  Index Scan using tblcnaccounts_pkey on tblcnaccounts a  (cost=0.08..0.36 rows=1 width=4) (actual
time=0.005..0.005rows=0 loops=162974) 
                     Index Cond: (master_user_id = d.master_user_id)
                     Filter: ((user_name)::text = 'rdoyleda'::text)
                     Rows Removed by Filter: 1
 Planning time: 3.155 ms
 Execution time: 392962.600 ms
(25 rows)

Thanks
ravi



-----Original Message-----
From: Chris Mair [mailto:chris@1006.org]
Sent: Tuesday, January 17, 2017 4:22 PM
To: Tomas Vondra <tomas.vondra@2ndquadrant.com>; Ravi Tammineni <rtammineni@partner.aligntech.com>
Cc: pgsql-general@postgresql.org
Subject: Re: [GENERAL] Queries are taking way longer in 9.6 than 9.5

On 17/01/17 23:21, Tomas Vondra wrote:
> Hi,
>
> after looking at the explain plans again, I very much doubt those come from the same query. The reason is the 9.5
plancontains this part: 
>
>     ->  HashAggregate  (cost=67.54..68.12 rows=192 width=4)
>           Group Key: d.vip_patient_id
>           ->  Nested Loop  (cost=0.17..67.44 rows=192 width=4)
>                 ->  Index Scan using unq_user_name on tblcnaccounts ...
>                       Index Cond: ((user_name)::text = 'dddddd'::text)
>                 ->  Index Only Scan using idx_tblcndoctorpatientmap ...
>                       Index Cond: (master_user_id = a.master_user_id)
>
> while the 9.6 plan does not include anything like that, i.e. there's only a single aggregate at the top level,
withoutany group keys. Also, the SQL query you've provided does not include any GROUP BY clause, so I claim that those
plansare from two different queries. 

There's also a user_name = 'dddddd' that has become a user_name = 'rdoyleda' ...

Ravi, could you please send the current query you're testing and the explain analyze of that query on 9.5 and 9.6?

Bye,
Chris.