On Tue, Apr 17, 2018, at 18:38, Thomas Munro wrote:
> I don't have any theories about how that could be going wrong right
> now, but I'm looking into it.
Thank you!
> > I don't have a backtrace yet, but I will provide them if/when the issue
> > happens again.
>
> 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.
Thanks again!
Jonathan
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=1896.13..1896.13 rows=2 width=4336) (actual time=29.396..29.447
rows=410 loops=1)
Sort Key: assets."position"
Sort Method: quicksort Memory: 1671kB
CTE assets
-> HashAggregate (cost=1861.88..1863.61 rows=173 width=864) (actual
time=23.328..23.883 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=853.88..1854.10 rows=173 width=864) (actual
time=10.871..22.002 rows=1242 loops=1)
-> CTE Scan on assets assets_7 (cost=853.88..861.60 rows=2
width=864) (actual time=10.870..12.339 rows=1242 loops=1)
Filter: (redacted_id = 32456)
CTE assets
-> HashAggregate (cost=850.45..853.88 rows=343
width=864) (actual time=10.867..11.392 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..835.02 rows=343
width=864) (actual time=0.380..9.456 rows=1261 loops=1)
-> Nested Loop (cost=1.41..174.78 rows=1
width=249) (actual time=0.046..0.046 rows=0 loops=1)
-> Nested Loop (cost=0.98..5.71
rows=1 width=4) (actual time=0.046..0.046 rows=0 loops=1)
-> Nested Loop
(cost=0.70..5.14 rows=1 width=8) (actual time=0.046..0.046 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.045..0.045 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..167.40 rows=167
width=249) (never executed)
Index Cond: (redacted_id =
32456)
Filter: (availability = 0)
-> Nested Loop (cost=1.13..174.22
rows=167 width=249) (actual time=0.067..0.067 rows=0 loops=1)
-> Nested Loop (cost=0.70..5.16
rows=1 width=4) (actual time=0.066..0.066 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.023..0.023 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.042..0.042 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..167.40 rows=167
width=249) (never executed)
Index Cond: (redacted_id =
32456)
Filter: (availability = 0)
-> Nested Loop (cost=1.55..67.28 rows=1
width=249) (actual time=0.267..9.147 rows=1261 loops=1)
-> Nested Loop (cost=1.12..11.54
rows=84 width=4) (actual time=0.221..1.282 rows=1331 loops=1)
-> Nested Loop
(cost=0.70..5.14 rows=1 width=8) (actual time=0.066..0.150 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.033..0.070 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.025..0.025 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.034..0.328 rows=444 loops=3)
Index Cond:
(collection_id = collections.id)
Filter:
(((availability_start < '2018-04-16 13:49:23.29558'::timestamp without time
zone) OR (availability_start IS NULL)) AND ((availability_end > '2018-04-16
13:49:23.29558'::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=249) (actual time=0.006..0.006
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..174.40 rows=1
width=249) (actual time=0.018..0.018 rows=0 loops=1)
-> Nested Loop (cost=0.98..5.71
rows=1 width=4) (actual time=0.017..0.017 rows=0 loops=1)
-> Nested Loop
(cost=0.70..5.14 rows=1 width=8) (actual time=0.016..0.016 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.016..0.016 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..166.97 rows=172
width=249) (never executed)
Index Cond: (redacted_id =
32456)
-> Nested Loop (cost=1.13..173.84
rows=172 width=249) (actual time=0.028..0.028 rows=0 loops=1)
-> Nested Loop (cost=0.70..5.16
rows=1 width=4) (actual time=0.028..0.028 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.014..0.014 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.012..0.012 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..166.97 rows=172
width=249) (never executed)
Index Cond: (redacted_id =
32456)
-> Nested Loop (cost=1.55..67.07 rows=1
width=249) (actual time=0.019..0.019 rows=0 loops=1)
-> Nested Loop (cost=1.12..11.54
rows=84 width=4) (actual time=0.019..0.019 rows=0 loops=1)
-> Nested Loop
(cost=0.70..5.14 rows=1 width=8) (actual time=0.018..0.018 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.018..0.018 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-16 13:49:23.298234'::timestamp without time
zone) OR (availability_start IS NULL)) AND ((availability_end > '2018-04-16
13:49:23.298234'::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=249) (never executed)
Index Cond: (id =
collection_asset_associations_2.asset_id)
Filter: (redacted_id = 32456)
-> Nested Loop (cost=0.71..171.57 rows=167 width=249)
(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.010..0.010 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..167.40 rows=167 width=249) (never executed)
Index Cond: (redacted_id = 32456)
Filter: (availability = 0)
-> Nested Loop (cost=1.13..819.19 rows=4 width=249) (actual
time=9.555..9.555 rows=0 loops=1)
-> Nested Loop (cost=0.85..805.67 rows=45 width=253)
(actual time=0.052..6.949 rows=1778 loops=1)
-> Index Scan using index_assets_on_redacted_id
on assets assets_9 (cost=0.43..167.40 rows=167 width=249) (actual
time=0.035..2.447 rows=1487 loops=1)
Index Cond: (redacted_id = 32456)
Filter: (availability = 0)
-> Index Scan using
index_collection_asset_associations_on_asset_id on
collection_asset_associations collection_asset_associations_3 (cost=0.42..3.77
rows=5 width=8) (actual time=0.002..0.003 rows=1 loops=1487)
Index Cond: (asset_id = assets_9.id)
Filter: (((availability_start < '2018-04-16
13:49:23.300161'::timestamp without time zone) OR (availability_start IS NULL))
AND ((availability_end > '2018-04-16 13:49:23.300161'::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..32.51 rows=2 width=4336) (actual
time=23.702..27.816 rows=410 loops=1)
-> Nested Loop Left Join (cost=1.85..26.51 rows=1 width=4255)
(actual time=23.660..26.965 rows=50 loops=1)
-> Nested Loop Left Join (cost=1.42..25.94 rows=1 width=3400)
(actual time=23.594..26.247 rows=50 loops=1)
-> Nested Loop (cost=0.99..21.72 rows=1 width=1778)
(actual time=23.547..25.455 rows=50 loops=1)
-> Nested Loop (cost=0.57..19.07 rows=1
width=1778) (actual time=23.524..25.243 rows=50 loops=1)
-> Nested Loop (cost=0.28..17.65 rows=1
width=1778) (actual time=23.436..25.030 rows=50 loops=1)
-> CTE Scan on assets
(cost=0.00..15.14 rows=1 width=864) (actual time=23.412..24.860 rows=50 loops=1)
Filter: ((redacted_id = 32456) AND
(section_id = 679855) AND (id = ANY
('{6703967,6703968,6703947,6714921,6714922,1689331,6714923,6767678,6767679,6767734,6767735,6767767,6767768,6767769,6767959,6767960,6767961,6716012,6716013,6716014,6716067,6716045,6716046,6716047,6716050,6730148,6730149,6730671,6730672,6730187,6730188,6730191,6730192,6730209,6730211,6732954,6732955,6732960,6732961,6735218,6735219,6735325,6735326,6735327,6735273,6737612,6746559,6746560,6746561,6746562}'::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.003 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.004 rows=1
loops=50)
Index Cond: (id = 679855)
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 = 6528) AND
(asset_id = assets.id))
Filter: (((availability_start < '2018-04-16
13:49:23.287216'::timestamp without time zone) OR (availability_start IS NULL))
AND ((availability_end > '2018-04-16 13:49:23.287216'::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.014..0.014
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.013..0.013 rows=1
loops=50)
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.007..0.012 rows=8 loops=50)
Index Cond: (asset_id = assets.id)
Planning time: 12.333 ms
Execution time: 30.771 ms
(143 rows)
