Slow notifications when instance blocking
First of all, thanks a lot for Pleroma ! It's nice being able to run an ActivityPub software that doesn't eat all your resources and actually speaks the protocol.
Environment
- Installation type (OTP or From Source): yunohost, so I guess it's a OPT install
- Pleroma version (could be found in the "Version" tab of settings in Pleroma-FE): 255
- Elixir version (
elixir -v
for from source installations, N/A for OTP): N/A - Operating system: Debian
- PostgreSQL version (
psql -V
): Debian 13.13
Warning
I think it's ok to put my own id, but there's also some accounts/instances that I block, for a good reason (racist stuff). I advise not checking them out.
Bug description
I've been having slow (5-10s) notifications for a few weeks now, so I started investigating and it seems to be the database.
After setting the logs to :debug here's the relevant section:
ec 12 16:11:18 rako.space pleroma[2268146]: 16:11:18.737 request_id=F6AheyPiJNo6PgUA_B2x [debug] QUERY OK source="notifications" db=6815.4ms queue=0.4ms idle=1556.1ms
Dec 12 16:11:18 rako.space pleroma[2268146]: 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') = associated_object_id(a1."data") INNER JOIN "users" AS u3 ON u3."ap_id" = a1."actor" LEFT OUTER JOIN "thread_mutes" AS t4 ON (t4."user_id" = $1) AND (t4."context" = a1."data"->>'context') WHERE (n0."user_id" = $2) AND (u3."is_active") AND (NOT (a1."actor" = ANY($3))) AND (t4."user_id" IS NULL) AND (NOT (a1."actor" = ANY($4))) AND (NOT (substring(a1."actor" from '.*://([^/]*)') = ANY($5)) OR
Dec 12 16:11:18 rako.space pleroma[2268146]: a1."actor" = ANY(SELECT ap_id FROM users AS u INNER JOIN following_relationships AS fr
Dec 12 16:11:18 rako.space pleroma[2268146]: ON u.id = fr.following_id WHERE fr.follower_id = $6 AND fr.state = $7)
Dec 12 16:11:18 rako.space pleroma[2268146]: ) AND (n0."type" = ANY($8)) ORDER BY n0."id" desc nulls last LIMIT $9 ["ADVMFpVkzRniZTxHqC", "ADVMFpVkzRniZTxHqC", [], ["https://toot.community/users/pmroman", "https://pieville.net/users/charliebrownau"], ["pieville.net"], <<0, 0, 1, 125, 47, 220, 171, 120, 78, 29, 208, 24, 89, 222, 0, 0>>, 2, ["mention", "follow", "follow_request", "reblog", "favourite", "move", "pleroma:emoji_reaction", "poll", "update"], 20]
Which, reordered and with fields filled in, gives this (I assume the binary list is my id, because I don't know how to turn it into an id):
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') = associated_object_id(a1."data")
INNER JOIN "users" AS u3 ON u3."ap_id" = a1."actor"
LEFT OUTER JOIN "thread_mutes" AS t4 ON (t4."user_id" = '0000017d-2fdc-ab78-4e1d-d01859de0000')
AND (
t4."context" = a1."data" ->> 'context'
)
WHERE
(n0."user_id" = '0000017d-2fdc-ab78-4e1d-d01859de0000')
AND (u3."is_active")
AND (
NOT (
a1."actor" = ANY(ARRAY[''::text])
)
)
AND (t4."user_id" IS NULL)
AND (
NOT (
a1."actor" = ANY(ARRAY['https://toot.community/users/pmroman', 'https://pieville.net/users/charliebrownau'])
)
)
AND (
NOT (
substring(
a1."actor"
from
'.*://([^/]*)'
) = ANY(ARRAY['pieville.net'])
)
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 = '0000017d-2fdc-ab78-4e1d-d01859de0000'
AND fr.state = 2
)
)
AND (
n0."type" = ANY(ARRAY['mention'::notification_type, 'follow'::notification_type, 'follow_request'::notification_type, 'reblog'::notification_type, 'favourite'::notification_type, 'move'::notification_type, 'pleroma:emoji_reaction'::notification_type, 'poll'::notification_type, 'update'])
)
ORDER BY
n0."id" desc nulls last
LIMIT
20;
When run in my db it is indeed slow, here is the EXPLAIN ANALYZE VERBOSE of it:
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=127134.34..127134.39 rows=20 width=2051) (actual time=7208.379..7208.388 rows=20 loops=1)
Output: 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
-> Sort (cost=127134.34..127135.50 rows=465 width=2051) (actual time=7123.124..7123.131 rows=20 loops=1)
Output: 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
Sort Key: n0.id DESC NULLS LAST
Sort Method: top-N heapsort Memory: 161kB
-> Nested Loop Anti Join (cost=2663.89..127121.96 rows=465 width=2051) (actual time=4.663..7116.180 rows=2670 loops=1)
Output: 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
Join Filter: ((t4.context)::text = (a1.data ->> 'context'::text))
-> Nested Loop Left Join (cost=2663.75..127105.66 rows=465 width=2051) (actual time=4.651..7112.875 rows=2670 loops=1)
Output: 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
Inner Unique: true
-> Nested Loop (cost=2662.95..126472.83 rows=465 width=750) (actual time=3.593..6999.082 rows=2670 loops=1)
Output: 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
Inner Unique: true
-> Hash Join (cost=2662.52..125300.95 rows=1828 width=750) (actual time=3.511..6921.999 rows=2676 loops=1)
Output: 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
Hash Cond: (a1.id = n0.activity_id)
-> Seq Scan on public.activities a1 (cost=2532.70..121191.40 rows=1056385 width=689) (actual time=0.177..6600.496 rows=1055736 loops=1)
Output: a1.id, a1.data, a1.inserted_at, a1.updated_at, a1.local, a1.actor, a1.recipients
Filter: (((a1.actor)::text <> ALL ('{""}'::text[])) AND ((a1.actor)::text <> ALL ('{https://toot.community/users/pmroman,https://pieville.net/users/charliebrownau}'::text[])) AND (("substring"((a1.actor)::text, '.*://([^/]*)'::text) <> ALL ('{pieville.net}'::text[])) OR (hashed SubPlan 1)))
Rows Removed by Filter: 9
SubPlan 1
-> Nested Loop (cost=0.42..2531.92 rows=313 width=38) (never executed)
Output: u.ap_id
Inner Unique: true
-> Seq Scan on public.following_relationships fr (cost=0.00..14.20 rows=313 width=16) (never executed)
Output: fr.id, fr.follower_id, fr.following_id, fr.state, fr.inserted_at, fr.updated_at
Filter: ((fr.follower_id = '0000017d-2fdc-ab78-4e1d-d01859de0000'::uuid) AND (fr.state = 2))
-> Index Scan using users_pkey on public.users u (cost=0.42..8.04 rows=1 width=54) (never executed)
Output: u.ap_id, u.id
Index Cond: (u.id = fr.following_id)
-> Hash (cost=106.91..106.91 rows=1833 width=61) (actual time=2.733..2.734 rows=2677 loops=1)
Output: n0.id, n0.seen, n0.type, n0.user_id, n0.activity_id, n0.inserted_at, n0.updated_at
Buckets: 4096 (originally 2048) Batches: 1 (originally 1) Memory Usage: 283kB
-> Seq Scan on public.notifications n0 (cost=0.00..106.91 rows=1833 width=61) (actual time=0.028..1.404 rows=2677 loops=1)
Output: n0.id, n0.seen, n0.type, n0.user_id, n0.activity_id, n0.inserted_at, n0.updated_at
Filter: ((n0.user_id = '0000017d-2fdc-ab78-4e1d-d01859de0000'::uuid) AND (n0.type = ANY ('{mention,follow,follow_request,reblog,favourite,move,pleroma:emoji_reaction,poll,update}'::notification_type[])))
Rows Removed by Filter: 92
-> Index Scan using users_ap_id_index on public.users u3 (cost=0.42..0.64 rows=1 width=38) (actual time=0.026..0.026 rows=1 loops=2676)
Output: u3.ap_id
Index Cond: ((u3.ap_id)::text = (a1.actor)::text)
Filter: u3.is_active
Rows Removed by Filter: 0
-> Index Scan using objects_unique_apid_index on public.objects o2 (cost=0.80..1.36 rows=1 width=1301) (actual time=0.027..0.027 rows=1 loops=2670)
Output: o2.id, o2.data, o2.inserted_at, o2.updated_at
Index Cond: ((o2.data ->> 'id'::text) = (associated_object_id(a1.data))::text)
-> Materialize (cost=0.14..8.17 rows=1 width=516) (actual time=0.000..0.000 rows=0 loops=2670)
Output: t4.context
-> Index Only Scan using unique_index on public.thread_mutes t4 (cost=0.14..8.16 rows=1 width=516) (actual time=0.006..0.006 rows=0 loops=1)
Output: t4.context
Index Cond: (t4.user_id = '0000017d-2fdc-ab78-4e1d-d01859de0000'::uuid)
Heap Fetches: 0
Planning Time: 38.492 ms
JIT:
Functions: 49
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 36.191 ms, Inlining 0.000 ms, Optimization 2.982 ms, Emission 81.449 ms, Total 120.623 ms
Execution Time: 7386.114 ms
(59 rows)
I tried to hack around and I see it's this specific part that makes the whole thing crawl to a slow:
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 = '0000017d-2fdc-ab78-4e1d-d01859de0000'
AND fr.state = 2
)
When I remove it and run it, it is fast again. Here's the EXPLAIN ANALYZE VERBOSE:
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Limit (cost=2.07..705.06 rows=20 width=2051) (actual time=0.239..2.793 rows=20 loops=1)
Output: 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
-> Nested Loop Anti Join (cost=2.07..16311.38 rows=464 width=2051) (actual time=0.237..2.784 rows=20 loops=1)
Output: 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
Join Filter: ((t4.context)::text = (a1.data ->> 'context'::text))
-> Nested Loop Left Join (cost=1.93..16295.10 rows=464 width=2051) (actual time=0.229..2.755 rows=20 loops=1)
Output: 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
Inner Unique: true
-> Nested Loop (cost=1.13..15663.00 rows=464 width=750) (actual time=0.118..1.300 rows=20 loops=1)
Output: 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
Inner Unique: true
-> Nested Loop (cost=0.71..14492.76 rows=1824 width=750) (actual time=0.085..0.747 rows=20 loops=1)
Output: 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
Inner Unique: true
-> Index Scan using notifications_id_desc_nulls_last_index on public.notifications n0 (cost=0.28..259.33 rows=1833 width=61) (actual time=0.024..0.061 rows=20 loops=1)
Output: n0.id, n0.user_id, n0.activity_id, n0.seen, n0.inserted_at, n0.updated_at, n0.type
Filter: ((n0.user_id = '0000017d-2fdc-ab78-4e1d-d01859de0000'::uuid) AND (n0.type = ANY ('{mention,follow,follow_request,reblog,favourite,move,pleroma:emoji_reaction,poll,update}'::notification_type[])))
Rows Removed by Filter: 1
-> Index Scan using activities_pkey on public.activities a1 (cost=0.43..7.77 rows=1 width=689) (actual time=0.032..0.032 rows=1 loops=20)
Output: a1.id, a1.data, a1.inserted_at, a1.updated_at, a1.local, a1.actor, a1.recipients
Index Cond: (a1.id = n0.activity_id)
Filter: (((a1.actor)::text <> ALL ('{""}'::text[])) AND ((a1.actor)::text <> ALL ('{https://toot.community/users/pmroman,https://pieville.net/users/charliebrownau}'::text[])) AND ("substring"((a1.actor)::text, '.*://([^/]*)'::text) <> ALL ('{pieville.net}'::text[])))
-> Index Scan using users_ap_id_index on public.users u3 (cost=0.42..0.64 rows=1 width=38) (actual time=0.026..0.026 rows=1 loops=20)
Output: u3.ap_id
Index Cond: ((u3.ap_id)::text = (a1.actor)::text)
Filter: u3.is_active
-> Index Scan using objects_unique_apid_index on public.objects o2 (cost=0.80..1.36 rows=1 width=1301) (actual time=0.054..0.054 rows=1 loops=20)
Output: o2.id, o2.data, o2.inserted_at, o2.updated_at
Index Cond: ((o2.data ->> 'id'::text) = (associated_object_id(a1.data))::text)
-> Materialize (cost=0.14..8.17 rows=1 width=516) (actual time=0.001..0.001 rows=0 loops=20)
Output: t4.context
-> Index Only Scan using unique_index on public.thread_mutes t4 (cost=0.14..8.16 rows=1 width=516) (actual time=0.004..0.004 rows=0 loops=1)
Output: t4.context
Index Cond: (t4.user_id = '0000017d-2fdc-ab78-4e1d-d01859de0000'::uuid)
Heap Fetches: 0
Planning Time: 3.238 ms
Execution Time: 2.903 ms
(37 rows)
I don't know enough about the project and Elixir to be able to fix it myself right now, although I do wish I could. I also see there are some related issues ("slow query") but it doesn't look like they're related to notifications.
If anyone can have a look, thanks in advance !