perf(postgres): fix search collapse at volume (#224)#260
Conversation
At ~1.3M search_index rows the Postgres backend served FHIR search at a 7.18s median / 51s p99, and `Observation?combo-code-value-quantity=` reliably timed out with a 500. Validated against a 1.45M-row replica of the benchmark dataset: at 30 concurrent clients the mixed search workload goes from 45.5 tps / 659ms to 107.3 tps / 280ms from the SQL and index changes alone. Query builder: * Composite search had NO value predicate in its WHERE clause — it aggregated every row of the parameter's slice (180k) on every request and spilled work_mem 30 ways under load. Add an OR-prefilter over the components; rows matching no component contribute 0 to every MAX(CASE ...) in the HAVING, so dropping them is provably result-preserving. The GROUP BY resource_id, composite_group and the per-value HAVING are kept exactly as they were — they are what forces all components into the same composite group. * Composite values that failed to parse mid-way left their earlier components' bind params attached to a `1 = 0` fragment, so the params had no placeholder and Postgres rejected the statement (`?code-value-quantity=8867-4$abc` → 500). Stage params per value and commit only on success. * Token and reference OR-lists emitted one `id IN (...)` per value, OR'd together. Postgres only pulls a sublink up into a semi-join when it sits in the top-level AND-list; under an OR it stays a SubPlan that can be re-executed per outer row. Emit a single sublink with the OR inside. 8.7ms → 0.65ms. * String search matched `COALESCE(value_string_folded, value_string) ILIKE $n`, which no btree can serve. Match `COALESCE(value_string_folded, lower(value_string)) LIKE $n` instead — semantically identical (fold_text already lowercases, and lower() on the raw fallback reproduces what ILIKE did) but indexable. value_string_folded is populated on write and never backfilled, so the COALESCE fallback is load-bearing for rows predating schema v10. * Escape LIKE metacharacters in string values (`?name=50%` was a live wildcard). chain_builder already did this; the main builder did not. Schema v14 (additive only; no index dropped, no semantics changed): * idx_resources_search on resources(tenant_id, resource_type, last_updated DESC, id ASC) WHERE NOT is_deleted. No index supplied the ORDER BY, so every low-selectivity search materialized the whole match set and sorted it to return 20 rows. Postgres now walks in sort order and stops early — 207 rows scanned instead of 90k. Column directions must be explicit: a backward scan of (last_updated, id) yields id DESC, which does not match id ASC. * idx_search_token_code puts value_token_code ahead of value_token_system. The hot forms (code=, category=, status=, class=) bind the code alone and could not seek with system leading. * idx_search_string_folded_pattern and idx_search_reference_pattern use text_pattern_ops — required for LIKE prefixes under CI's non-C collation. * Extended statistics on (param_name, value_token_code): value_token_code mixes codes from every param_name, so Postgres estimated the conjunction as a product of independent marginals and was off by orders of magnitude. Plain per-column stats cannot express this, which is why the ANALYZE tried earlier had no effect. * Serialize initialize_schema with a session advisory lock. Several instances routinely share one database (cluster-smoke runs two) and schema_version is read-then-written without a transaction; index builds widen that race from microseconds to seconds. Runtime: * The pool was pinned at 10 and unreachable: parse_connection_string never consulted HFS_PG_MAX_CONNECTIONS, and HFS_DATABASE_URL takes that path — so no environment variable could change it. At 30 concurrent clients, Little's Law puts ~2/3 of every request's latency in the connection queue. Apply the env overrides on every construction path and default to cores*4 clamped to 16..64. * statement_timeout was SET on one borrowed connection and returned to the pool. It is a session GUC, so the other connections inherited the server default (no limit). This is why a "30s timeout" produced a 500 at 39.5s and a 65s max — only the ~1-in-10 request drawing the armed connection was ever capped. Send it in the startup packet instead. * Bound deadpool's wait/create/recycle timeouts (it waits forever by default) and surface pool exhaustion as 503 rather than 500. connect_timeout_secs was dead config. * parse_connection_string put any URL query string into dbname verbatim. Benchmark workflow: * Build --release. The step was literally named "Build debug binary" — we were timing an unoptimized build against production-tuned comparators. * VACUUM (ANALYZE) before the search suite. After a bulk load relallvisible is 0 until a VACUUM runs, and index-only scans silently degrade to heap fetches; ANALYZE alone never sets the visibility map. * Emit per-query-shape latency from the tags search.js already sets. The aggregate summary was why #224 could not attribute the 7s median. Rejected on measurement, documented in-code: a correlated EXISTS for composites (1ms on a match but 440ms when it matches nothing — the benchmark fires such a value in every composite list — and 90 vs 112 tps under load); a self-join on composite_group (slower, 4x the buffers); EXISTS-for-IN (no effect, Postgres already flattens IN). idx_search_resource was NOT dropped despite looking redundant: it takes ~12M scans in a 30s run. Tests: composite components must share a composite_group (a two-group blood-pressure panel — the existing single-group test cannot detect a cross-group false positive); composite OR-list values stay isolated; string search still matches rows whose value_string_folded is NULL.
Four test fixes surfaced by CI (nothing here changes production behavior): * The string-search assertions expected `ILIKE`, which the #224 fix replaced with a `LIKE` against `COALESCE(value_string_folded, lower(value_string))` — `ILIKE` can never use a btree index. Assert the new sargable expression and that `ILIKE` is gone. The token-display, uri, and reference-display paths still use `ILIKE` and are deliberately left alone. * test_postgres_config_defaults pinned max_connections to the old fixed 10. The default is now derived from the core count, so assert the clamp contract (16..=64) rather than a machine-dependent number. * postgres_integration_string_search_matches_unbackfilled_rows seeded search_index with the bare tenant literal, but `create_tenant` suffixes a UUID for isolation — so the row violated the FK to `resources` and the test failed for its setup rather than its subject. Read the effective tenant id back off the context, as the chained-search test already does.
The #224 fixes moved the search median from 7.18s to 48ms and throughput from 3.0 to 11.5 rps, but the composite shapes still run at 12-13s and time out, and Encounter?status shows a bimodal 8ms median / 27s p95. Those composites measured ~70ms against a synthetic 1.45M-row replica, so the replica's data distribution is not representative and local A/B testing cannot be trusted for them. Capture EXPLAIN (ANALYZE, BUFFERS) against the real imported dataset instead, after VACUUM and before the load starts. The script also A/Bs the correlated-EXISTS composite (rejected earlier on replica numbers: 1ms on a match but 440ms on a zero-match — a trade that looks very different against a 13s baseline) and tests whether disabling the ordered index scan removes the zero-match cliff, which would show the tail is a planner-choice problem rather than missing index coverage.
First real benchmark run — big win, but the headline bug is not fixedRun 29342370727, postgres, 30 VUs / 2m, release build.
The failure increase is the truth surfacing, not a regression. All 27 are searches at exactly 30,002–30,009 ms — the Per-shape attribution (the thing #224 said we couldn't see)Fixed:
Still broken:
Two distinct problems remain:
Note on the
|
Codecov Report❌ Patch coverage is 📢 Thoughts on this report? Let us know! |
…cs on real data The first plan capture reframed both remaining problems, and disproved two of my own hypotheses: * There is NO zero-match cliff. Encounter?status=missing-status runs in 0.8ms. The slow token case is the opposite — status=finished matches ALL 65,659 Encounters, and Postgres estimates the token scan at rows=1832 (a 36x under-estimate), so it materialises 65k ids, does 65k pkey heap fetches, sorts, and returns 21. The v14 statistics cover (param_name, value_token_code) but the query also binds resource_type and all three are correlated, so the marginals are still multiplied independently. Test a 3-column MCV. * The correlated-EXISTS composite, which I was about to adopt, is catastrophic at real scale: only 222 of 656,737 Observations match, so an ordered scan probing per row walks 190k rows to find 21 (8.9s), or all 656k on a zero-match (20s). The shipped grouped subquery is unflattenable, which forces the materialise- then-probe shape — that turns out to be a feature for a sparse composite. The real composite cost is random heap I/O: the OR-prefilter forces a BitmapOr -> Bitmap Heap Scan that reads 113k rows in 111,881 buffer READS — nearly one random page per row on a ~10M-row table. So the prefilter, which reduces rows scanned, is also what causes the I/O. Test a covering index that lets the whole slice be read index-only instead. This has to be measured in CI: a local replica small enough to fit in cache cannot reproduce random heap I/O, and A/B-ing there ranked the covering-index variant LAST — exactly backwards. Read 'Buffers: shared read=' as the metric, not Execution Time.
…stimated
search_index is one wide table, so value_token_code mixes LOINC codes, Encounter
statuses and ActCodes in a single column. Every token search binds resource_type,
param_name AND value_token_code, and the three are near-perfectly correlated —
only Encounter rows carry param_name='status', and only those carry 'finished'.
Postgres multiplies the three marginals independently and lands orders of
magnitude low.
Measured on the benchmark dataset: Encounter?status=finished matches ALL 65,659
Encounters but was estimated at 1,832 rows. On that estimate the planner
materializes every matching id, heap-fetches all 65k rows to sort them, and
returns 21 — 5,261ms. With the correlation captured it walks idx_resources_search
in last_updated order and stops after ~21 rows: 10.4ms, 4 buffers. A 506x
improvement from a statistics change alone.
Controls are unaffected: status=missing-status stays 0.05ms, category=laboratory
11.8ms.
The two-column (param_name, value_token_code) object this migration originally
shipped was not enough — it still left resource_type to be multiplied in
independently. Replaced with the three-column form.
Also corrects the composite commentary in the query builder. The real dataset
(656,737 Observations, 1.8M code-value-quantity rows) disproved every alternative
an earlier, much smaller replica had ranked highly:
* dropping the prefilter and reading the slice index-only from a covering
index: 16.5s (the prefilter is load-bearing)
* correlated EXISTS: 8.9s on a match, 20s on a zero-match — only 222 of 656,737
Observations match, so an ordered scan probing per row walks ~190k rows to
collect 21 hits
The grouped subquery's unflattenability is what forces the correct
materialize-then-probe shape for a sparse composite. It is a feature.
Composite is still ~12s at 30 VUs: the Bitmap Heap Scan fetches ~113k rows in
~112k buffer READS — nearly one random page per row on a ~10M-row table. That is
I/O, and no index shape fixes it. The real fix is storing one row per composite
group with all component values populated; tracked separately.
Real-data plans: two of my own hypotheses were wrongRun 29349631586 + 29354381099 captured First: the dataset is 8x bigger than the issue saysThe issue states "~1.3M
656,737 Observations. The real index is ~10M rows. Every local estimate I made was against a replica ~14x too small on the parameter that matters, and it ranked the candidate fixes backwards. Wrong hypothesis 1: "the zero-match cliff"There is no zero-match cliff. The slow token case is the opposite —
506x, from a statistics change alone. Postgres estimated the token scan at Wrong hypothesis 2: "switch composite to correlated EXISTS"I said in the previous comment that the
Only 222 of 656,737 Observations match this composite (0.03%). Any plan that walks Good thing this was measured rather than shipped on the reasoning in my last comment. What is still brokenComposite remains ~12 s at 30 VUs, and no query or index shape fixes it. The Bitmap Heap Scan fetches ~113k rows in ~112k buffer READS — nearly one random page per row, because a parameter's rows are scattered across a ~10M-row table. That is I/O, not CPU or plan choice. The real fix is a storage change: write one row per composite group with every component's value column populated, so a single index answers Method noteThe composite numbers cannot be A/B'd on a laptop-sized replica: the cost is random heap I/O on a 10M-row table, and any replica that fits in cache has no such cost. Mine ranked the covering-index variant last when in CI it is the only one that touches the I/O at all. Read |
|
Marking ready. The two remaining problems are spun off so they don't block this 149x median / 4.7x throughput win:
Still open on this PR before merge: the import median regression (99.7ms → 530ms), which needs isolating — build mode, four new indexes, and pool 10→32 all changed at once. Happy to attribute that here or in a follow-up, whichever you prefer. |
No code change. 406de2a changed only migration SQL-string literals (2-col -> 3-col MCV) and a comment, which cannot affect compilation or unit tests; this empty commit exists solely to run CI against the current head, since the prior run landed one commit back.
# Conflicts: # crates/persistence/src/backends/postgres/schema.rs
… parsing, and pool-tuning knobs Fills the Codecov gaps on PR #260's new code: - error.rs: the entire RestError::ServiceUnavailable path (Display, the 503/transient client_response mapping, into_response body) plus the full From<BackendError> mapping — Unavailable -> 503, UnsupportedCapability -> 501, and the generic arm collapsing to a sanitized 500. - postgres/backend.rs (no test module existed): parse_connection_string across full URL, the #224 query-string-stripping regression, the postgresql:// scheme, no-password, invalid-port fallback, host:port without dbname, and bare host; the default tuning knobs; and apply_env_overrides for both the set and unparseable-value cases.
1 participant
Fixes #224 (partially — see "What is still broken").
At ~10M
search_indexrows the Postgres backend served FHIR search at a 7.18s median / 51s p99, andObservation?combo-code-value-quantity=reliably timed out with a 500.Result (measured in CI, postgres, 30 VUs / 2m)
The failure count rising is the truth surfacing, not a regression. Every failure is a search cut at exactly 30.0s by
statement_timeout— which previously was armed on 1 pooled connection in 10, so runaway queries mostly ran free to 65s. Now every connection enforces it.Per-shape (the attribution #224 said we lacked — this PR adds it to the workflow):
Encounter?statusp95Observation?component-value-quantitymedianObservation?combo-value-quantityp95Encounter?classmedianPatient?addressmedianOrganization?name/Patient?namemedianreferenceshapesThe fixes
Statistics — a 506x win on its own.
search_indexis one wide table, sovalue_token_codemixes LOINC codes, Encounter statuses and ActCodes in one column. Every token search bindsresource_typeandparam_nameand the code, and the three are near-perfectly correlated. Postgres multiplied the marginals independently:Encounter?status=finishedmatches all 65,659 Encounters but was estimated at 1,832 — a 36x under-estimate — so the planner materialised every id, heap-fetched all 65k rows to sort them, and returned 21 (5,261 ms). A 3-column MCV makes it walk the ordered index and stop after ~21 rows: 10.4 ms, 4 buffers.This is also why the ANALYZE tried earlier in #224 did nothing: no amount of per-column statistics can express a cross-column correlation. (Second reason: after a bulk load
relallvisibleis 0 until a VACUUM runs, so index-only scans silently degrade to heap fetches. ANALYZE never sets the visibility map. The workflow now VACUUMs.)Composite had no value predicate in its
WHEREat all — it aggregated the parameter's whole slice on every request. Now prefiltered. TheGROUP BY resource_id, composite_group+ per-valueHAVINGare untouched: they are what force all components into the same group.OR'd sublinks never become semi-joins. Token/reference OR-lists emitted
id IN (…) OR id IN (…); Postgres only pulls a sublink up into a semi-join from the top-levelAND-list, so under anORit stays a re-executableSubPlan.ILIKEover aCOALESCEis unindexable. Replaced with aLIKEagainstCOALESCE(value_string_folded, lower(value_string))— semantically identical (fold_textalready lowercases;lower()on the raw fallback reproduces whatILIKEdid) but indexable. The fallback is load-bearing:value_string_foldedis populated on write and never backfilled.The pool was pinned at 10 and unreachable —
parse_connection_stringnever consultedHFS_PG_MAX_CONNECTIONS, andHFS_DATABASE_URLtakes that path. By Little's Law ~2/3 of every request's latency was queueing for a connection that did not exist.statement_timeoutwas set on one connection of ten (a session GUC,SETon one borrowed client). This resolves the paradox in the issue — a "30s timeout" producing a 500 at 39.5s and a max of 65.5s.The benchmark built a debug binary. Now
--release.Rejected on real-data measurement (documented in-code)
Every one of these was ranked highly by a local replica and is wrong against the real 656,737-Observation dataset:
EXISTScompositecomposite_groupEXISTS-for-ININidx_search_resourceas redundantOnly 222 of 656,737 Observations match the composite, so any plan that walks
resourcesin sort order and probes per row must traverse ~190k rows to collect 21 hits. The shipped grouped subquery cannot be flattened — which forces Postgres to build the small candidate set and probe by primary key. Its unflattenability is a feature.What is still broken
Composite is still ~12s at 30 VUs, and no query or index shape fixes it. The Bitmap Heap Scan fetches ~113k rows in ~112k buffer reads — nearly one random page per row, because a parameter's rows are scattered across a ~10M-row table. That is I/O. The real fix is a storage change: write one row per composite group with every component's value column populated, so a single index answers
code = X AND value > Y within one groupdirectly. Needs a writer change, a migration and a backfill — worth its own issue.A sparse-match tail. With accurate statistics Postgres now picks the ordered-index scan more often, which is right when many rows match and wrong when almost none do (it walks the whole type).
Observation?codep95 regressed 5.7s → 30s andEncounter?datep95 2.6s → 17.8s, whilestatus/class/quantity improved far more. Net p95 is 1.7x better and throughput 23% better, but this is a real trade and the next thing to attack.Import median moved 99.7 ms → 530 ms. Not yet attributed (build mode, four new indexes, and pool 10→32 all changed at once). Needs isolating before merge.
Safety
Schema v14 is additive only — no index dropped, no query semantics changed; ~6s on 1.45M rows.
initialize_schemanow takes an advisory lock, because several instances routinely share one database (cluster-smokeruns two) andschema_versionis read-then-written without a transaction.Three new tests, all green on the old code too:
composite_group— a two-group blood-pressure panel. The pre-existing single-group test is structurally blind to the cross-group false positive that a careless composite rewrite ships.value_string_foldedis NULL.CI green.