7392bb63 - Index the ledger content-change scan and project financial-log fields in SQL

[TaprootFreak]

Why

All database-backed endpoints on dfxprd were 6–30x slower than usual, while endpoints that touch no database stayed unchanged. I traced this to two independent sources of load and measured both in production.

1. The per-minute content-change scan has no index to use.

The nine ledger consumers each run @DfxCron(EVERY_MINUTE) and call runContentChangeScan, which issues a (updated, id) keyset scan:

WHERE (updated > :scan OR (updated = :scan AND id > :scanId)) ORDER BY updated ASC, id ASC LIMIT 100

None of the nine source tables had an index on updated — I checked 17 tables, none had one. Production EXPLAIN (ANALYZE, BUFFERS) for trading_order (921 MB, the largest):

Parallel Seq Scan on trading_order
  Rows Removed by Filter: 1806023   (x3 workers = 5,418,069 rows)
  Buffers: shared hit=26096 read=63188    -> ~494 MB from disk per call
  rows=4                                  -> 4 matching rows
Execution Time: 151.765 ms

A 45-second delta measurement attributed 4,750 MB of disk reads and 32.5 million rows read to trading_order alone.

2. GET /v1/dashboard/financial/log transfers the whole message JSON.

The endpoint is called twice per minute (121 calls in 2 hours) and the query that runs is the unsampled full-column path.

How that is established — the caller's parameters are not visible in the access log, because morgan here logs the path without the query string (verified: not one log line in a full hour contains a ?, across 5–7 requests/s). The evidence is the SQL actually observed in pg_stat_activity:

SELECT "log"."id", ..., "log"."message", ... FROM "log" "log"
WHERE "log"."system" = $1 AND "log"."subsystem" = $2 AND "log"."severity" = $3
  AND "log"."valid" = $4 AND "log"."created" >= $5
ORDER BY "log"."created" ASC, "log"."id" ASC

Two things follow from its shape: there is no id IN (SELECT MAX(id) ... GROUP BY CAST(created AS DATE)), so dailySample arrives as false (the controller maps a missing parameter to true via dailySample !== 'false', so it cannot be absent); and created >= $5 is present, so from is supplied. There is no upper bound and no LIMIT.

Measured payload of the full matching set (the upper bound of what this path can transfer; the actual per-call volume depends on the caller's from):

message total:                1,316 MB
  assets:                     1,346 MB   <- never read (except one value)
  tradings:                      43 MB   <- never read
  balancesTotal:                2.9 MB   <- needed
  balancesByFinancialType:       31 MB   <- needed

Production query time: 6.6 s median, 29.8 s maximum. In 64 of 168 pg_stat_activity samples this exact query was running, frequently in wait event Client:ClientWrite.

Together these produce roughly 105 MB/s of sustained reads against 5–7 actual requests/s. The Postgres container is capped at 4 GB and sits at 99.99% of that limit with ~62 memory reclaim events/s and pgsteal/pgscan at ~100%, so no working set survives in cache and even GET /v1/asset (18 -> 187 ms) has to hit disk. That container limit lives in the infrastructure repo and is deliberately out of scope here.

Evidence that this is not event-loop saturation: CORS preflights, which go through Express but touch no database, stayed at 0.1 ms in both a healthy and a degraded window (factor 1.2–1.8), while every database-backed endpoint degraded by 6–30x.

What this changes

Part A — new migration adding composite (updated, id) indexes on all nine consumer source tables: trading_order, crypto_input, bank_tx, buy_crypto, exchange_tx, payout_order, buy_fiat, liquidity_management_order, liquidity_order.

Column order is intentional: the query orders by updated, id, so an index on updated alone would still need an explicit Sort whenever rows share an updated value — the same reasoning as AddFinancialLogQueryIndex1785400000000 for (created, id).

CREATE INDEX CONCURRENTLY is not used because migrations here run transactionally and boot-blockingly (migrationsRun, gated by SQL_MIGRATE); CONCURRENTLY is not permitted inside a transaction.

On lock duration, stated precisely: a plain CREATE INDEX holds a SHARE lock for the entire build, so reads continue but writes to that one table block until it finishes. I measured the scan+sort of (updated, id) on the largest table at 1159 ms, but that figure is a work_mem-bound external merge sort spilling ~116 MB to disk — not the index build itself, which sorts in maintenance_work_mem and should be faster, plus the cost of writing ~150 MB of index pages. That points at a low single-digit-second range but is explicitly not a measured upper bound. Judged acceptable because trading_order takes roughly one write every 20 seconds (~4,350 rows/day) and its writers retry.

Part B — new repository method getFinancialLogSummaries projects only the three needed sub-trees in SQL (balancesTotal scalars, the optional BTC priceChf, and the balancesByFinancialType sub-object). assets and tradings are never selected. DashboardFinancialService.getFinancialLog consumes the projection; getBtcCoin() now resolves before the query because the BTC price is projected in SQL, costing one sequential roundtrip that is negligible against the eliminated transfer.

The response is unchanged for the same underlying data. fxPnlChf deliberately stays null in the projection so the existing ?? 0 default remains at the mapping call site rather than being introduced in the data layer.

Behaviour change, stated explicitly

Malformed message JSON now aborts the query instead of silently dropping that one row: message::jsonb fails loud, whereas the previous per-row try/catch returned undefined and the row was filtered out. For a financial dashboard a visible failure is preferable to an unnoticed gap in the series.

I verified against production that this is not a latent risk today, in two separate steps, because JSON validity alone would not have been sufficient evidence:

1. Document validity — casting message::jsonb over all matching rows succeeds; there is no row holding invalid JSON.
2. Value types — the projected scalars are never a non-numeric type, which is what would actually abort the ::float8 cast. Measured type distribution over 31,956 rows:

totalBalanceChf / plusBalanceChf
  number  / number   31952 rows
  absent  / number       3 rows
  null    / null         1 row   (id 1612147: {"plusBalanceChf": null, "minusBalanceChf": 487473.55, "totalBalanceChf": null})

No string or boolean values exist. For the four rows with an absent key or JSON null, ->> yields SQL NULL, which ::float8 casts to NULL rather than failing — confirmed by casting all 31,956 rows in one query without error. Those rows then map to 0, exactly as the previous financeLog.balancesTotal?.totalBalanceChf ?? 0 did, so the response is unchanged for them too.

What this does not cover: a future writer emitting a string into one of these fields would abort the whole query rather than degrade one row. Unlike the neighbouring getFinancialLogAssetPrices, this projection does not guard the cast with jsonb_typeof(...) = 'number'. That is a robustness gap, not a present defect, and is tracked as a follow-up.

What this PR does not promise

Both inefficiencies above are measured facts about the code: reading ~494 MB per call to return four rows, and shipping a message payload of which the endpoint reads three small sub-trees. Removing them is worth doing on its own terms.

It would be wrong, though, to present this as a guaranteed latency figure. Observed p50 of the access-log latency on dfxprd over the same day, at essentially constant request volume (5.5–6.4 req/s throughout):

16:20   23 ms          16:40  113 ms        18:00  394 ms
20:00    8 ms          21:00   17 ms        21:30–03:00  2.2 ms (stable)

During the 2.2 ms stretch the content-change scans were still running at the same rate (a 45 s delta attributed 2,788 MB of disk reads to trading_order alone — more than during a 15 ms window earlier), and GET /v1/dashboard/financial/log was still being called 60 times per hour. So the relationship between this load and end-user latency is not monotonic: the same load coexists with p50 values two orders of magnitude apart, evidently gated by cache state rather than by request volume. There is also an unexplained pattern where restarting the API container alone shifts latency for hours.

In other words: this PR removes two well-documented sources of avoidable database load, and the load reduction itself is straightforwardly verifiable after deploy (index usage via pg_stat_user_indexes, disappearance of the seq scans, transferred payload size). Whether p50 lands at 2 ms or 200 ms afterwards depends on factors this change does not control — notably the 4 GB memory cap on the Postgres container, which is infrastructure and deliberately out of scope here.

Verification

All CI gates mirrored locally: format:check, lint, type-check and the test suites for the touched areas (125 tests, 5 suites, green).

Test sharpness is backed by a mutation run rather than asserted. Baseline green, then five deliberate defects injected one at a time:

M1  plusBalanceChf reads minusBalanceChf in SQL       -> caught
M2  BTC price hardcoded to 42                         -> caught
M3  plus/minus swapped in the balancesByType mapping  -> caught
M4  fxPnlChf defaulted to 0 in the data layer         -> caught
M5  ORDER BY reversed to DESC                         -> NOT caught

M5 is a genuine gap: the ORDER BY created ASC, id ASC guarantee is untested, and it carries both the chart's chronological order and the after keyset pagination. A test for it is still to be added.

The migration SQL was not executed against production.