mirror of
https://github.com/block/buzz.git
synced 2026-10-27 12:40:30 +00:00
fix(db): bound every statement and the #p mention scan (#8461)
## Problem An agent `#p` + `#h` + `since` REQ (the `require_mention` subscription in `buzz-acp`) ran for over 45 minutes on a production writer and held `AccessShare` on every `events` partition. There were two causes: 1. **The mention side of the `#p` join was unbounded.** `build_query_events_sql` joined `event_mentions` on `(community_id, event_id)` only. The planner picked a nested loop whose outer side was every mention of the pubkey, ever, and whose inner side range-scanned the channel index from `since` on each partition. Cost ≈ total mentions × channel rows since `since`. 2. **Nothing cancelled it.** The writer `statement_timeout` defaulted to `0`. Only `#e` reads had a deadline (the 20s cap from #7854), and read-replica sessions had none at all. `pg_stat_statements` shows this shape has a multi-thousand-second max going back months, so it is chronic and was not introduced by a recent change. ## Change **`#p` mention bound** (`store/event.rs`, `push_mention_join`, shared by the page SELECT and COUNT) - Join on the full event key, `AND e.created_at = m.event_created_at`. Mention rows copy the event's `created_at` at insert (migration 0007 already relies on this equality), so the join can prune `events` partitions by time. - Repeat `since`/`until` on `m.event_created_at`, so the outer scan is a range on the existing `idx_event_mentions_pubkey_created`. `until` is a superset bound for the keyset cursor; the exact `(created_at, id)` cursor test stays on `e`. - Repeat `kinds` on `m.event_kind` when the filter has kinds. Every production mention writer binds the event kind (`insert_mentions` in `store/runtime/mod.rs`, and the replaceable-event path in `store/replaceable.rs`, back to the first Postgres schema), and no migration inserts mention rows, so this drops no rows written by the relay. Rows imported out of band with a NULL `event_kind` would no longer match a kinds-filtered `#p` read; a read-only production count on 2026-10-20 found 0 such rows on both production reader databases. The pushdown makes `idx_event_mentions_pubkey_kind_created` available to the planner for the `require_mention` kind-9 shape; its use has not been observed (see below). An E2E fixture with a hand-set NULL `event_kind` row confirmed the caveat: base returns 8 events, head 7. - The feed's mentions and needs-action queries (`store/feed.rs`, `build_mentions_query` / `build_needs_action_query`) join `event_mentions` the same way, so each joined row probes one `events` partition instead of all of them. Their `ORDER BY m.event_created_at ... LIMIT` already kept them from running away; this removes the per-row cross-partition probe. - Observed plan (E2E at `9cb6638b1`, before the `kinds` pushdown; 60,000 historical mentions + 2,500 recent decoys, stock planner, `EXPLAIN (ANALYZE, BUFFERS)` of the captured production SQL): the mention side is a bounded range on `idx_event_mentions_pubkey_created` (13 rows), then a hash join with a scan of the recent `events` partition. Base scanned 2,509 recent events and probed `event_mentions_pkey` 2,509 times. Head: **1.1 ms / 319 shared hits**; base: **8.5 ms / 10,049 shared hits**. Not measured against the production replica. A fresh `EXPLAIN (ANALYZE, BUFFERS)` replay at `a7065c367`, after the pushdown, ran on a smaller fixture where the planner chose a sequential mention scan, so it neither confirms nor replaces these numbers. **Reads: 20s deadline on every generic event read** - `query_events_on` and `count_events_on` always run under the transaction-local 20s deadline that `#e` reads used (`fetch_with_read_deadline`, formerly `fetch_with_e_tag_deadline`). It only tightens: shorter operator or caller caps are kept. - Read-replica sessions get a 20s session default through `after_connect`, using the same tighten-only SQL. - Cost: every generic REQ history read and COUNT now pays BEGIN + `set_config` + ROLLBACK (three extra round trips; before, only `#e` reads did). In the local E2E the end-to-end history read was still faster at head (median 4.1 ms vs 10.2 ms at base, 9 samples each, warm cache), so the round trips are dominated by the bounded plan; this does not isolate them or establish production p99. The round trips also lengthen how long each such read holds its writer connection; that hold time has not been measured against production pool sizing. - A replica read cancelled at its deadline (57014) is returned, not re-run on the writer. Usually the cancel means expensive work the writer would only repeat. It can also mean the replica waited on a lock only it holds (a replayed `ACCESS EXCLUSIVE` from primary DDL), when the writer would have answered quickly; that miss is the accepted price of keeping runaway reads off the primary. The rationale now lives once on `DbError::is_statement_cancelled` instead of in a dozen copied comments. The generic routed reads and `ReadSession` already did this; the eight routed reads with their own SQL (feed mentions, needs-action and activity; thread replies; channel window; relay membership; thread window and its auxiliary scan) now do too. A cancelled auxiliary scan also keeps its replica session instead of degrading it to the writer for the rest of the request. Other replica failures (e.g. hot-standby recovery conflicts) still fall back to the writer. - Paths with their own tighter `SET LOCAL` (artifact 2–5s, thread window 4s, personal reads, usage 5–15s, serving lease 1.5s) are unchanged. **Writes: every writer session is bounded** - The default `statement_timeout` changes from `0` to 120s (`DEFAULT_STATEMENT_TIMEOUT_MS`). - `BUZZ_DB_STATEMENT_TIMEOUT_MS` still overrides it. `0` or any value above 300s installs 300s (`MAX_STATEMENT_TIMEOUT_MS`), so a session can no longer disable it, and a clamped value logs a `warn!` when the pool is built. Only the operator-approved, fenced destruction paths below lift it, per transaction. **Long-running writer paths, audited** | Path | Behavior | |---|---| | Migrations / schema destruction (`with_exclusive_schema_destruction_lock`) | Unchanged: these lift lock and statement timeouts on their own detached connection | | Partition maintenance | Unchanged: own 5s `statement_timeout` | | Partition audit (`buzz-admin`) | Unchanged: 30s | | Community deletion inventory, purge and logical verification (`inventory_schema` whole-tenant counts, `purge_postgres` whole-community `DELETE` per table in one tx, `verify_postgres_logically_deleted` whole-tenant `EXISTS` per table right after the purge) | Lifted (`statement_timeout = 0`) transaction-locally by `lift_statement_timeout`, like migrations; lock and idle timeouts still bound them. Inventory counts each table in its own lifted transaction, so each table's lock and snapshot are released as soon as its count finishes, as the autocommit counts did. A cancelled purge would retry from scratch and eventually block, so a cap here would turn large-tenant deletion into an operator override | | Audit appends (`buzz-audit`, audit pool inherits the writer cap) | Waits on the audit-chain advisory lock. With `BUZZ_DB_LOCK_TIMEOUT_MS=0` (or at least the statement cap), `statement_timeout` (57014) cancels the wait instead of `lock_timeout` (55P03). The relay's audit worker now retries both with the same backoff instead of dropping the entry on 57014; admission refusal stays terminal | On HTTP routes a statement timeout already maps to the distinct retryable 503 (`api/mod.rs`, `statement_timeout_maps_to_distinct_503`). A cancelled REQ fails its history read instead of hanging. ## Tests - `p_tag_query_bounds_mention_side_by_time` (unit): page and COUNT SQL carry the `created_at` join and the `since`/`until`/`kinds` mention bounds, and the bounds are absent when the filter has none. - `p_tag_read_with_mention_bounds_keeps_results` (Postgres): through the production mention insert, unbounded, `since`, window and keyset-cursor reads return exactly the mentioned rows, and COUNT matches. Every bound sits exactly on a mentioned row's second and the cursor page includes a same-second sibling after the cursor id, so an off-by-one on either mention-side bound fails it. - `plain_read_is_cancelled_at_deadline_when_timeout_disabled` / `count_events_cancels_at_read_deadline_when_timeout_disabled` (Postgres): the production `#p` + `#h` + `since` shape and a plain COUNT are cancelled at 20s with the session timeout disabled. Previously these covered `#e` only. - `writer_statement_timeout_is_always_bounded` (unit) and `session_statement_timeouts_bound_writer_and_reader_sessions` (Postgres): through `Db::new`, writer sessions install `2min` / `5min` (for `0` and for 600s) / `45s`, and replica sessions install `20s`. - `deletion_whole_tenant_stages_outlive_the_writer_statement_timeout` (Postgres): on a scratch desired-state database with a 500ms writer cap, the real `inventory_schema`, `purge_postgres` and `verify_postgres_logically_deleted` each wait behind a held `ACCESS EXCLUSIVE` lock on `events` for over 1s and still complete, a plain statement is cancelled (57014), and pooled sessions still read `500ms` afterwards. A lifted transaction reads `statement_timeout = 0`, so a bounded lift (e.g. `'300000'`) fails it, as does removing any of the three `lift_statement_timeout` calls. - `mentions_query_is_tenant_scoped_and_joins_mentions_by_composite_key` / `needs_action_query_is_tenant_scoped_and_joins_mentions_by_composite_key` (unit): both feed queries carry the `e.created_at = m.event_created_at` join. - `replica_statement_cancel_propagates_without_writer_rerun` (Postgres): with the replica locked past its cap, each of the six routed reads above returns 57014 instead of the writer's copy. Removing the cancel arm in any of them fails it. - `thread_window_statement_cancel_propagates_without_writer_rerun` (Postgres): a thread-window read parked behind a replica lock and cancelled (57014; the window's own 1s `lock_timeout` would otherwise fire first) returns the cancel instead of the unlocked writer's window, and an auxiliary scan timed out on a replica session returns 57014 and leaves the session on the replica. Removing either guard fails it. - `audit_worker_retries_statement_timeout_until_original_entry_is_appended_once` (Postgres, `buzz-relay`): the production audit worker, with `lock_timeout` disabled and a 100ms statement cap, keeps the entry through repeated 57014 cancels while the chain lock is held and appends it exactly once after release. Treating only 55P03 as retryable fails it. - The existing writer and audit-pool GUC tests now expect `5min` for a disabled statement timeout. ## After deploy, watch - `buzz_db_route_decision{decision="replica",reason="statement_cancelled"}`: replica reads that now fail instead of falling back to the writer, including the replica-only lock case above. - `buzz_db_pool_acquire_wait_seconds` and `buzz_db_pool_waiters` on the writer pool: every generic REQ history read and COUNT now holds its connection for three extra round trips. ## Database checklist (`docs/database.md` § Review checklist) This PR changes schema-dependent `buzz-db` queries (the `#p` join and its `m.event_kind` pushdown). It does not change the schema. - **Phase:** none. No schema change, so this is not an expand, backfill or contract step. Nothing before or after it is required. - **Triggers, functions, procedures, rules, foreign keys:** none added. - **Row mutations / backfill:** no migration, and no row is mutated or backfilled. The one data-shape dependency is mention rows with a NULL `event_kind`: a kinds-filtered `#p` read no longer matches them (see the `kinds` bullet under Change). Relay writers always bind `event_kind`, so only rows imported out of band are affected. A read-only production count on 2026-10-20 found 0 such rows on both production reader databases. - **Contract migration:** N/A. - **Rule 4 locations:** none touched. No table, index or desired-state file changes, so no parity test applies. The new bounds use the existing `idx_event_mentions_pubkey_created` and `idx_event_mentions_pubkey_kind_created`. - **Deployed relay vs. new schema:** there is no new schema. The currently deployed relay and this relay run against the same tables. - **Lock and statement timeouts:** this PR is about them. Generic reads get a 20s deadline, replica sessions a 20s default, and writer sessions a 120s default capped at 300s. Community-deletion transactions lift `statement_timeout` per transaction; migrations and schema destruction are unchanged (see "Long-running writer paths, audited"). No index builds and no operator prebuild step. ## What got simpler - One read-deadline path instead of an `#e`-only branch in `query_events_on` and `count_events_on`. - The `#p` join SQL that was duplicated between SELECT and COUNT now lives in one `push_mention_join`. - The deletion tests share one scratch desired-state database helper instead of an inline copy. - "Is this query bounded?" now has one answer: yes, unless it runs in a migration, schema destruction, or community-deletion transaction. ## Identified debt (not in this PR) - `buzz-acp` re-sends the same filter after a timeout `CLOSED` (no backoff or narrowing). With the `#p` bound the `require_mention` read should finish well inside 20s, so this is a follow-up, not a blocker. --------- Signed-off-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz> Co-authored-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz>
This commit is contained in:
19
.env.example
19
.env.example
@@ -58,19 +58,24 @@ REDIS_URL=redis://localhost:6379
|
||||
# BUZZ_PARTITION_MANAGER_ADVANCE_ENABLED=true
|
||||
|
||||
# Writer-session Postgres timeouts for buzz-db-backed pools and the relay audit
|
||||
# pool, all in milliseconds; 0 disables. The separately deployed push gateway
|
||||
# owns its own database and session policy and does not consume these knobs.
|
||||
# pool, all in milliseconds; 0 disables the lock and idle timeouts. The
|
||||
# separately deployed push gateway owns its own database and session policy
|
||||
# and does not consume these knobs.
|
||||
# lock_timeout: fail a statement that waits this long on any lock instead of
|
||||
# parking behind a wedged holder (default 5000).
|
||||
# BUZZ_DB_LOCK_TIMEOUT_MS=5000
|
||||
# idle_in_transaction_session_timeout: reap sessions idle inside an open
|
||||
# transaction — bounds how long a wedged client can hold locks (default 60000).
|
||||
# BUZZ_DB_IDLE_TXN_TIMEOUT_MS=60000
|
||||
# statement_timeout: cap any single statement's runtime. Off by default —
|
||||
# startup migrations/backfills legitimately run long statements. Warning: a
|
||||
# pathologically low value (e.g. 1) also times out connection setup and can
|
||||
# prevent any DB connection from establishing.
|
||||
# BUZZ_DB_STATEMENT_TIMEOUT_MS=0
|
||||
# statement_timeout: cap any single statement's runtime (default 120000). A
|
||||
# session cannot disable it: 0 or anything above 300000 installs 300000 (5
|
||||
# minutes) and logs a warning at startup. Migrations, schema destruction, and
|
||||
# community-deletion inventory and purge transactions lift it for themselves.
|
||||
# Generic event reads (REQ history, /query, /count) and read-replica sessions
|
||||
# are further capped at 20s. Warning: a pathologically low value (e.g. 1) also
|
||||
# times out connection setup and can prevent any DB connection from
|
||||
# establishing.
|
||||
# BUZZ_DB_STATEMENT_TIMEOUT_MS=120000
|
||||
|
||||
# -----------------------------------------------------------------------------
|
||||
# Typesense (search)
|
||||
|
||||
Reference in New Issue
Block a user