Notifications timeline times out (after migration)
Basically for some users they get a 500 error when trying to access notifications. It's all too familiar:
[error] #PID<0.10581.0> running Pleroma.Web.Endpoint (connection #PID<0.10580.0>, stream id 1) terminated
Server: localhost:3036 (http)
Request: GET /api/v1/notifications
** (exit) an exception was raised:
** (DBConnection.ConnectionError) tcp recv: closed (the connection was closed by the pool, possibly due to a timeout or because the pool has been terminated)
(ecto_sql 3.4.5) lib/ecto/adapters/sql.ex:593: Ecto.Adapters.SQL.raise_sql_call_error/1
(ecto_sql 3.4.5) lib/ecto/adapters/sql.ex:526: Ecto.Adapters.SQL.execute/5
(ecto 3.4.5) lib/ecto/repo/queryable.ex:192: Ecto.Repo.Queryable.execute/4
(ecto 3.4.5) lib/ecto/repo/queryable.ex:17: Ecto.Repo.Queryable.all/3
(pleroma 2.0.50-2479-g014f91c1-develop+dev) lib/pleroma/pagination.ex:40: Pleroma.Pagination.fetch_paginated/4
(pleroma 2.0.50-2479-g014f91c1-develop+dev) lib/pleroma/web/mastodon_api/controllers/notification_controller.ex:59: Pleroma.Web.MastodonAPI.NotificationController.index/2
(pleroma 2.0.50-2479-g014f91c1-develop+dev) lib/pleroma/web/mastodon_api/controllers/notification_controller.ex:5: Pleroma.Web.MastodonAPI.NotificationController.action/2
(pleroma 2.0.50-2479-g014f91c1-develop+dev) lib/pleroma/web/mastodon_api/controllers/notification_controller.ex:5: Pleroma.Web.MastodonAPI.NotificationController.phoenix_controller_pipeline/2
(pleroma 2.0.50-2479-g014f91c1-develop+dev) lib/pleroma/web/endpoint.ex:5: Pleroma.Web.Endpoint.instrument/4
(phoenix 1.4.17) lib/phoenix/router.ex:288: Phoenix.Router.__call__/2
(pleroma 2.0.50-2479-g014f91c1-develop+dev) lib/pleroma/web/endpoint.ex:5: Pleroma.Web.Endpoint.plug_builder_call/2
(pleroma 2.0.50-2479-g014f91c1-develop+dev) lib/plug/debugger.ex:132: Pleroma.Web.Endpoint."call (overridable 3)"/2
(pleroma 2.0.50-2479-g014f91c1-develop+dev) lib/pleroma/web/endpoint.ex:5: Pleroma.Web.Endpoint.call/2
(phoenix 1.4.17) lib/phoenix/endpoint/cowboy2_handler.ex:42: Phoenix.Endpoint.Cowboy2Handler.init/4
(cowboy 2.8.0) /home/alex/Projects/pleroma/deps/cowboy/src/cowboy_handler.erl:37: :cowboy_handler.execute/2
(cowboy 2.8.0) /home/alex/Projects/pleroma/deps/cowboy/src/cowboy_stream_h.erl:300: :cowboy_stream_h.execute/3
(cowboy 2.8.0) /home/alex/Projects/pleroma/deps/cowboy/src/cowboy_stream_h.erl:291: :cowboy_stream_h.request_process/3
(stdlib 3.13) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
Anyway, here's the query. Any clue what could be going on with it?
SELECT n0."id", n0."seen", n0."type", n0."user_id", n0."activity_id", n0."inserted_at", n0."updated_at", a1."id", a1."data", a1."local", a1."actor", a1."recipients", a1."inserted_at", a1."updated_at", o2."id", o2."data", o2."inserted_at", o2."updated_at" FROM "notifications" AS n0 INNER JOIN "activities" AS a1 ON a1."id" = n0."activity_id" LEFT OUTER JOIN "objects" AS o2 ON (o2."data"->>'id') = COALESCE(a1."data"->'object'->>'id', a1."data"->>'object') LEFT OUTER JOIN "thread_mutes" AS t3 ON (t3."user_id" = '{00000173-e5c9-0f1e-191e-1eab842d0000}') AND (t3."context" = a1."data"->>'context') WHERE (n0."user_id" = '{00000173-e5c9-0f1e-191e-1eab842d0000}') AND (a1."actor" not in (SELECT ap_id FROM users WHERE deactivated = 'true')) AND (NOT (a1."actor" = ANY('{}'))) AND (t3."user_id" IS NULL) AND (NOT (a1."actor" = ANY('{"https://gab.com/users/good4politics", "https://cliterati.club/users/AmyDyess", "https://freespeechextremist.com/users/snail"}'))) AND (NOT (substring(a1."actor" from '.*://([^/]*)') = ANY('{"kiwifarms.cc", "cliterati.club", "fedibird.com", "social.quodverum.com"}')) OR
a1."actor" = ANY(SELECT ap_id FROM users AS u INNER JOIN following_relationships AS fr
ON u.id = fr.following_id WHERE fr.follower_id = '{00000173-e5c9-0f1e-191e-1eab842d0000}' AND fr.state = 2)
) AND (n0."type" = ANY('{"mention", "follow", "follow_request", "reblog", "favourite", "move", "pleroma:emoji_reaction"}')) ORDER BY n0."id" desc nulls last LIMIT 20;
EXPLAIN ANALYZE:
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=506531.40..506531.45 rows=20 width=2217) (actual time=17750.536..17750.540 rows=20 loops=1)
-> Sort (cost=506531.40..506531.53 rows=52 width=2217) (actual time=17750.533..17750.536 rows=20 loops=1)
Sort Key: n0.id DESC NULLS LAST
Sort Method: top-N heapsort Memory: 169kB
-> Nested Loop Anti Join (cost=33101.54..506530.02 rows=52 width=2217) (actual time=16023.523..17750.208 rows=147 loops=1)
Join Filter: ((t3.context)::text = (a1.data ->> 'context'::text))
Rows Removed by Join Filter: 3675
-> Nested Loop Left Join (cost=33101.54..506502.57 rows=52 width=2217) (actual time=16023.466..17748.988 rows=147 loops=1)
-> Hash Join (cost=33100.98..506457.81 rows=52 width=909) (actual time=16023.377..17745.708 rows=147 loops=1)
Hash Cond: (a1.id = n0.activity_id)
-> Seq Scan on activities a1 (cost=32904.64..490049.34 rows=1621161 width=848) (actual time=26.871..17338.072 rows=3244429 loops=1)
Filter: (((actor)::text <> ALL ('{}'::text[])) AND (NOT (hashed SubPlan 1)) AND ((actor)::text <> ALL ('{https://gab.com/users/good4politics,https://cliterati.club/users/AmyDyess,https://freespeechextremist.com/users/snail}'::text[])) AND (("substring"((actor)::text, '.*://([^/]*)'::text) <> ALL ('{kiwifarms.cc,cliterati.club,fedibird.com,social.quodverum.com}'::text[])) OR (hashed SubPlan 2)))
Rows Removed by Filter: 28084
SubPlan 1
-> Index Scan using users_deactivated_index on users (cost=0.42..3660.21 rows=4656 width=36) (actual time=0.073..21.593 rows=4615 loops=1)
Index Cond: (deactivated = true)
Filter: deactivated
SubPlan 2
-> Gather (cost=1412.00..29200.80 rows=12793 width=36) (actual time=3.280..36.568 rows=13623 loops=1)
Workers Planned: 2
Workers Launched: 2
-> Nested Loop (cost=412.00..26921.50 rows=5330 width=36) (actual time=0.974..34.260 rows=4541 loops=3)
-> Parallel Bitmap Heap Scan on following_relationships fr (cost=411.58..4239.55 rows=5330 width=16) (actual time=0.932..6.778 rows=4541 loops=3)
Recheck Cond: (follower_id = '00000173-e5c9-0f1e-191e-1eab842d0000'::uuid)
Filter: (state = 2)
Heap Blocks: exact=1046
-> Bitmap Index Scan on following_relationships_follower_id_following_id_index (cost=0.00..408.38 rows=12795 width=0) (actual time=1.977..1.977 rows=13623 loops=1)
Index Cond: (follower_id = '00000173-e5c9-0f1e-191e-1eab842d0000'::uuid)
-> Index Scan using users_pkey on users u (cost=0.42..4.26 rows=1 width=52) (actual time=0.005..0.005 rows=1 loops=13623)
Index Cond: (id = fr.following_id)
-> Hash (cost=195.02..195.02 rows=106 width=61) (actual time=0.911..0.911 rows=147 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 22kB
-> Bitmap Heap Scan on notifications n0 (cost=5.41..195.02 rows=106 width=61) (actual time=0.116..0.793 rows=147 loops=1)
Recheck Cond: (user_id = '00000173-e5c9-0f1e-191e-1eab842d0000'::uuid)
Filter: (type = ANY ('{mention,follow,follow_request,reblog,favourite,move,pleroma:emoji_reaction}'::notification_type[]))
Heap Blocks: exact=90
-> Bitmap Index Scan on notifications_user_id_id_desc_nulls_last_index (cost=0.00..5.39 rows=147 width=0) (actual time=0.065..0.065 rows=147 loops=1)
Index Cond: (user_id = '00000173-e5c9-0f1e-191e-1eab842d0000'::uuid)
-> Index Scan using objects_unique_apid_index on objects o2 (cost=0.56..0.86 rows=1 width=1308) (actual time=0.020..0.020 rows=1 loops=147)
Index Cond: ((data ->> 'id'::text) = COALESCE(((a1.data -> 'object'::text) ->> 'id'::text), (a1.data ->> 'object'::text)))
-> Materialize (cost=0.00..4.76 rows=25 width=69) (actual time=0.000..0.002 rows=25 loops=147)
-> Seq Scan on thread_mutes t3 (cost=0.00..4.64 rows=25 width=69) (actual time=0.009..0.035 rows=25 loops=1)
Filter: (user_id = '00000173-e5c9-0f1e-191e-1eab842d0000'::uuid)
Rows Removed by Filter: 106
Planning time: 12.393 ms
Execution time: 17751.596 ms
(46 rows)
EDIT: In the meantime I added timeout: 30_000
to Pleroma.Repo config, and it does work eventually (after about 20 seconds, the default is 15 apparently).
Edited by Alex Gleason