On Tue, Apr 17, 2018, at 19:31, Thomas Munro wrote:
> On Wed, Apr 18, 2018 at 11:01 AM, Jonathan Rudenberg
> <jonat...@titanous.com> wrote:
> > On Tue, Apr 17, 2018, at 18:38, Thomas Munro wrote:
> >> Thanks, that would be much appreciated, as would any clues about what
> >> workload you're running.  Do you know what the query plan looks like
> >> for the queries that crashed?
> >
> > Yep, I think I know approximately what it looked like, I've attached a 
> > lightly redacted plan. All of the hung queries were running some variant of 
> > this plan as far as I can tell.
> 
> Hmm, that isn't a parallel query.  I was expecting to see "Gather" and
> "Parallel" in there.

Oops, I'm really sorry about that. I only have the first part of the hung 
queries, and there are a few variants. Here's one that's parallel.
                                                                                
                                                                                
                                                                                
                        QUERY PLAN                                              
                                                                                
                                                                                
                                                          
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=13229.50..13229.51 rows=2 width=4336) (actual time=23.486..23.515 
rows=316 loops=1)
   Sort Key: assets."position"
   Sort Method: quicksort  Memory: 1293kB
   CTE assets
     ->  HashAggregate  (cost=13060.31..13075.88 rows=1557 width=864) (actual 
time=19.064..19.601 rows=1242 loops=1)
           Group Key: assets_7.id, assets_7.name, assets_7.description, 
assets_7.asset_key, assets_7.type, assets_7.created_at, assets_7.updated_at, 
assets_7.deleted_at, assets_7.redacted_id, assets_7.section_id, 
assets_7."position", assets_7.creator_id, assets_7.modifier_id, assets_7.data, 
assets_7.thumbnail_override, assets_7.availability_start, 
assets_7.availability_end, assets_7.availability
           ->  Append  (cost=6383.09..12990.25 rows=1557 width=864) (actual 
time=6.781..17.848 rows=1242 loops=1)
                 ->  CTE Scan on assets assets_7  (cost=6383.09..6451.83 
rows=15 width=864) (actual time=6.780..8.180 rows=1242 loops=1)
                       Filter: (redacted_id = 32456)
                       CTE assets
                         ->  HashAggregate  (cost=6352.54..6383.09 rows=3055 
width=864) (actual time=6.775..7.270 rows=1242 loops=1)
                               Group Key: assets_1.id, assets_1.name, 
assets_1.description, assets_1.asset_key, assets_1.type, assets_1.created_at, 
assets_1.updated_at, assets_1.deleted_at, assets_1.redacted_id, 
assets_1.section_id, assets_1."position", assets_1.creator_id, 
assets_1.modifier_id, assets_1.data, assets_1.thumbnail_override, 
assets_1.availability_start, assets_1.availability_end, assets_1.availability
                               ->  Append  (cost=1.41..6215.07 rows=3055 
width=864) (actual time=0.137..5.495 rows=1261 loops=1)
                                     ->  Nested Loop  (cost=1.41..1514.55 
rows=1 width=248) (actual time=0.026..0.026 rows=0 loops=1)
                                           ->  Nested Loop  (cost=0.98..5.71 
rows=1 width=4) (actual time=0.026..0.026 rows=0 loops=1)
                                                 ->  Nested Loop  
(cost=0.70..5.14 rows=1 width=8) (actual time=0.026..0.026 rows=0 loops=1)
                                                       ->  Index Scan using 
index_user_id_on_permissible_type on user_permissions  (cost=0.42..2.64 rows=1 
width=4) (actual time=0.025..0.025 rows=0 loops=1)
                                                             Index Cond: 
((user_id = 98789) AND ((permissible_type)::text = 'Organization'::text))
                                                             Filter: 
((permission_level)::text = 'guest'::text)
                                                       ->  Index Only Scan 
using organizations_pkey on organizations  (cost=0.28..2.50 rows=1 width=4) 
(never executed)
                                                             Index Cond: (id = 
user_permissions.permissible_id)
                                                             Heap Fetches: 0
                                                 ->  Index Scan using 
index_redacteds_on_organization_id on redacteds redacteds_1  (cost=0.28..0.43 
rows=1 width=8) (never executed)
                                                       Index Cond: 
(organization_id = organizations.id)
                                                       Filter: ((deleted_at IS 
NULL) AND (id = 32456))
                                           ->  Index Scan using 
index_assets_on_redacted_id on assets assets_1  (cost=0.43..1493.79 rows=1505 
width=248) (never executed)
                                                 Index Cond: (redacted_id = 
32456)
                                                 Filter: (availability = 0)
                                     ->  Nested Loop  (cost=1.13..1513.99 
rows=1505 width=248) (actual time=0.037..0.037 rows=0 loops=1)
                                           ->  Nested Loop  (cost=0.70..5.16 
rows=1 width=4) (actual time=0.037..0.037 rows=0 loops=1)
                                                 ->  Index Scan using 
redacteds_pkey on redacteds redacteds_2  (cost=0.28..2.50 rows=1 width=4) 
(actual time=0.017..0.017 rows=1 loops=1)
                                                       Index Cond: (id = 32456)
                                                       Filter: (deleted_at IS 
NULL)
                                                 ->  Index Scan using 
unique_index_on_user_permissions on user_permissions user_permissions_1  
(cost=0.42..2.65 rows=1 width=4) (actual time=0.019..0.019 rows=0 loops=1)
                                                       Index Cond: 
(((permissible_type)::text = 'Redacted'::text) AND (permissible_id = 32456) AND 
(user_id = 98789))
                                                       Filter: 
((permission_level)::text = 'guest'::text)
                                           ->  Index Scan using 
index_assets_on_redacted_id on assets assets_2  (cost=0.43..1493.79 rows=1505 
width=248) (never executed)
                                                 Index Cond: (redacted_id = 
32456)
                                                 Filter: (availability = 0)
                                     ->  Nested Loop  (cost=1.55..67.28 rows=1 
width=248) (actual time=0.073..5.253 rows=1261 loops=1)
                                           ->  Nested Loop  (cost=1.12..11.54 
rows=84 width=4) (actual time=0.055..0.770 rows=1331 loops=1)
                                                 ->  Nested Loop  
(cost=0.70..5.14 rows=1 width=8) (actual time=0.025..0.041 rows=3 loops=1)
                                                       ->  Index Scan using 
index_user_id_on_permissible_type on user_permissions user_permissions_2  
(cost=0.42..2.64 rows=1 width=4) (actual time=0.011..0.014 rows=3 loops=1)
                                                             Index Cond: 
((user_id = 98789) AND ((permissible_type)::text = 'Collection'::text))
                                                             Filter: 
((permission_level)::text = 'guest'::text)
                                                       ->  Index Scan using 
collections_pkey on collections  (cost=0.28..2.50 rows=1 width=4) (actual 
time=0.008..0.008 rows=1 loops=3)
                                                             Index Cond: (id = 
user_permissions_2.permissible_id)
                                                             Filter: 
(deleted_at IS NULL)
                                                 ->  Index Scan using 
index_collection_asset_associations_on_collection_id on 
collection_asset_associations collection_asset_associations_1  (cost=0.42..4.90 
rows=149 width=8) (actual time=0.015..0.198 rows=444 loops=3)
                                                       Index Cond: 
(collection_id = collections.id)
                                                       Filter: 
(((availability_start < '2018-04-17 21:06:57.643933'::timestamp without time 
zone) OR (availability_start IS NULL)) AND ((availability_end > '2018-04-17 
21:06:57.643933'::timestamp without time zone) OR (availability_end IS NULL)))
                                                       Rows Removed by Filter: 4
                                           ->  Index Scan using assets_pkey on 
assets assets_3  (cost=0.43..0.66 rows=1 width=248) (actual time=0.003..0.003 
rows=1 loops=1331)
                                                 Index Cond: (id = 
collection_asset_associations_1.asset_id)
                                                 Filter: ((redacted_id = 32456) 
AND (availability = 0))
                                                 Rows Removed by Filter: 0
                                     ->  Nested Loop  (cost=1.41..1511.09 
rows=1 width=248) (actual time=0.013..0.013 rows=0 loops=1)
                                           ->  Nested Loop  (cost=0.98..5.71 
rows=1 width=4) (actual time=0.013..0.013 rows=0 loops=1)
                                                 ->  Nested Loop  
(cost=0.70..5.14 rows=1 width=8) (actual time=0.013..0.013 rows=0 loops=1)
                                                       ->  Index Scan using 
index_user_id_on_permissible_type on user_permissions user_permissions_3  
(cost=0.42..2.64 rows=1 width=4) (actual time=0.012..0.012 rows=0 loops=1)
                                                             Index Cond: 
((user_id = 98789) AND ((permissible_type)::text = 'Organization'::text))
                                                             Filter: 
((permission_level)::text = ANY ('{collaborator,admin,owner}'::text[]))
                                                       ->  Index Only Scan 
using organizations_pkey on organizations organizations_1  (cost=0.28..2.50 
rows=1 width=4) (never executed)
                                                             Index Cond: (id = 
user_permissions_3.permissible_id)
                                                             Heap Fetches: 0
                                                 ->  Index Scan using 
index_redacteds_on_organization_id on redacteds redacteds_3  (cost=0.28..0.43 
rows=1 width=8) (never executed)
                                                       Index Cond: 
(organization_id = organizations_1.id)
                                                       Filter: ((deleted_at IS 
NULL) AND (id = 32456))
                                           ->  Index Scan using 
index_assets_on_redacted_id on assets assets_4  (cost=0.43..1489.92 rows=1546 
width=248) (never executed)
                                                 Index Cond: (redacted_id = 
32456)
                                     ->  Nested Loop  (cost=1.13..1510.54 
rows=1546 width=248) (actual time=0.022..0.022 rows=0 loops=1)
                                           ->  Nested Loop  (cost=0.70..5.16 
rows=1 width=4) (actual time=0.022..0.022 rows=0 loops=1)
                                                 ->  Index Scan using 
redacteds_pkey on redacteds redacteds_4  (cost=0.28..2.50 rows=1 width=4) 
(actual time=0.010..0.010 rows=1 loops=1)
                                                       Index Cond: (id = 32456)
                                                       Filter: (deleted_at IS 
NULL)
                                                 ->  Index Scan using 
unique_index_on_user_permissions on user_permissions user_permissions_4  
(cost=0.42..2.65 rows=1 width=4) (actual time=0.011..0.011 rows=0 loops=1)
                                                       Index Cond: 
(((permissible_type)::text = 'Redacted'::text) AND (permissible_id = 32456) AND 
(user_id = 98789))
                                                       Filter: 
((permission_level)::text = ANY ('{collaborator,admin,owner}'::text[]))
                                           ->  Index Scan using 
index_assets_on_redacted_id on assets assets_5  (cost=0.43..1489.92 rows=1546 
width=248) (never executed)
                                                 Index Cond: (redacted_id = 
32456)
                                     ->  Nested Loop  (cost=1.55..67.07 rows=1 
width=248) (actual time=0.012..0.012 rows=0 loops=1)
                                           ->  Nested Loop  (cost=1.12..11.54 
rows=84 width=4) (actual time=0.011..0.011 rows=0 loops=1)
                                                 ->  Nested Loop  
(cost=0.70..5.14 rows=1 width=8) (actual time=0.011..0.011 rows=0 loops=1)
                                                       ->  Index Scan using 
index_user_id_on_permissible_type on user_permissions user_permissions_5  
(cost=0.42..2.64 rows=1 width=4) (actual time=0.011..0.011 rows=0 loops=1)
                                                             Index Cond: 
((user_id = 98789) AND ((permissible_type)::text = 'Collection'::text))
                                                             Filter: 
((permission_level)::text = ANY ('{collaborator,admin,owner}'::text[]))
                                                             Rows Removed by 
Filter: 3
                                                       ->  Index Scan using 
collections_pkey on collections collections_1  (cost=0.28..2.50 rows=1 width=4) 
(never executed)
                                                             Index Cond: (id = 
user_permissions_5.permissible_id)
                                                             Filter: 
(deleted_at IS NULL)
                                                 ->  Index Scan using 
index_collection_asset_associations_on_collection_id on 
collection_asset_associations collection_asset_associations_2  (cost=0.42..4.90 
rows=149 width=8) (never executed)
                                                       Index Cond: 
(collection_id = collections_1.id)
                                                       Filter: 
(((availability_start < '2018-04-17 21:06:57.649733'::timestamp without time 
zone) OR (availability_start IS NULL)) AND ((availability_end > '2018-04-17 
21:06:57.649733'::timestamp without time zone) OR (availability_end IS NULL)))
                                           ->  Index Scan using assets_pkey on 
assets assets_6  (cost=0.43..0.66 rows=1 width=248) (never executed)
                                                 Index Cond: (id = 
collection_asset_associations_2.asset_id)
                                                 Filter: (redacted_id = 32456)
                 ->  Nested Loop  (cost=0.71..1511.34 rows=1505 width=248) 
(actual time=0.011..0.011 rows=0 loops=1)
                       ->  Index Scan using redacteds_pkey on redacteds 
redacteds_5  (cost=0.28..2.50 rows=1 width=4) (actual time=0.011..0.011 rows=0 
loops=1)
                             Index Cond: (id = 32456)
                             Filter: ((deleted_at IS NULL) AND ((privacy)::text 
= 'public'::text))
                             Rows Removed by Filter: 1
                       ->  Index Scan using index_assets_on_redacted_id on 
assets assets_8  (cost=0.43..1493.79 rows=1505 width=248) (never executed)
                             Index Cond: (redacted_id = 32456)
                             Filter: (availability = 0)
                 ->  Gather  (cost=1029.60..5011.51 rows=37 width=248) (actual 
time=9.560..9.560 rows=0 loops=1)
                       Workers Planned: 1
                       Workers Launched: 1
                       ->  Nested Loop  (cost=29.60..4007.81 rows=22 width=248) 
(actual time=5.488..5.488 rows=0 loops=2)
                             ->  Nested Loop  (cost=29.32..3934.16 rows=245 
width=252) (actual time=0.324..4.098 rows=889 loops=2)
                                   ->  Parallel Bitmap Heap Scan on assets 
assets_9  (cost=28.90..1697.87 rows=885 width=248) (actual time=0.273..1.597 
rows=744 loops=2)
                                         Recheck Cond: (redacted_id = 32456)
                                         Filter: (availability = 0)
                                         Heap Blocks: exact=767
                                         ->  Bitmap Index Scan on 
index_assets_on_redacted_id  (cost=0.00..28.52 rows=1546 width=0) (actual 
time=0.380..0.380 rows=1487 loops=1)
                                               Index Cond: (redacted_id = 32456)
                                   ->  Index Scan using 
index_collection_asset_associations_on_asset_id on 
collection_asset_associations collection_asset_associations_3  (cost=0.42..2.48 
rows=5 width=8) (actual time=0.003..0.003 rows=1 loops=1487)
                                         Index Cond: (asset_id = assets_9.id)
                                         Filter: (((availability_start < 
'2018-04-17 21:06:57.652961'::timestamp without time zone) OR 
(availability_start IS NULL)) AND ((availability_end > '2018-04-17 
21:06:57.652961'::timestamp without time zone) OR (availability_end IS NULL)))
                                         Rows Removed by Filter: 0
                             ->  Index Scan using collections_pkey on 
collections collections_2  (cost=0.28..0.30 rows=1 width=4) (actual 
time=0.001..0.001 rows=0 loops=1778)
                                   Index Cond: (id = 
collection_asset_associations_3.collection_id)
                                   Filter: ((deleted_at IS NULL) AND public)
                                   Rows Removed by Filter: 1
   ->  Nested Loop Left Join  (cost=2.28..153.61 rows=2 width=4336) (actual 
time=19.248..22.243 rows=316 loops=1)
         ->  Nested Loop Left Join  (cost=1.85..147.61 rows=1 width=4255) 
(actual time=19.222..21.777 rows=51 loops=1)
               ->  Nested Loop Left Join  (cost=1.42..147.04 rows=1 width=3400) 
(actual time=19.190..21.394 rows=51 loops=1)
                     ->  Nested Loop  (cost=0.99..142.82 rows=1 width=1778) 
(actual time=19.167..21.090 rows=50 loops=1)
                           ->  Nested Loop  (cost=0.57..140.16 rows=1 
width=1778) (actual time=19.146..20.899 rows=50 loops=1)
                                 ->  Nested Loop  (cost=0.28..138.75 rows=1 
width=1778) (actual time=19.106..20.730 rows=50 loops=1)
                                       ->  CTE Scan on assets  
(cost=0.00..136.24 rows=1 width=864) (actual time=19.088..20.578 rows=50 
loops=1)
                                             Filter: ((redacted_id = 32456) AND 
(section_id = 679855) AND (id = ANY 
('{6703952,6703955,6714907,6714913,6767146,6767723,6767758,6767764,6767858,6767864,6767866,6767938,6767945,6767999,6716005,6716007,6730106,6730107,6730128,6730145,6730146,6730147,6730676,6730677,6730176,6730177,6730201,6730204,6730207,6730199,6730214,6730267,6730216,6730217,6730218,6730220,6730221,6730222,6730223,6730225,6730226,6730227,6730228,6735195,6735197,6735200,6735202,6735236,6735241,6735247}'::integer[])))
                                             Rows Removed by Filter: 1192
                                       ->  Index Scan using redacteds_pkey on 
redacteds  (cost=0.28..2.50 rows=1 width=914) (actual time=0.002..0.002 rows=1 
loops=50)
                                             Index Cond: (id = 32456)
                                             Filter: (deleted_at IS NULL)
                                 ->  Index Only Scan using sections_pkey on 
sections  (cost=0.29..1.41 rows=1 width=4) (actual time=0.003..0.003 rows=1 
loops=50)
                                       Index Cond: (id = 163863)
                                       Heap Fetches: 50
                           ->  Index Scan using 
index_collection_assets_on_collection_id_and_asset_id on 
collection_asset_associations  (cost=0.42..2.65 rows=1 width=4) (actual 
time=0.003..0.003 rows=1 loops=50)
                                 Index Cond: ((collection_id = 67459) AND 
(asset_id = assets.id))
                                 Filter: (((availability_start < '2018-04-17 
21:06:57.631399'::timestamp without time zone) OR (availability_start IS NULL)) 
AND ((availability_end > '2018-04-17 21:06:57.631399'::timestamp without time 
zone) OR (availability_end IS NULL)))
                     ->  Index Scan using index_attachments_on_asset_id on 
attachments  (cost=0.43..4.16 rows=6 width=1622) (actual time=0.005..0.005 
rows=1 loops=50)
                           Index Cond: (asset_id = assets.id)
               ->  Index Scan using index_versions_on_item_type_and_item_id on 
versions  (cost=0.43..0.56 rows=1 width=855) (actual time=0.006..0.006 rows=1 
loops=51)
                     Index Cond: (((item_type)::text = 'Attachment'::text) AND 
(item_id = attachments.id))
         ->  Index Scan using index_tags_on_asset_id on tags  (cost=0.43..5.81 
rows=19 width=81) (actual time=0.004..0.006 rows=6 loops=51)
               Index Cond: (asset_id = assets.id)
 Planning time: 7.210 ms
 Execution time: 24.650 ms
(149 rows)

Reply via email to