messages timeout

.md

Bonfire boundary EXISTS subquery is the dominant DB bottleneck under federation load

TL;DR

• Every page that checks "can user see this?" runs the same complex boundary EXISTS subquery (bonfire_boundaries_summary view). It's a 6-way cross-join + custom aggregate re-evaluated on every check.
• Under federation pressure, this subquery's cost compounds: federation workers hammer ap_object and a per-peer "silencing circle" lookup, saturating the DB pool. The boundary EXISTS queues behind them, normal pages slow, /messages specifically times out at 20 s (statement_timeout).
• /messages is the canary, not the patient. The same EXISTS runs on every feed, profile, thread, MRF filter, etc.

Original symptom (from production logs)

2026-05-11T11:48:49.920 [error] Postgrex.Protocol disconnected:
** (DBConnection.ConnectionError) client #PID<...>
   ({Phoenix.LiveView, Bonfire.UI.Messages.MessagesLive, ...})
   timed out because it queued and checked out the connection for longer than 20000ms

11:48:49.920 [warning] Slow database query: error db=20000ms repo=Elixir.Bonfire.Common.Repo
  SELECT s0."id", s0."thread_id" FROM (
    SELECT DISTINCT ON (sb2."thread_id") ...
    FROM bonfire_data_social_message sb0
    LEFT JOIN bonfire_data_social_activity sb1 ...
    WHERE EXISTS (... boundary subquery with agg_perms ...)
  ) ORDER BY ... LIMIT 21

** Elixir.Postgrex.Error: ERROR 57014 (query_canceled)
   canceling statement due to statement timeout

Bonfire.Messages.list_threads_paginated/4 @ deps/bonfire_messages/lib/messages.ex:397
Bonfire.Messages.LiveHandler.list_threads/3 @ deps/bonfire_ui_messages/lib/live_handlers/messages_live_handler.ex:307
Bonfire.UI.Messages.MessagesLive."mount" @ deps/bonfire_ui_messages/lib/views/messages_live.ex:32

What was happening in the same window

In the 30 s leading up to the timeout:

• 97 Oban federation jobs started, 96 finished (~3/sec across federator_incoming + remote_fetcher queues)
• 32 slow-query warnings, top 3 over 1,000 ms each on ap_object
• 15+ slow queries on bonfire_data_access_control_circle in the 400-600 ms range — same query shape repeating (one per incoming AP activity)

So when the /messages request landed, the DB pool was already saturated; the boundary EXISTS sat with a checked-out connection waiting on contention, hit 20 s, was killed.

The 3 slow-query categories

1. Boundary EXISTS subquery (the systemic one)

Generated SQL (excerpt — full version in the logs):

WHERE EXISTS (
  SELECT count(sss0.subject_id), sss0.object_id
  FROM (
    SELECT sssp0.id AS subject_id, sssb1.id AS object_id, sssb2.id AS verb_id,
           agg_perms(sssb3.value) AS value
    FROM pointers_pointer sssp0
    CROSS JOIN bonfire_data_access_control_controlled sssb1
    CROSS JOIN bonfire_data_access_control_verb sssb2
    LEFT JOIN bonfire_data_access_control_grant sssb3
      ON sssb1.acl_id = sssb3.acl_id AND sssb3.verb_id = sssb2.id
    LEFT JOIN bonfire_data_access_control_circle sssb4 ON sssb3.subject_id = sssb4.id
    LEFT JOIN bonfire_data_access_control_encircle sssb5
      ON sssb5.circle_id = sssb4.id AND sssb5.subject_id = sssp0.id
    WHERE sssb3.subject_id = sssp0.id OR sssb5.id IS NOT NULL
    GROUP BY sssp0.id, sssb1.id, sssb2.id
  ) AS sss0
  WHERE sss0.object_id = sb1.object_id
    AND sss0.subject_id = ANY($1::uuid[])
    AND sss0.verb_id    = ANY($2::uuid[])
  GROUP BY sss0.object_id
  HAVING agg_perms(sss0.value)
)

Origin: Bonfire.Boundaries.Queries.boundarise macro at extensions/bonfire_boundaries/lib/queries.ex:44, expanding Bonfire.Boundaries.Summary (definition at extensions/bonfire_boundaries/lib/summary.ex:101). The view is not materialised — Postgres re-runs the cross-join + agg_perms aggregate every call.

EXPLAIN ANALYZE on prod (warm cache, no concurrent load), for one /messages call (user has ~1,283 messages on the instance, 74 visible after boundaries, 35 distinct threads):

Execution Time: 134.7 ms
Buffers: shared hit=178846 read=9581
SubPlan 1 (boundary EXISTS) ran 1,283 times
  -> 175,230 buffer hits accumulated inside the subplan
  -> 1,209 rows removed by EXISTS, 74 survived

So per-/messages-load: ~180k buffer page accesses, ~1.3k boundary subqueries.

The view's cost is paid per page load, per row, across the whole app.

2. Federation peer-blocked check (per-incoming-activity)

SQL:

SELECT b0.id, b1.id, b1.name, b2.id, b2.summary, b2.info, b3.id, b3.caretaker_id,
       b4.id, b4.stereotype_id, b5.id, b5.name
FROM bonfire_data_access_control_circle b0
LEFT JOIN bonfire_data_social_named b1     ON b1.id = b0.id
LEFT JOIN bonfire_data_social_extra_info b2 ON b2.id = b0.id
LEFT JOIN bonfire_data_identity_caretaker b3 ON b3.id = b0.id
LEFT JOIN bonfire_boundaries_stereotype b4 ON b4.id = b0.id
LEFT JOIN bonfire_data_social_named b5     ON b5.id = b4.stereotype_id
WHERE NOT (b0.id = ANY('{}'))
  AND (b4.id IS NULL OR NOT (b4.stereotype_id = ANY('{}')))
  AND (b3.caretaker_id = ANY('{<peer_instance_id>}') OR b0.id = ANY('{}'))
  AND b4.stereotype_id = ANY('{0KF1NEY0VD0N0TWANTT0HEARME}')  -- "People silencing me"

Time: 400-600 ms each, fires once per incoming AP activity.

Call path (from stack):

• Bonfire.Federate.ActivityPub.BoundariesMRF.filter/2 (line 48)
• → BoundariesMRF.activity_blocked?/4 (line 176)
• → Peered.actor_blocked?/3 (line 184)
• → Peered.do_get_or_create/3 (line 124)
• → Instances.do_get_or_create/1 at deps/bonfire_federate_activitypub/lib/peer/instances.ex:155

The log captures the developer's own warning:

[warning] TEMPORARY: create a silencing circle for instance
(remove this in future, since doing it when a Peer is first created should be enough):
{:ok, %Bonfire.Data.AccessControl.Circle{...}}

So this is a known unresolved TODO that fires on the hot federation ingress path.

3. ap_object JSONB lookup (federation object cache miss)

SQL:

SELECT a0.id, a0.data, a0.local, a0.public, a0.is_object, a0.pointer_id,
       a0.inserted_at, a0.updated_at
FROM ap_object a0
WHERE coalesce((a0.data)->'object'->>'id', (a0.data)->>'object') = '<remote_url>'
  AND (a0.data)->>'type' = 'Create'
ORDER BY a0.inserted_at DESC
LIMIT 1

Time: ~1,050-1,080 ms each.

Call path: ActivityPub.Object.normalize/3 → Cachex miss → ActivityPub.Object.get/1 → this SELECT.

Root cause: there's no functional index on coalesce((data)->'object'->>'id', (data)->>'object'). Postgres scans the whole ap_object table evaluating the JSONB extraction per row. Cost grows linearly with table size.

---

Why /messages specifically times out

(While other pages "only" slow to 200-500 ms.)

Verified via EXPLAIN ANALYZE:

Factor	Feed/profile page	/messages
Candidate-set pre-filter	feed_publish.feed_id = X or activity.subject_id = X → ~50-200 rows	None — scans all messages on the instance (1,283 in this case)
LIMIT short-circuit	Plain ORDER BY id DESC LIMIT 20	DISTINCT ON (thread_id) + wrapped subquery for outer re-sort — must fully evaluate before LIMIT
Boundary EXISTS invocations	~50-200	1,283

messages.ex:421 previously had def filter(:messages_involving, _user_id, query), do: query — a no-op for the current-user case, leaving boundary as the only filter. A fix was attempted to pre-filter by sender/tagged. It did not help (proved via EXPLAIN): the planner won't push the new OR predicate below the EXISTS, so candidate count is unchanged.

The bottleneck is the EXISTS itself, not the candidate-set size as originally thought.

---

Action taken on prod (heads-up)

While diagnosing, ANALYZE pointers_pointer; was run on prod to verify a stats-skew hypothesis. This made /messages slower: 134 ms → 605-1,358 ms warm. The planner now switches to Seq Scan on bonfire_data_social_activity (3.18M rows) because it correctly sees ~1,283 message candidates but still over-estimates the EXISTS cost at 12,169 per row.

The previous 134 ms baseline relied on stale stats fooling the planner. Autovacuum would have run ANALYZE eventually and triggered the same regression — we just accelerated it by a few days/weeks. The latent issue is unchanged; only the visibility timeline shifted.

Also tested (all session-local, all failed to help):

• SET random_page_cost = 1.1 (we run on SSD) → same Seq Scan plan
• SET enable_seqscan = off → forces Index Scan over all 3.18M activity rows → 3,845 ms (worse)

Conclusion: no planner-config knob fixes this. The EXISTS cost estimate (12,169 per row) drives the planner to the wrong shape regardless of stats or settings. The only way to lower that estimate is to make the EXISTS cheaper to evaluate — i.e. materialise the view.

---

Proposed solutions

A. Materialise bonfire_boundaries_summary (primary fix — global impact)

Defined at extensions/bonfire_boundaries/lib/summary.ex. Lines 12-15 already draft the alternative:

@view_type "view"
@create_view_type "or replace view"
# @view_type "MATERIALIZED view"
# @create_view_type @view_type

Effect:

• EXISTS becomes a single index lookup on a real table.
• Planner cost estimate drops from 12,169 to single-digit per row → it'll choose nested loop + index scan automatically.
• Buffer hits per /messages load drop from ~180k to maybe a few hundred.
• Helps every boundary-checked query, not just /messages.

Cost — refresh strategy:

• The view depends on controlled, verb, grant, circle, encircle, pointer. Any insert/update/delete on those tables can change visibility.
• Refresh options (ranked by my preference):
  1. Oban job triggered on writes to those tables; debounce to avoid refresh storms; accept ≤ N seconds of staleness. Best for app-level latency.
  2. DB triggers that REFRESH MATERIALIZED VIEW CONCURRENTLY — simpler but tighter coupling and can block writes.
  3. Periodic cron refresh (e.g. every 5 minutes) — simplest, accepts up to 5 min staleness. May be OK if the freshness requirements are weak (need product call here).
• Need a unique index on the view to allow CONCURRENTLY. With (subject_id, object_id, verb_id) already grouped, that's the natural unique key.

Open questions for the team:

• Acceptable staleness?
• Is anyone relying on instant visibility after a grant/encircle change? (e.g. UI feedback that "you now have access")
• Should we phase by user: refresh per-user view rather than global? (Tradeoff: more refreshes, but smaller each.)

B. Functional index on ap_object (Bucket 3)

CREATE INDEX CONCURRENTLY ap_object_object_id_idx
ON ap_object ((coalesce((data)->'object'->>'id', (data)->>'object')));

Effect:

• Bucket 3 queries drop from ~1 s to single-digit ms.
• Reduces DB pressure during federation spikes.
• No code change needed; can ship as a migration in bonfire_federate_activitypub or wherever the ap_object schema lives.

Caveats:

• Functional indexes inflate write cost slightly (small for ap_object — write-heavy but the extraction is cheap).
• Index size growth — need to check what % of ap_object rows have the object.id shape.

C. Resolve the silencing-circle TODO (Bucket 2)

The codebase already flags it as a TODO. The fix is to create the silencing circle when a Peer is first created (write-time, once) rather than lazily on every incoming AP activity (read-time, repeatedly).

Locations:

• deps/bonfire_federate_activitypub/lib/peer/instances.ex:155 (current lazy creation)
• deps/bonfire_federate_activitypub/lib/peer/peered.ex:124, 184 (call site)
• deps/bonfire_federate_activitypub/lib/boundaries/boundaries_mrf.ex:48, 131, 176 (consumer)

Need a teammate familiar with the federate-activitypub extension to validate the right write-time hook (probably when Peered is upserted for the first time).

D. Cap Oban federation queue concurrency

Independent mitigation: reduces DB-pool starvation regardless of whether (A)-(C) ship.

Find the Oban config (likely in config/runtime.exs or a federate extension config) and cap:

config :bonfire, Oban,
  queues: [
    federator_incoming: 5,   # currently appears uncapped or high
    remote_fetcher: 5,
    # ...
  ]

Cost: federation backlog grows during spikes (catches up later). Benefit: interactive pages never starve.

E. Revert messages.ex:421 change

A code change was made at extensions/bonfire_messages/lib/messages.ex:421 to pre-filter the candidate set by activity.subject_id / tagged.tag_id. It does not help (proven via two EXPLAIN ANALYZE comparisons — the planner doesn't push the new predicate down). It's a correctness alignment with the two-user filter shape but doesn't change performance. Revert to avoid noise in any future debugging.

Tests added at extensions/bonfire_messages/test/messages/messages_threads_test.exs are still useful regression coverage for the latest_in_threads: true path — keep those.

F. Postgres config (worth checking even if it didn't fix this case)

We run on SSDs. Confirm random_page_cost in postgresql.conf is set appropriately (1.1 is the SSD norm; default 4.0 assumes HDD). Tested session-local and it didn't shift the plan for /messages specifically, but it's still better-practice for the whole DB.

---

Priority recommendation

1. (D) Cap federation queue concurrency — cheap, partial relief for the contention story today.
2. (B) Functional index on ap_object — single migration, big win on the heaviest individual query class.
3. (A) Materialise the boundary view — the structural fix; biggest payoff but most design work. Pair with refresh-strategy spike.
4. (C) Silencing-circle TODO — independent improvement, needs federate-AP context.
5. (E) Revert the messages.ex change.
6. (F) Verify random_page_cost.

---

Honest caveats

• (A) is sketched, not designed. The refresh strategy is the hard part and needs the team to weigh staleness vs. write cost. Pre-spike: try it in a dev DB; measure refresh time on a representative dataset.
• (B) is the lowest-risk lever identified.
• (C) requires understanding of the federate-AP extension not fully covered here.
• The 134 ms → 605 ms regression introduced via ANALYZE is on prod right now. It's safe but slower than yesterday. Materialising the view will reverse it and then some.
• Two code-level fixes were attempted (the messages.ex:421 pre-filter and a CTE rewrite of the query) before reaching this diagnosis. Both proved wrong via EXPLAIN. Documenting them so nobody else wastes time on the same paths.