Re: Joining on CTE is unusually slow?

On Tue, Jul 29, 2014, at 05:38 PM, David G Johnston wrote:
> You should at least provide some explain a/o explain analyse results.
>
> Not to sound pedantic here but you are not JOINing on the CTE, you are
> pushing it into WHERE clause via a pair of sub-selects.

Fair criticisms. Okay, here we go. Table schemas at the end of the
email. My apologies for the length; I didn't want to try trimming out
"irrelevant" things that would end up causing actual changes to the
question I'm asking. I've run EXPLAIN ANALYZE for all the queries.
(The queries here are slightly different from the anonymized ones I put
in the first email.)

WITH RECURSIVE pn_downstream_thread(id, parent_id) AS
(SELECT pn_msg.id AS id, pn_msg.parent_id AS parent_id
FROM ams_msg AS pn_msg JOIN ams_msg_asset ON pn_msg.id =
ams_msg_asset.msg_id JOIN ams_asset ON ams_asset.id =
ams_msg_asset.asset_id JOIN ams_msg AS oi_msg ON oi_msg.id =
pn_msg.parent_id
WHERE pn_msg.message_type = 'structured' AND pn_msg.structured_type =
'pursuit_notification' AND ams_asset.typ = 'tp' AND ams_asset.public_id
= '59c89bdcaf6711e3b67f12313b0a607d' AND oi_msg.date >=
'2014-06-05T00:00:00' UNION SELECT pr_msg.id AS id, pr_msg.parent_id AS
parent_id
FROM ams_msg AS pr_msg JOIN pn_downstream_thread ON pr_msg.parent_id =
pn_downstream_thread.id)
SELECT pn_downstream_thread.id
FROM pn_downstream_thread;

Basically this is getting the ids of all pursuit notification messages
linked to a certain asset, and all replies downstream of those messages.
It's pretty fast. There's 2.3 million rows in ams_msg; this returns six
ids.

QUERY
PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
CTE Scan on pn_downstream_thread (cost=28135.55..28281.37 rows=7291 width=8)
(actual time=0.131..0.410 rows=6 loops=1)
CTE pn_downstream_thread
-> Recursive Union (cost=1.71..28135.55 rows=7291 width=12) (actual
time=0.126..0.391 rows=6 loops=1)
-> Nested Loop (cost=1.71..68.15 rows=1 width=12) (actual
time=0.118..0.275 rows=2 loops=1)
-> Nested Loop (cost=1.28..59.69 rows=1 width=12) (actual
time=0.102..0.230 rows=3 loops=1)
-> Nested Loop (cost=0.85..21.12 rows=5 width=8)
(actual time=0.058..0.100 rows=12 loops=1)
-> Index Scan using idx_16485_unique_asset_typ_id
on ams_asset (cost=0.42..8.45 rows=1 width=8)
(actual time=0.038..0.039 rows=1 loops=1)
Index Cond: ((typ = 'tp'::text) AND
(public_id =
'59c89bdcaf6711e3b67f12313b0a607d'::text))
-> Index Scan using idx_16551_asset_id on
ams_msg_asset (cost=0.43..11.26 rows=141 width=16)
(actual time=0.011..0.030 rows=12 loops=1)
Index Cond: (asset_id = ams_asset.id)
-> Index Scan using amsnew_msg_pkey on ams_msg pn_msg
(cost=0.43..7.70 rows=1 width=12) (actual
time=0.008..0.008 rows=0 loops=12)
Index Cond: (id = ams_msg_asset.msg_id)
Filter: ((message_type =
'structured'::ams_message_type) AND
(structured_type =
'pursuit_notification'::ams_structured_type))
Rows Removed by Filter: 1
-> Index Scan using amsnew_msg_pkey on ams_msg oi_msg
(cost=0.43..8.45 rows=1 width=8) (actual time=0.011..0.011
rows=1 loops=3)
Index Cond: (id = pn_msg.parent_id)
Filter: (date >= '2014-06-05 00:00:00-04'::timestamp with
time zone)
Rows Removed by Filter: 0
-> Nested Loop (cost=0.43..2792.16 rows=729 width=12) (actual
time=0.015..0.021 rows=1 loops=4)
-> WorkTable Scan on pn_downstream_thread
pn_downstream_thread_1 (cost=0.00..0.20 rows=10 width=8)
(actual time=0.001..0.002 rows=2 loops=4)
-> Index Scan using ix_ams_msg_parent_id on ams_msg pr_msg
(cost=0.43..278.47 rows=73 width=12) (actual time=0.007..0.008
rows=1 loops=6)
Index Cond: (parent_id = pn_downstream_thread_1.id)
Total runtime: 0.579 ms
(23 rows)

SELECT ams_msg.*
FROM ams_msg
WHERE ams_msg.id IN (SELECT min(pr_msg.id) AS id
FROM ams_msg AS pr_msg JOIN ams_ref AS pr_ref ON pr_msg.id = pr_ref.msg_id JOIN
ams_thread AS pr_thread ON pr_ref.thread_id = pr_thread.id JOIN auth_axialuser
AS pr_user ON pr_thread.user_id = pr_user.user_ptr_id JOIN auth_axialuser AS
pn_user ON pn_user.company_id = pr_user.company_id JOIN ams_thread AS pn_thread
ON pn_thread.user_id = pn_user.user_ptr_id JOIN ams_ref AS pn_ref ON
pn_ref.thread_id = pn_thread.id JOIN ams_msg AS pn_msg ON pn_ref.msg_id =
pn_msg.id JOIN ams_msg_asset AS pr_msg_asset ON pr_msg.id = pr_msg_asset.msg_id
JOIN ams_asset AS pr_asset ON pr_msg_asset.asset_id = pr_asset.id
WHERE pn_msg.message_type = 'structured' AND pn_msg.structured_type =
'pursuit_notification' AND pn_ref.header = 'to' AND pr_ref.header = 'from' AND
pr_msg.id IN (2648995, 2648996, 2648997, 2648998, 2649000, 2649002) AND
pn_msg.id IN (2648995, 2648996, 2648997, 2648998, 2649000, 2649002) AND
pr_asset.typ = 'opp' GROUP BY pr_asset.public_id);

Here's a refinement on the ids returned. It makes sure we only get certain
replies that are important for our metrics. Here I've manually substituted in
the six ids returned by the CTE query. It's also pretty fast.

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=251.44..259.48 rows=1 width=299) (actual time=2.872..2.888
rows=2 loops=1)
-> HashAggregate (cost=251.01..251.02 rows=1 width=8) (actual
time=2.859..2.860 rows=2 loops=1)
-> HashAggregate (cost=250.99..251.00 rows=1 width=40) (actual
time=2.848..2.850 rows=2 loops=1)
-> Nested Loop (cost=4.04..250.99 rows=1 width=40) (actual
time=1.597..2.829 rows=3 loops=1)
-> Nested Loop (cost=3.61..234.60 rows=2 width=16)
(actual time=1.569..2.760 rows=6 loops=1)
Join Filter: (pr_msg.id = pr_msg_asset.msg_id)
-> Nested Loop (cost=3.18..230.24 rows=1 width=16)
(actual time=1.555..2.694 rows=3 loops=1)
Join Filter: (pr_thread.user_id =
pr_user.user_ptr_id)
Rows Removed by Join Filter: 915
-> Nested Loop (cost=1.30..155.18 rows=6
width=24) (actual time=0.046..0.207 rows=6
loops=1)
-> Nested Loop (cost=0.87..105.96
rows=6 width=24) (actual
time=0.035..0.137 rows=6 loops=1)
-> Index Only Scan using
amsnew_msg_pkey on ams_msg pr_msg
(cost=0.43..33.84 rows=6 width=8)
(actual time=0.014..0.047 rows=6
loops=1)
Index Cond: (id = ANY
('{2648995,2648996,2648997,2648998,2649000,2649002}'::bigint[]))
Heap Fetches: 6
-> Index Scan using
idx_16556_unique_thread_ref on
ams_ref pr_ref (cost=0.43..12.00
rows=2 width=16) (actual
time=0.008..0.011 rows=1 loops=6)
Index Cond: (msg_id =
pr_msg.id)
Filter: (header =
'from'::text)
Rows Removed by Filter: 2
-> Index Scan using amsnew_thread_pkey
on ams_thread pr_thread (cost=0.43..8.19
rows=1 width=16) (actual
time=0.007..0.008 rows=1 loops=6)
Index Cond: (id = pr_ref.thread_id)
-> Materialize (cost=1.88..74.01 rows=12
width=8) (actual time=0.013..0.280 rows=153
loops=6)
-> Nested Loop (cost=1.88..73.95
rows=12 width=8) (actual
time=0.067..0.813 rows=153 loops=1)
-> Nested Loop (cost=1.59..62.13
rows=1 width=8) (actual
time=0.045..0.131 rows=2 loops=1)
-> Nested Loop
(cost=1.30..54.09 rows=1
width=8) (actual
time=0.033..0.103 rows=2
loops=1)
-> Nested Loop
(cost=0.87..45.89
rows=1 width=8) (actual
time=0.021..0.074
rows=2 loops=1)
-> Index Scan
using
amsnew_msg_pkey
on ams_msg pn_msg

(cost=0.43..33.87
rows=1 width=8)
(actual
time=0.010..0.043
rows=2 loops=1)
Index Cond:
(id = ANY
('{2648995,2648996,2648997,2648998,2649000,2649002}'::bigint[]))
Filter:
((message_type
=
'structured'::ams_message_type)
AND
(structured_type
=
'pursuit_notification'::ams_structured_type))
Rows
Removed by
Filter: 4
-> Index Scan
using
idx_16556_unique_thread_ref
on ams_ref pn_ref

(cost=0.43..12.00
rows=2 width=16)
(actual
time=0.007..0.010
rows=1 loops=2)
Index Cond:
(msg_id =
pn_msg.id)
Filter:
(header =
'to'::text)
Rows
Removed by
Filter: 2
-> Index Scan using
amsnew_thread_pkey on
ams_thread pn_thread
(cost=0.43..8.19 rows=1
width=16) (actual
time=0.009..0.009
rows=1 loops=2)
Index Cond: (id =
pn_ref.thread_id)
-> Index Scan using
auth_axialuser_pkey on
auth_axialuser pn_user
(cost=0.29..8.02 rows=1
width=16) (actual
time=0.008..0.009 rows=1
loops=2)
Index Cond:
(user_ptr_id =
pn_thread.user_id)
-> Index Scan using
idx_16590_auth_axialuser_543518c6
on auth_axialuser pr_user
(cost=0.29..11.80 rows=2 width=16)
(actual time=0.012..0.215 rows=76
loops=2)
Index Cond: (company_id =
pn_user.company_id)
-> Index Only Scan using amsnew_msg_asset_pkey on
ams_msg_asset pr_msg_asset (cost=0.43..4.34 rows=2
width=16) (actual time=0.007..0.014 rows=2 loops=3)
Index Cond: (msg_id = pr_ref.msg_id)
Heap Fetches: 6
-> Index Scan using amsnew_asset_pkey on ams_asset
pr_asset (cost=0.42..8.18 rows=1 width=40) (actual
time=0.007..0.008 rows=0 loops=6)
Index Cond: (id = pr_msg_asset.asset_id)
Filter: (typ = 'opp'::text)
Rows Removed by Filter: 0
-> Index Scan using amsnew_msg_pkey on ams_msg (cost=0.43..8.45 rows=1
width=299) (actual time=0.007..0.008 rows=1 loops=2)
Index Cond: (id = (min(pr_msg.id)))
Total runtime: 3.271 ms
(49 rows)

So I tried two different approaches to combining them. One uses JOIN, one uses
subselect. Both are very very slow.

WITH RECURSIVE pn_downstream_thread(id, parent_id) AS
(SELECT pn_msg.id AS id, pn_msg.parent_id AS parent_id
FROM ams_msg AS pn_msg JOIN ams_msg_asset ON pn_msg.id = ams_msg_asset.msg_id
JOIN ams_asset ON ams_asset.id = ams_msg_asset.asset_id JOIN ams_msg AS oi_msg
ON oi_msg.id = pn_msg.parent_id
WHERE pn_msg.message_type = 'structured' AND pn_msg.structured_type =
'pursuit_notification' AND ams_asset.typ = 'tp' AND ams_asset.public_id =
'59c89bdcaf6711e3b67f12313b0a607d' AND oi_msg.date >= '2014-06-05T00:00:00'
UNION SELECT pr_msg.id AS id, pr_msg.parent_id AS parent_id
FROM ams_msg AS pr_msg JOIN pn_downstream_thread ON pr_msg.parent_id =
pn_downstream_thread.id)
SELECT ams_msg.*
FROM ams_msg
WHERE ams_msg.id IN (SELECT min(pr_msg.id) AS id
FROM ams_msg AS pr_msg JOIN ams_ref AS pr_ref ON pr_msg.id = pr_ref.msg_id JOIN
ams_thread AS pr_thread ON pr_ref.thread_id = pr_thread.id JOIN auth_axialuser
AS pr_user ON pr_thread.user_id = pr_user.user_ptr_id JOIN auth_axialuser AS
pn_user ON pn_user.company_id = pr_user.company_id JOIN ams_thread AS pn_thread
ON pn_thread.user_id = pn_user.user_ptr_id JOIN ams_ref AS pn_ref ON
pn_ref.thread_id = pn_thread.id JOIN ams_msg AS pn_msg ON pn_ref.msg_id =
pn_msg.id JOIN ams_msg_asset AS pr_msg_asset ON pr_msg.id = pr_msg_asset.msg_id
JOIN ams_asset AS pr_asset ON pr_msg_asset.asset_id = pr_asset.id
JOIN pn_downstream_thread as cte_1 ON pn_msg.id = cte_1.id
JOIN pn_downstream_thread as cte_2 ON pr_msg.id = cte_2.id
WHERE pn_msg.message_type = 'structured' AND pn_msg.structured_type =
'pursuit_notification' AND pn_ref.header = 'to' AND pr_ref.header = 'from' AND
pr_asset.typ = 'opp' GROUP BY pr_asset.public_id);

QUERY
PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=483389.42..483397.46 rows=1 width=299) (actual time=700374.934..700374.954 rows=2 loops=1)
CTE pn_downstream_thread
-> Recursive Union (cost=1.71..28135.55 rows=7291 width=12) (actual time=0.126..0.473 rows=6 loops=1)
-> Nested Loop (cost=1.71..68.15 rows=1 width=12) (actual time=0.118..0.342 rows=2 loops=1)
-> Nested Loop (cost=1.28..59.69 rows=1 width=12) (actual time=0.103..0.280 rows=3 loops=1)
-> Nested Loop (cost=0.85..21.12 rows=5 width=8) (actual time=0.058..0.108 rows=12 loops=1)
-> Index Scan using idx_16485_unique_asset_typ_id on ams_asset (cost=0.42..8.45 rows=1 width=8)
(actual time=0.040..0.042 rows=1 loops=1)
Index Cond: ((typ = 'tp'::text) AND (public_id = '59c89bdcaf6711e3b67f12313b0a607d'::text))
-> Index Scan using idx_16551_asset_id on ams_msg_asset (cost=0.43..11.26 rows=141 width=16)
(actual time=0.011..0.034 rows=12 loops=1)
Index Cond: (asset_id = ams_asset.id)
-> Index Scan using amsnew_msg_pkey on ams_msg pn_msg_1 (cost=0.43..7.70 rows=1 width=12) (actual
time=0.011..0.011 rows=0 loops=12)
Index Cond: (id = ams_msg_asset.msg_id)
Filter: ((message_type = 'structured'::ams_message_type) AND (structured_type =
'pursuit_notification'::ams_structured_type))
Rows Removed by Filter: 1
-> Index Scan using amsnew_msg_pkey on ams_msg oi_msg (cost=0.43..8.45 rows=1 width=8) (actual
time=0.012..0.016 rows=1 loops=3)
Index Cond: (id = pn_msg_1.parent_id)
Filter: (date >= '2014-06-05 00:00:00-04'::timestamp with time zone)
Rows Removed by Filter: 0
-> Nested Loop (cost=0.43..2792.16 rows=729 width=12) (actual time=0.017..0.024 rows=1 loops=4)
-> WorkTable Scan on pn_downstream_thread (cost=0.00..0.20 rows=10 width=8) (actual time=0.001..0.002 rows=2
loops=4)
-> Index Scan using ix_ams_msg_parent_id on ams_msg pr_msg_1 (cost=0.43..278.47 rows=73 width=12) (actual
time=0.008..0.009 rows=1 loops=6)
Index Cond: (parent_id = pn_downstream_thread.id)
-> HashAggregate (cost=455253.44..455253.45 rows=1 width=8) (actual time=700374.910..700374.912 rows=2 loops=1)
-> HashAggregate (cost=455253.42..455253.43 rows=1 width=40) (actual time=700374.896..700374.898 rows=2 loops=1)
-> Nested Loop (cost=455045.13..455253.41 rows=1 width=40) (actual time=700374.790..700374.870 rows=3 loops=1)
-> Hash Join (cost=455044.71..455245.22 rows=1 width=16) (actual time=700374.767..700374.789 rows=6
loops=1)
Hash Cond: (cte_1.id = pn_ref.msg_id)
-> CTE Scan on pn_downstream_thread cte_1 (cost=0.00..145.82 rows=7291 width=8) (actual
time=0.130..0.139 rows=6 loops=1)
-> Hash (cost=455042.62..455042.62 rows=167 width=32) (actual time=700374.614..700374.614 rows=10
loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 1kB
-> Nested Loop (cost=454436.25..455042.62 rows=167 width=32) (actual
time=700374.496..700374.591 rows=10 loops=1)
-> Merge Join (cost=454435.82..454628.24 rows=95 width=40) (actual
time=700374.442..700374.475 rows=5 loops=1)
Merge Cond: (pr_msg.id = cte_2.id)
-> Sort (cost=453822.21..453899.72 rows=31002 width=32) (actual
time=622310.591..667805.360 rows=26231614 loops=1)
Sort Key: pr_msg.id
Sort Method: external merge Disk: 1077000kB
-> Hash Join (cost=318038.61..450767.45 rows=31002 width=32) (actual
time=306327.528..396943.344 rows=26231614 loops=1)
Hash Cond: (pr_msg.id = pr_ref.msg_id)
-> Seq Scan on ams_msg pr_msg (cost=0.00..89947.41 rows=2374141
width=8) (actual time=0.263..4658.827 rows=2374141 loops=1)
-> Hash (cost=317469.09..317469.09 rows=31002 width=24) (actual
time=306237.993..306237.993 rows=26231614 loops=1)
Buckets: 2048 Batches: 2048 (originally 2) Memory Usage: 1025kB
-> Hash Join (cost=155156.55..317469.09 rows=31002 width=24)
(actual time=132410.113..263949.902 rows=26231614 loops=1)
Hash Cond: (pr_ref.thread_id = pr_thread.id)
-> Seq Scan on ams_ref pr_ref (cost=0.00..129630.14
rows=2370235 width=16) (actual time=0.015..13992.997
rows=2374141 loops=1)
Filter: (header = 'from'::text)
Rows Removed by Filter: 2378202
-> Hash (cost=154104.02..154104.02 rows=57322 width=24)
(actual time=131698.305..131698.305 rows=26078188 loops=1)
Buckets: 2048 Batches: 2048 (originally 4) Memory
Usage: 1025kB
-> Hash Join (cost=2953.57..154104.02 rows=57322
width=24) (actual time=5513.152..77126.605
rows=26078188 loops=1)
Hash Cond: (pr_thread.user_id =
pr_user.user_ptr_id)
-> Seq Scan on ams_thread pr_thread
(cost=0.00..134142.62 rows=4382562 width=16)
(actual time=0.004..16796.421 rows=4383993
loops=1)
-> Hash (cost=2944.69..2944.69 rows=710
width=24) (actual time=5512.309..5512.309
rows=29576 loops=1)
Buckets: 1024 Batches: 2 (originally 1)
Memory Usage: 1025kB
-> Nested Loop (cost=444.65..2944.69
rows=710 width=24) (actual
time=1089.878..5451.100 rows=29576
loops=1)
-> Nested Loop
(cost=444.36..2341.93 rows=51
width=24) (actual
time=1079.548..5112.162 rows=4433
loops=1)
-> Nested Loop
(cost=444.07..1867.94 rows=59
width=24) (actual
time=1079.478..5051.058
rows=4440 loops=1)
-> Nested Loop
(cost=443.64..1383.99
rows=59 width=24)
(actual
time=1052.732..3461.278
rows=4440 loops=1)
-> Bitmap Heap
Scan on ams_msg
pn_msg
(cost=443.20..674.81
rows=59 width=8)
(actual
time=1015.754..1039.104
rows=4438 loops=1)
Recheck
Cond:
((structured_type
=
'pursuit_notification'::ams_structured_type)
AND
(message_type
=
'structured'::ams_message_type))
->
BitmapAnd
(cost=443.20..443.20
rows=59
width=0)
(actual
time=1015.538..1015.538
rows=0
loops=1)
->
Bitmap
Index
Scan
on
ix_ams_msg_structured_type

(cost=0.00..221.46
rows=11871
width=0)
(actual
time=1.298..1.298
rows=4438
loops=1)
Index
Cond:
(structured_type
=
'pursuit_notification'::ams_structured_type)
->
Bitmap
Index
Scan on
ix_ams_msg_message_type

(cost=0.00..221.46
rows=11871
width=0)
(actual
time=1014.074..1014.074
rows=2354849
loops=1)
Index
Cond:
(message_type
=
'structured'::ams_message_type)
-> Index Scan
using
idx_16556_unique_thread_ref
on ams_ref pn_ref
(cost=0.43..12.00
rows=2 width=16)
(actual
time=0.437..0.541
rows=1 loops=4438)
Index Cond:
(msg_id =
pn_msg.id)
Filter:
(header =
'to'::text)
Rows Removed
by Filter: 1
-> Index Scan using
amsnew_thread_pkey on
ams_thread pn_thread
(cost=0.43..8.19 rows=1
width=16) (actual
time=0.352..0.354 rows=1
loops=4440)
Index Cond: (id =
pn_ref.thread_id)
-> Index Scan using
auth_axialuser_pkey on
auth_axialuser pn_user
(cost=0.29..8.02 rows=1
width=16) (actual
time=0.008..0.009 rows=1
loops=4440)
Index Cond: (user_ptr_id
= pn_thread.user_id)
-> Index Scan using
idx_16590_auth_axialuser_543518c6 on
auth_axialuser pr_user
(cost=0.29..11.80 rows=2 width=16)
(actual time=0.046..0.062 rows=7
loops=4433)
Index Cond: (company_id =
pn_user.company_id)
-> Sort (cost=613.61..631.83 rows=7291 width=8) (actual time=0.405..0.413 rows=8
loops=1)
Sort Key: cte_2.id
Sort Method: quicksort Memory: 25kB
-> CTE Scan on pn_downstream_thread cte_2 (cost=0.00..145.82 rows=7291
width=8) (actual time=0.006..0.369 rows=6 loops=1)
-> Index Only Scan using amsnew_msg_asset_pkey on ams_msg_asset pr_msg_asset
(cost=0.43..4.34 rows=2 width=16) (actual time=0.012..0.015 rows=2 loops=5)
Index Cond: (msg_id = pr_msg.id)
Heap Fetches: 10
-> Index Scan using amsnew_asset_pkey on ams_asset pr_asset (cost=0.42..8.18 rows=1 width=40) (actual
time=0.009..0.009 rows=0 loops=6)
Index Cond: (id = pr_msg_asset.asset_id)
Filter: (typ = 'opp'::text)
Rows Removed by Filter: 0
-> Index Scan using amsnew_msg_pkey on ams_msg (cost=0.43..8.45 rows=1 width=299) (actual time=0.013..0.014 rows=1 loops=2)
Index Cond: (id = (min(pr_msg.id)))
Total runtime: 700954.434 ms
(88 rows)

WITH RECURSIVE pn_downstream_thread(id, parent_id) AS
(SELECT pn_msg.id AS id, pn_msg.parent_id AS parent_id
FROM ams_msg AS pn_msg JOIN ams_msg_asset ON pn_msg.id = ams_msg_asset.msg_id JOIN ams_asset ON ams_asset.id =
ams_msg_asset.asset_id JOIN ams_msg AS oi_msg ON oi_msg.id = pn_msg.parent_id
WHERE pn_msg.message_type = 'structured' AND pn_msg.structured_type = 'pursuit_notification' AND ams_asset.typ = 'tp' AND
ams_asset.public_id = '59c89bdcaf6711e3b67f12313b0a607d' AND oi_msg.date >= '2014-06-05T00:00:00' UNION SELECT pr_msg.id AS id,
pr_msg.parent_id AS parent_id
FROM ams_msg AS pr_msg JOIN pn_downstream_thread ON pr_msg.parent_id = pn_downstream_thread.id)
SELECT ams_msg.*
FROM ams_msg
WHERE ams_msg.id IN (SELECT min(pr_msg.id) AS id
FROM ams_msg AS pr_msg JOIN ams_ref AS pr_ref ON pr_msg.id = pr_ref.msg_id JOIN ams_thread AS pr_thread ON pr_ref.thread_id =
pr_thread.id JOIN auth_axialuser AS pr_user ON pr_thread.user_id = pr_user.user_ptr_id JOIN auth_axialuser AS pn_user ON
pn_user.company_id = pr_user.company_id JOIN ams_thread AS pn_thread ON pn_thread.user_id = pn_user.user_ptr_id JOIN ams_ref AS
pn_ref ON pn_ref.thread_id = pn_thread.id JOIN ams_msg AS pn_msg ON pn_ref.msg_id = pn_msg.id JOIN ams_msg_asset AS pr_msg_asset
ON pr_msg.id = pr_msg_asset.msg_id JOIN ams_asset AS pr_asset ON pr_msg_asset.asset_id = pr_asset.id
WHERE pn_msg.message_type = 'structured' AND pn_msg.structured_type = 'pursuit_notification' AND pn_ref.header = 'to' AND
pr_ref.header = 'from' AND pr_msg.id IN (SELECT pn_downstream_thread.id FROM pn_downstream_thread) AND pn_msg.id IN (SELECT
pn_downstream_thread.id FROM pn_downstream_thread) AND pr_asset.typ = 'opp' GROUP BY pr_asset.public_id);

QUERY
PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=512435.29..514092.87 rows=1187070 width=299) (actual time=379071.802..379071.823 rows=2 loops=1)
CTE pn_downstream_thread
-> Recursive Union (cost=1.71..28135.55 rows=7291 width=12) (actual time=0.170..0.489 rows=6 loops=1)
-> Nested Loop (cost=1.71..68.15 rows=1 width=12) (actual time=0.158..0.356 rows=2 loops=1)
-> Nested Loop (cost=1.28..59.69 rows=1 width=12) (actual time=0.133..0.302 rows=3 loops=1)
-> Nested Loop (cost=0.85..21.12 rows=5 width=8) (actual time=0.074..0.114 rows=12 loops=1)
-> Index Scan using idx_16485_unique_asset_typ_id on ams_asset (cost=0.42..8.45 rows=1 width=8)
(actual time=0.048..0.049 rows=1 loops=1)
Index Cond: ((typ = 'tp'::text) AND (public_id = '59c89bdcaf6711e3b67f12313b0a607d'::text))
-> Index Scan using idx_16551_asset_id on ams_msg_asset (cost=0.43..11.26 rows=141 width=16)
(actual time=0.014..0.030 rows=12 loops=1)
Index Cond: (asset_id = ams_asset.id)
-> Index Scan using amsnew_msg_pkey on ams_msg pn_msg_1 (cost=0.43..7.70 rows=1 width=12) (actual
time=0.013..0.013 rows=0 loops=12)
Index Cond: (id = ams_msg_asset.msg_id)
Filter: ((message_type = 'structured'::ams_message_type) AND (structured_type =
'pursuit_notification'::ams_structured_type))
Rows Removed by Filter: 1
-> Index Scan using amsnew_msg_pkey on ams_msg oi_msg (cost=0.43..8.45 rows=1 width=8) (actual
time=0.013..0.014 rows=1 loops=3)
Index Cond: (id = pn_msg_1.parent_id)
Filter: (date >= '2014-06-05 00:00:00-04'::timestamp with time zone)
Rows Removed by Filter: 0
-> Nested Loop (cost=0.43..2792.16 rows=729 width=12) (actual time=0.017..0.024 rows=1 loops=4)
-> WorkTable Scan on pn_downstream_thread pn_downstream_thread_2 (cost=0.00..0.20 rows=10 width=8) (actual
time=0.002..0.003 rows=2 loops=4)
-> Index Scan using ix_ams_msg_parent_id on ams_msg pr_msg_1 (cost=0.43..278.47 rows=73 width=12) (actual
time=0.008..0.009 rows=1 loops=6)
Index Cond: (parent_id = pn_downstream_thread_2.id)
-> HashAggregate (cost=484299.31..484301.31 rows=200 width=8) (actual time=379071.753..379071.756 rows=2 loops=1)
-> HashAggregate (cost=484286.30..484292.08 rows=578 width=40) (actual time=379071.729..379071.739 rows=2 loops=1)
-> Hash Join (cost=467127.91..484283.41 rows=578 width=40) (actual time=379071.557..379071.701 rows=3 loops=1)
Hash Cond: (pr_msg_asset.asset_id = pr_asset.id)
-> Hash Join (cost=451410.54..468055.19 rows=13610 width=16) (actual time=378945.800..378945.923 rows=6
loops=1)
Hash Cond: (pr_msg_asset.msg_id = pr_msg.id)
-> Nested Loop (cost=164.48..1039.46 rows=2084476 width=24) (actual time=0.552..0.720 rows=12
loops=1)
-> HashAggregate (cost=164.05..166.05 rows=200 width=8) (actual time=0.527..0.539 rows=6
loops=1)
-> CTE Scan on pn_downstream_thread (cost=0.00..145.82 rows=7291 width=8) (actual
time=0.175..0.507 rows=6 loops=1)
-> Index Only Scan using amsnew_msg_asset_pkey on ams_msg_asset pr_msg_asset (cost=0.43..4.35
rows=2 width=16) (actual time=0.016..0.021 rows=2 loops=6)
Index Cond: (msg_id = pn_downstream_thread.id)
Heap Fetches: 12
-> Hash (cost=451052.30..451052.30 rows=15501 width=16) (actual time=378945.150..378945.150 rows=2396
loops=1)
Buckets: 2048 Batches: 1 Memory Usage: 113kB
-> Hash Join (cost=318207.16..451052.30 rows=15501 width=16) (actual
time=275956.121..378936.272 rows=2396 loops=1)
Hash Cond: (pn_ref.msg_id = pn_downstream_thread_1.id)
-> Hash Join (cost=318038.61..450767.45 rows=31002 width=32) (actual
time=273432.709..346500.045 rows=26231614 loops=1)
Hash Cond: (pr_msg.id = pr_ref.msg_id)
-> Seq Scan on ams_msg pr_msg (cost=0.00..89947.41 rows=2374141 width=8) (actual
time=0.020..3929.575 rows=2374141 loops=1)
-> Hash (cost=317469.09..317469.09 rows=31002 width=24) (actual
time=273355.257..273355.257 rows=26231614 loops=1)
Buckets: 2048 Batches: 2048 (originally 2) Memory Usage: 1025kB
-> Hash Join (cost=155156.55..317469.09 rows=31002 width=24) (actual
time=124914.036..223312.662 rows=26231614 loops=1)
Hash Cond: (pr_ref.thread_id = pr_thread.id)
-> Seq Scan on ams_ref pr_ref (cost=0.00..129630.14 rows=2370235
width=16) (actual time=0.010..13122.603 rows=2374141 loops=1)
Filter: (header = 'from'::text)
Rows Removed by Filter: 2378202
-> Hash (cost=154104.02..154104.02 rows=57322 width=24) (actual
time=124778.594..124778.594 rows=26078188 loops=1)
Buckets: 2048 Batches: 2048 (originally 4) Memory Usage: 1025kB
-> Hash Join (cost=2953.57..154104.02 rows=57322 width=24)
(actual time=3043.653..74317.926 rows=26078188 loops=1)
Hash Cond: (pr_thread.user_id = pr_user.user_ptr_id)
-> Seq Scan on ams_thread pr_thread (cost=0.00..134142.62
rows=4382562 width=16) (actual time=0.007..18718.597
rows=4383993 loops=1)
-> Hash (cost=2944.69..2944.69 rows=710 width=24) (actual
time=3043.531..3043.531 rows=29576 loops=1)
Buckets: 1024 Batches: 2 (originally 1) Memory Usage:
1025kB
-> Nested Loop (cost=444.65..2944.69 rows=710
width=24) (actual time=1004.410..2996.868 rows=29576
loops=1)
-> Nested Loop (cost=444.36..2341.93 rows=51
width=24) (actual time=1004.393..2837.055
rows=4433 loops=1)
-> Nested Loop (cost=444.07..1867.94
rows=59 width=24) (actual
time=1004.373..2784.782 rows=4440 loops=1)
-> Nested Loop
(cost=443.64..1383.99 rows=59
width=24) (actual
time=1004.350..1565.038 rows=4440
loops=1)
-> Bitmap Heap Scan on ams_msg
pn_msg (cost=443.20..674.81
rows=59 width=8) (actual
time=1004.309..1017.421
rows=4438 loops=1)
Recheck Cond:
((structured_type =
'pursuit_notification'::ams_structured_type)
AND (message_type =
'structured'::ams_message_type))
-> BitmapAnd
(cost=443.20..443.20
rows=59 width=0) (actual
time=1004.116..1004.116
rows=0 loops=1)
-> Bitmap Index
Scan on
ix_ams_msg_structured_type
(cost=0.00..221.46
rows=11871 width=0)
(actual
time=1.056..1.056
rows=4438 loops=1)
Index Cond:
(structured_type
=
'pursuit_notification'::ams_structured_type)
-> Bitmap Index
Scan on
ix_ams_msg_message_type
(cost=0.00..221.46
rows=11871 width=0)
(actual
time=1002.880..1002.880
rows=2354849
loops=1)
Index Cond:
(message_type
=
'structured'::ams_message_type)
-> Index Scan using
idx_16556_unique_thread_ref on
ams_ref pn_ref
(cost=0.43..12.00 rows=2
width=16) (actual
time=0.098..0.119 rows=1
loops=4438)
Index Cond: (msg_id =
pn_msg.id)
Filter: (header =
'to'::text)
Rows Removed by Filter: 1
-> Index Scan using
amsnew_thread_pkey on ams_thread
pn_thread (cost=0.43..8.19 rows=1
width=16) (actual time=0.270..0.271
rows=1 loops=4440)
Index Cond: (id =
pn_ref.thread_id)
-> Index Scan using auth_axialuser_pkey on
auth_axialuser pn_user (cost=0.29..8.02
rows=1 width=16) (actual time=0.006..0.008
rows=1 loops=4440)
Index Cond: (user_ptr_id =
pn_thread.user_id)
-> Index Scan using
idx_16590_auth_axialuser_543518c6 on
auth_axialuser pr_user (cost=0.29..11.80 rows=2
width=16) (actual time=0.008..0.022 rows=7
loops=4433)
Index Cond: (company_id =
pn_user.company_id)
-> Hash (cost=166.05..166.05 rows=200 width=8) (actual time=0.042..0.042 rows=6 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 1kB
-> HashAggregate (cost=164.05..166.05 rows=200 width=8) (actual time=0.025..0.033
rows=6 loops=1)
-> CTE Scan on pn_downstream_thread pn_downstream_thread_1 (cost=0.00..145.82
rows=7291 width=8) (actual time=0.002..0.008 rows=6 loops=1)
-> Hash (cost=15018.62..15018.62 rows=34380 width=40) (actual time=100.730..100.730 rows=34318 loops=1)
Buckets: 2048 Batches: 4 Memory Usage: 675kB
-> Bitmap Heap Scan on ams_asset pr_asset (cost=1378.87..15018.62 rows=34380 width=40) (actual
time=10.715..53.246 rows=34318 loops=1)
Recheck Cond: (typ = 'opp'::text)
-> Bitmap Index Scan on idx_16485_unique_asset_typ_id (cost=0.00..1370.27 rows=34380 width=0)
(actual time=10.507..10.507 rows=34318 loops=1)
Index Cond: (typ = 'opp'::text)
-> Index Scan using amsnew_msg_pkey on ams_msg (cost=0.43..8.27 rows=1 width=299) (actual time=0.022..0.024 rows=1 loops=2)
Index Cond: (id = (min(pr_msg.id)))
Total runtime: 379072.791 ms
(89 rows)

Have I made an obvious mistake in how I combined these two queries? I've read that a CTE is supposed to be separately optimized by
the query planner, and since the basic CTE takes only a few ms to run, I'm at a loss as to why the combination takes orders of
magnitude longer.

Here's the table schemas:

Table "public.ams_msg"
Column | Type | Modifiers
--------------------------+------------------------------+---------------------------------------------------------
id | bigint | not null default nextval('amsnew_msg_id_seq'::regclass)
public_id | text | not null
smtp_id | text | not null
original_id | text |
date | timestamp with time zone |
scheduled_mailbox | text |
user_msg_id | bigint |
user_id | bigint |
ext_email_id | bigint |
subject | text |
created_on | timestamp with time zone | not null
parent_id | integer |
message_type | ams_message_type |
unstructured_type | ams_unstructured_type |
structured_type | ams_structured_type |
system_notification_type | ams_system_notification_type |
Indexes:
"amsnew_msg_pkey" PRIMARY KEY, btree (id)
"idx_16544_ix_amsnew_msg_public_id" UNIQUE, btree (public_id)
"idx_16544_original_id" UNIQUE, btree (original_id)
"idx_16544_smtp_id" UNIQUE, btree (smtp_id)
"idx_16544_user_msg_id" UNIQUE, btree (user_msg_id)
"idx_16544_ext_email_id" btree (ext_email_id)
"idx_16544_user_id" btree (user_id)
"ix_ams_msg_message_type" btree (message_type)
"ix_ams_msg_parent_id" btree (parent_id)
"ix_ams_msg_structured_type" btree (structured_type)
"ix_ams_msg_system_notification_type" btree (system_notification_type)
"ix_ams_msg_unstructured_type" btree (unstructured_type)
Foreign-key constraints:
"ams_msg_parent_id_fkey" FOREIGN KEY (parent_id) REFERENCES ams_msg(id)
"amsnew_msg_ibfk_1" FOREIGN KEY (user_msg_id) REFERENCES message_center_usermessage(id)
"amsnew_msg_ibfk_2" FOREIGN KEY (user_id) REFERENCES auth_axialuser(user_ptr_id)
"amsnew_msg_ibfk_3" FOREIGN KEY (ext_email_id) REFERENCES ams_ext_email(id)

Table "public.ams_ref"
Column | Type | Modifiers
-------------+--------+---------------------------------------------------------
id | bigint | not null default nextval('amsnew_ref_id_seq'::regclass)
public_id | text | not null
thread_id | bigint | not null
msg_id | bigint | not null
status | text | not null
sub_status | text | not null
ext_smtp_id | text |
checkpoint | text |
header | text | not null
bounce_id | bigint |
inbound_id | bigint |
Indexes:
"amsnew_ref_pkey" PRIMARY KEY, btree (id)
"idx_16556_public_id" UNIQUE, btree (public_id)
"idx_16556_unique_thread_ref" UNIQUE, btree (msg_id, thread_id)
"idx_16556_ams_ref_inbound_fk" btree (inbound_id)
"idx_16556_bounce_id" btree (bounce_id)
"idx_16556_ix_amsnew_ref_ext_smtp_id" btree (ext_smtp_id)
"idx_16556_ix_amsnew_ref_header" btree (header)
"idx_16556_ix_amsnew_ref_status" btree (status)
"idx_16556_thread_id" btree (thread_id)
Foreign-key constraints:
"ams_ref_inbound_fk" FOREIGN KEY (inbound_id) REFERENCES ams_inbound(id)
"amsnew_ref_ibfk_1" FOREIGN KEY (thread_id) REFERENCES ams_thread(id)
"amsnew_ref_ibfk_2" FOREIGN KEY (msg_id) REFERENCES ams_msg(id)
"amsnew_ref_ibfk_3" FOREIGN KEY (bounce_id) REFERENCES ams_bounce(id)

Table "public.ams_thread"
Column | Type | Modifiers
--------------+--------------------------+------------------------------------------------------------
id | bigint | not null default nextval('amsnew_thread_id_seq'::regclass)
public_id | text | not null
subject | text |
important | boolean | not null
user_id | bigint |
ext_email_id | bigint |
created_on | timestamp with time zone | not null
Indexes:
"amsnew_thread_pkey" PRIMARY KEY, btree (id)
"idx_16565_unique_user_thread" UNIQUE, btree (user_id, public_id, ext_email_id)
"idx_16565_ext_email_id" btree (ext_email_id)
"idx_16565_ix_amsnew_thread_public_id" btree (public_id)
Foreign-key constraints:
"amsnew_thread_ibfk_1" FOREIGN KEY (user_id) REFERENCES auth_axialuser(user_ptr_id)
"amsnew_thread_ibfk_2" FOREIGN KEY (ext_email_id) REFERENCES ams_ext_email(id)

Table "public.auth_axialuser"
Column | Type | Modifiers
------------------------------+--------------------------+-----------------------------------------
user_ptr_id | bigint | not null
created_on | timestamp with time zone | not null
updated_on | timestamp with time zone | not null
company_id | bigint | not null default (2)::bigint
phone | text | not null
title | text | not null
timezone | text | not null default 'US/Eastern'::text
salesforce_id | text |
mobile_phone | text | not null
author_page | text | not null
salesforce_sync | boolean | not null
salesforce_last_message | text | not null
is_email_verified | boolean | not null
is_generated_from_opp_invite | boolean | not null
tos_date | timestamp with time zone |
has_profile_picture | boolean | not null
unique_slug_id | bigint | not null
registration_source | text | default ''::text
slug | text | not null
slug_display | text | not null
ams_from_email | text |
ams_fwd_email | text |
company_location_id | bigint |
page_rank | numeric(21,20) | not null default 0.00000000000000000000
primary_group_id | bigint |
valuation_id | integer |
Indexes:
"auth_axialuser_pkey" PRIMARY KEY, btree (user_ptr_id)
"idx_16590_auth_axialuser_slug" UNIQUE, btree (slug)
"idx_16590_primary_group_id_uniq" UNIQUE, btree (primary_group_id)
"idx_16590_unique_slug_id" UNIQUE, btree (unique_slug_id)
"idx_16590_auth_axialuser_543518c6" btree (company_id)
"idx_16590_auth_axialuser_company_location" btree (company_location_id)
"idx_16590_auth_axialuser_salesforce_id" btree (salesforce_id)
Foreign-key constraints:
"auth_axialuser_company_location" FOREIGN KEY (company_location_id) REFERENCES company_location(id)
"auth_axialuser_ibfk_1" FOREIGN KEY (primary_group_id) REFERENCES newauth_group(id)
"company_id_refs_id_7ff35742" FOREIGN KEY (company_id) REFERENCES company_company(id)
"company_id_refs_id_e971af8800ca8be" FOREIGN KEY (company_id) REFERENCES company_company(id)
"unique_slug_id_refs_id_30c7ff8b75ddc5ac" FOREIGN KEY (unique_slug_id) REFERENCES common_slug(id)
"user_ptr_id_refs_id_2a7cd755" FOREIGN KEY (user_ptr_id) REFERENCES auth_user(id)

Table "public.ams_msg_asset"
Column | Type | Modifiers
----------+--------+-----------
msg_id | bigint | not null
asset_id | bigint | not null
Indexes:
"amsnew_msg_asset_pkey" PRIMARY KEY, btree (msg_id, asset_id)
"idx_16551_asset_id" btree (asset_id)
Foreign-key constraints:
"amsnew_msg_asset_ibfk_1" FOREIGN KEY (msg_id) REFERENCES ams_msg(id)
"amsnew_msg_asset_ibfk_2" FOREIGN KEY (asset_id) REFERENCES ams_asset(id)

Table "public.ams_asset"
Column | Type | Modifiers
-----------+--------+-----------------------------------------------------------
id | bigint | not null default nextval('amsnew_asset_id_seq'::regclass)
typ | text | not null
public_id | text | not null
title | text | not null
Indexes:
"amsnew_asset_pkey" PRIMARY KEY, btree (id)
"idx_16485_unique_asset_typ_id" UNIQUE, btree (typ, public_id)
"idx_16485_ix_amsnew_asset_public_id" btree (public_id)