mirror of
https://github.com/simplex-chat/simplexmq.git
synced 2026-10-05 23:07:22 +00:00
* smp server: add prometheus scan indexes * smp server: estimate queue count in metrics * docs: add smp server db load report * smp server: reduce msg_queues write load * docs: document batch-2 fixes and operator actions
201 lines
13 KiB
Markdown
201 lines
13 KiB
Markdown
# SMP server database load: root causes and fixes
|
|
|
|
## Summary
|
|
|
|
The recurring `pMsgFwdsOwn_pErrorsOther` spikes are a symptom of chronic disk saturation of the
|
|
`smp_server` PostgreSQL database, not a proxy or forwarding bug. The baseline read load is the
|
|
Prometheus scrape running whole-table `COUNT` scans of `msg_queues` (48.5M rows) every 30 seconds,
|
|
compounded by the message-expiration sweep. The write load comes from indexing `updated_at`:
|
|
`updateQueueTime` stamps it on the first send to each active queue per UTC day, and these non-HOT
|
|
updates bloat the indexes to 104 GB and amplify WAL to about 425 GB per day (37% full-page images,
|
|
~31% from `updateQueueTime`). Because the stamp is day-granular, this write burst clusters at 00:00 UTC,
|
|
tipping the saturated disk into the observed spike and loading the pgBackRest backup repository.
|
|
|
|
Code fixes replace the largest metric scan with an estimate and index the sweep and notifier counts.
|
|
Reclaiming the index bloat, which also clears the remaining metric scan, and keeping it down are
|
|
operator actions, because PostgreSQL never shrinks indexes automatically.
|
|
|
|
## Environment
|
|
|
|
The affected deployment runs the pure PostgreSQL backend (`store_queues: database`,
|
|
`store_messages: database`), schema `smp_server`, `db_pool_size 20`, `prometheus_interval 30`,
|
|
`[NAMES]` enabled, own-server proxying enabled, and forwards routed over a SOCKS proxy.
|
|
|
|
`msg_queues`: 48.5M live rows, 12.3% dead tuples, 14 GB heap, 104 GB indexes, 118 GB total.
|
|
|
|
## Evidence
|
|
|
|
`pg_stat_statements` over a 5 minute window, ordered by disk reads (`track_io_timing` was off, so
|
|
`shared_blks_read` is the disk proxy; the two `EXPLAIN ANALYZE` rows are manual and excluded):
|
|
|
|
| query | calls | mean ms | reads | share of all reads |
|
|
| --- | --- | --- | --- | --- |
|
|
| `getEntityCounts` (the six-`COUNT` metric query) | 30 | 111,456 | 990 GB | 70.7% |
|
|
| queue-record load (`SELECT recipient_id, …`) | 47,027 | 121 | 89 GB | 6.3% |
|
|
| expiration sweep batch (`array_agg` in `expire_old_messages`) | 13 | 233,143 | 62 GB | 4.5% |
|
|
| message peek (`DISTINCT ON (recipient_id)`) | 46,932 | 76 | 43 GB | 3.0% |
|
|
| `updateQueueTime` (`UPDATE msg_queues SET updated_at`) | 172,885 | 4 | 7.7 GB | 0.5% |
|
|
| `write_message` | 110,911 | 5 | 7.0 GB | 0.5% |
|
|
|
|
`EXPLAIN (ANALYZE, BUFFERS)` of each `msg_queues` count inside `getEntityCounts`:
|
|
|
|
| count | plan | time |
|
|
| --- | --- | --- |
|
|
| `queue_count` (`deleted_at IS NULL`) | Parallel Seq Scan | 30 s |
|
|
| `notifier_count` (`deleted_at IS NULL AND notifier_id IS NOT NULL`) | Parallel Seq Scan | 32.6 s |
|
|
| `ntf_service_queues_count` (`ntf_service_id IS NOT NULL AND deleted_at IS NULL`) | Parallel Seq Scan | 30.2 s |
|
|
| `rcv_service_queues_count` (`rcv_service_id IS NOT NULL AND deleted_at IS NULL`) | Index Only Scan | 1.4 ms |
|
|
|
|
The expiration sweep batch: 229 s for one 10,000-row batch, walking `msg_queues_pkey` and discarding
|
|
809,729 rows by filter to find 10,000 expirable ones.
|
|
|
|
`pg_stat_wal` over the measurement window: 27 TB of WAL accumulated, 37.2% of records full-page
|
|
images, averaging about 425 GB per day; recent days reach ~470 GB (from the `archive-push` log) as
|
|
the queue count grows.
|
|
|
|
Per-statement WAL from `pg_stat_statements` (`wal_bytes`), leaf statements only (this instance runs
|
|
`pg_stat_statements.track = all`, so the `write_message` wrapper double-counts the `INSERT` and
|
|
`UPDATE` it runs, and is excluded):
|
|
|
|
| category | share of WAL | main statements |
|
|
| --- | --- | --- |
|
|
| `msg_queues` updates | ~42% | `updateQueueTime` ~31%, `msg_can_write` flags ~9%, insert/delete ~2% |
|
|
| `messages` insert and delete | ~34% | message `INSERT`, `DELETE` by `message_id` and `recipient_id` |
|
|
| read path (hint bits, FPIs on SELECT) | ~24% | message peek ~15%, `msg_queue_size`, `getEntityCounts` |
|
|
|
|
## Root causes
|
|
|
|
1. Prometheus scrape. `getEntityCounts` (`QueueStore/Postgres.hs:154`) runs six `COUNT(1)` subqueries
|
|
every `prometheus_interval` (30 s), called from the metrics path (`Server.hs:698`). Four count
|
|
`msg_queues`; three of those seq-scan the 48.5M-row heap. At 70.7% of all reads it is the dominant
|
|
disk consumer, and it runs continuously (mean 111 s per scrape exceeds the 30 s interval).
|
|
|
|
2. Message-expiration sweep. `expireMessagesThread` (`Server.hs:477`) calls the `expire_old_messages`
|
|
procedure (`server_schema.sql`), whose inner batch query selects expirable queues ordered by
|
|
`recipient_id`. With `oldQueue = 0` the `updated_at` filter matches everything, so the planner
|
|
walks the primary key and filters `msg_queue_expire`, discarding ~99% of rows per batch.
|
|
|
|
3. Index bloat. 104 GB of indexes on a 14 GB table. `updated_at` is part of
|
|
`idx_msg_queues_updated_at_recipient_id` (`server_schema.sql:526`) and `updateQueueTime`
|
|
(`QueueStore/Postgres.hs:443`) updates it on the day's first send per queue (172,885 times in the
|
|
window above). Updating an indexed column prevents HOT updates, so every update writes a new row
|
|
version plus new entries in every index on the table, and the old index entries accumulate as bloat.
|
|
|
|
4. WAL amplification. Only 15.6% of `msg_queues` updates are HOT, because its composite index covers
|
|
`updated_at` and `msg_queue_expire`, both changed on the hot path (cause 3); the rest rewrite every
|
|
index on the table. With the 104 GB of bloated indexes and frequent checkpoints (`max_wal_size 4GB`,
|
|
`checkpoint_timeout 5min`, `wal_compression off`), 37% of WAL records are full-page images, and the
|
|
server generates about 425 GB of WAL per day (27 TB accumulated; recent days near 470 GB).
|
|
`updateQueueTime`, stamping `updated_at` on the ~5.3M daily-active queues, is the single largest
|
|
statement at ~31% of WAL (see Evidence). pgBackRest `archive-push` ships all of it, loading the
|
|
primary disk and the backup repository. The load peaks
|
|
at 00:00 UTC because `getSystemDate` rounds `updated_at` to the UTC day, so the first send to each
|
|
active queue after midnight runs `updateQueueTime`, clustering these writes and the `archive-push`
|
|
volume in the 00h hour.
|
|
|
|
## Index bloat and autovacuum
|
|
|
|
Autovacuum is running (60 runs on this table) and is not misconfigured, but two limits apply.
|
|
|
|
Autovacuum reclaims heap dead tuples and refreshes planner statistics; it does not shrink indexes.
|
|
Only `REINDEX` or `pg_repack` rebuilds a bloated B-tree. Index bloat therefore has no automatic
|
|
remedy.
|
|
|
|
Default autovacuum pacing assumes moderate churn. `autovacuum_vacuum_scale_factor = 0.2` waits until
|
|
20% of the table is dead (about 9.7M rows here) before vacuuming, and cost-based throttling caps its
|
|
I/O, so a hot table stays around 12% dead. Per-table tuning makes it run sooner and faster.
|
|
|
|
The amplifier is indexing `updated_at`, a column updated on every send, which the fixes and operator
|
|
actions below address.
|
|
|
|
## Implemented fixes (batch 1)
|
|
|
|
Branch `sh/leaks-batch-1`, two commits.
|
|
|
|
| commit | change | effect |
|
|
| --- | --- | --- |
|
|
| `88673eee` | migration `20260916_prometheus_indexes` adds partial indexes `idx_msg_queues_expire (recipient_id) WHERE deleted_at IS NULL AND msg_queue_expire` and `idx_msg_queues_notifier_active (notifier_id) WHERE deleted_at IS NULL AND notifier_id IS NOT NULL` | the sweep batch and `notifier_count` become index scans |
|
|
| `2912be1e` | `getEntityCounts.queue_count` uses `pg_class.reltuples` (`QueueStore/Postgres.hs:154`) | removes the 30 s, 990 GB whole-table `COUNT` on every scrape |
|
|
|
|
Verified: both indexes are created and used as index-only scans, the schema-dump test passes, and
|
|
`smp-server` builds. `queueCount` is consumed only by metrics, logs, and display
|
|
(`Server.hs:528,698,815,2369`), so an estimate is safe.
|
|
|
|
Not fixed by new indexes:
|
|
|
|
- `ntf_service_queues_count` seq-scans only because of index bloat; `idx_msg_queues_ntf_service_id`
|
|
already covers it. `REINDEX` restores the index-only scan, as proven by `rcv_service_queues_count`.
|
|
- `rcv_service_queues_count` and the two `services` counts are already cheap.
|
|
|
|
## Implemented fixes (batch 2)
|
|
|
|
Migration `20260917_msg_queues_hot` and `MsgStore/Postgres.hs`.
|
|
|
|
| change | effect |
|
|
| --- | --- |
|
|
| drop `idx_msg_queues_updated_at_recipient_id`, set `msg_queues` `fillfactor = 80` | `updateQueueTime` updates become HOT, so they rewrite no index entries; removes its index bloat and cuts its WAL |
|
|
| remove the dead `updated_at > p_old_queue` filter and its parameter from `expire_old_messages`, matching the `CALL` (`MsgStore/Postgres.hs:113`) | the sweep query runs as an index-only scan on `idx_msg_queues_expire`; `updated_at` is no longer read on the hot path |
|
|
| autovacuum reloptions on `msg_queues`, `messages` (and its TOAST), and `services` | keeps dead tuples and bloat low per table (see the table below) |
|
|
|
|
Verified on PostgreSQL 16 with the daily-active pattern (~11% of queues updated per day): `updateQueueTime`
|
|
goes from 0% HOT (indexed `updated_at`) to 100% HOT at `fillfactor = 80` (96.7% at 90), and per-update
|
|
WAL drops about 4x. The HOT ratio depends on how many rows per page change before autovacuum reclaims
|
|
space, so it is workload-dependent; `fillfactor = 80` reached 100% for this fraction, and updating a much
|
|
larger share of queues at once would need a lower value. `fillfactor` applies to pages rewritten after
|
|
the change, so the ratio ramps up as the heap turns over, or immediately after `pg_repack`.
|
|
|
|
Dropping the index regresses the deprecated journal message store's expiration (`foldRecentQueueRecs`,
|
|
`Journal.hs:434`) to a sequential scan; this is accepted because that store is being retired. The
|
|
Postgres message store does not read `updated_at`.
|
|
|
|
Autovacuum reloptions applied by the migration:
|
|
|
|
| table | reloptions | reason |
|
|
| --- | --- | --- |
|
|
| `msg_queues` | `fillfactor 80`, `autovacuum_vacuum_scale_factor 0.02`, `autovacuum_analyze_scale_factor 0.01`, `autovacuum_vacuum_cost_limit 1000` | HOT headroom; vacuum/analyze at ~2%/1% churn instead of 20%/10%; faster vacuum |
|
|
| `messages` (and TOAST) | `autovacuum_vacuum_scale_factor 0.02`, `autovacuum_analyze_scale_factor 0.01`, `toast.autovacuum_vacuum_scale_factor 0.02` | high insert and delete churn; 152 GB, mostly TOASTed message bodies |
|
|
| `services` | `fillfactor 70`, `autovacuum_vacuum_threshold 1000`, `autovacuum_vacuum_scale_factor 0` | tiny, very hot table was autovacuumed tens of thousands of times; make updates HOT and vacuum it far less |
|
|
|
|
## Operator actions
|
|
|
|
1. Reclaim index bloat (online, no lock; needs free disk near the index size; run largest first):
|
|
```
|
|
REINDEX INDEX CONCURRENTLY smp_server.idx_msg_queues_updated_at_recipient_id;
|
|
REINDEX INDEX CONCURRENTLY smp_server.idx_msg_queues_notifier_id;
|
|
REINDEX INDEX CONCURRENTLY smp_server.idx_msg_queues_ntf_service_id;
|
|
REINDEX INDEX CONCURRENTLY smp_server.idx_msg_queues_rcv_service_id;
|
|
REINDEX INDEX CONCURRENTLY smp_server.idx_msg_queues_sender_id;
|
|
REINDEX INDEX CONCURRENTLY smp_server.idx_msg_queues_link_id;
|
|
ANALYZE smp_server.msg_queues;
|
|
```
|
|
Expect `pg_indexes_size('smp_server.msg_queues')` to drop from 104 GB to roughly 12 GB (measured
|
|
after reindexing). `ANALYZE` restores the index-only scan for `ntf_service_queues_count`. With the
|
|
batch-2 `fillfactor` the index bloat no longer rebuilds, so this is a one-time reclaim.
|
|
|
|
2. Autovacuum reloptions are applied by the batch-2 migration (`msg_queues`, `messages` and its TOAST,
|
|
`services`), so no manual `ALTER TABLE` is needed. Reclaim the current `messages` bloat once with
|
|
`pg_repack smp_server.messages` (152 GB heap and TOAST, roughly 30-50 GB reclaimable); running
|
|
`pg_repack` on `msg_queues` also makes `fillfactor = 80` effective immediately rather than as pages
|
|
turn over. With `fillfactor = 80` the `msg_queues` index bloat no longer rebuilds, so scheduled
|
|
reindexing is rarely needed. To automate it anyway, run `reindexdb --concurrently` or `pg_repack`
|
|
from a scheduler; `pg_cron` runs each job inside a transaction and cannot execute
|
|
`REINDEX ... CONCURRENTLY`, so use `pg_cron` only for `VACUUM`/`ANALYZE` or a non-concurrent
|
|
maintenance-window `REINDEX`.
|
|
|
|
3. Cut WAL and checkpoint pressure (all reloadable, no restart):
|
|
```
|
|
ALTER SYSTEM SET wal_compression = 'lz4';
|
|
ALTER SYSTEM SET max_wal_size = '32GB';
|
|
ALTER SYSTEM SET checkpoint_timeout = '30min';
|
|
SELECT pg_reload_conf();
|
|
```
|
|
Fewer checkpoints produce fewer full-page images; `wal_compression` shrinks those that remain.
|
|
Together these reduce the WAL written on the primary and shipped by `archive-push`. The message
|
|
insert and delete volume itself is fixed by traffic, but most of its WAL cost is amplification
|
|
(full-page images and hint-bit writes on bloated pages), which these settings and `REINDEX` reduce.
|
|
This is separate from pgBackRest repo-side compression, which does not reduce WAL on the primary.
|
|
Verify with `pg_stat_reset_shared('wal')`, wait, then re-check `wal_fpi` and `wal_bytes` in
|
|
`pg_stat_wal`.
|
|
|
|
4. Enable `track_io_timing = on` so disk wait time is measurable in `pg_stat_statements`.
|