Re: 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) (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(at)1006(dot)org]
Sent: Tuesday, January 17, 2017 4:22 PM
To: Tomas Vondra <tomas(dot)vondra(at)2ndquadrant(dot)com>; Ravi Tammineni <rtammineni(at)partner(dot)aligntech(dot)com>
Cc: pgsql-general(at)postgresql(dot)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.