Skip to content

02adf11f - Merge the two log indexes, close ledger master-switch test gaps, report non-finite prices, fix the AsyncCache invalidation race - #4534

Draft
TaprootFreak wants to merge 4 commits into
developfrom
fix/4531-performance-follow-ups
Draft

02adf11f - Merge the two log indexes, close ledger master-switch test gaps, report non-finite prices, fix the AsyncCache invalidation race#4534
TaprootFreak wants to merge 4 commits into
developfrom
fix/4531-performance-follow-ups

Conversation

@TaprootFreak

Copy link
Copy Markdown
Collaborator

Closes #4531.

Works through all four follow-ups from the performance work merged on 2026-07-30 (#4519, #4520, #4521, #4527). Point 1 ends differently than the issue proposed — the measurement contradicted the premise.

1. The log index: not worthless, cut wrong

The issue asked whether IDX_b7eda1156aca7b2a1302cdf88f (42 MB, 25 idx_scan) earns its keep next to IDX_log_financial_query (46 MB, 16'687 idx_scan), and proposed dropping it. Measuring first turned that around.

The index was added by #4519 so the Overview chart query would be served by an Index Only Scan. It cannot do that. The query selects created, id, "totalBalanceChf", "btcPriceChf", and id is neither a key nor an INCLUDE column of that index — so the planner falls back to IDX_log_financial_query and the scan is not index-only. Production EXPLAIN (ANALYZE, BUFFERS), over the full 33'136-row result:

Query Plan Buffers Time
The real one, id in the select list Index Scan using IDX_log_financial_query hit=2806 read=9222 163.2 ms
Same query, id removed Index Only Scan using IDX_b7eda… hit=2272 read=623 12.8 ms

The 6.0 ms quoted in the issue holds only with a time window. The single production caller (dashboard-financial.service.ts:34-42) passes to, limit and after as undefined throughout, so the query carries no LIMIT — the 163 ms row is the one that runs.

So a single column separates the two plans. Rather than drop the index and keep the slow plan, this replaces both indexes with one that does both jobs:

IDX_5e9ca4be25d4b828fe02a2dddf
  ON log (system, subsystem, severity, valid, created, id)
  INCLUDE ("totalBalanceChf", "btcPriceChf")

Its key columns are identical to IDX_log_financial_query, so every access path that index serves today — all 16'687 scans, including the per-minute LedgerMarkService query it was built for — is served unchanged, with the same ordering and selectivity. The two payload columns ride along as INCLUDE, which makes the chart query index-only-capable. One index instead of two, roughly 54 MB instead of 88 MB.

On the evidence for that last claim, stated precisely: the combined plan itself was not measured — hypopg is not available on the production database, so no hypothetical index could be planned. What is measured is both halves. The dailySample subquery already gets an Index Only Scan using IDX_log_financial_query (Heap Fetches 91 of 33'136), which shows the key columns including id are index-only-servable and the visibility map is in good shape. Measurement D above shows the INCLUDE columns are too. An index holding both column sets covers all four selected columns; that is a conclusion from two measurements, not a third measurement.

Migration ordering follows from the lock behaviour: CREATE INDEX first, both DROP INDEX last. All pending migrations share one transaction (migrationsTransactionMode: 'all'), and Postgres holds locks until COMMIT — so the ACCESS EXCLUSIVE taken by each DROP blocks reads on log for the rest of the run. Building first keeps that window as late and short as possible. It also means this migration is best deployed on its own. CREATE INDEX CONCURRENTLY is not an option inside a transaction, same as for its two predecessors.

The index name is the deterministic TypeORM DefaultNamingStrategy name, not a chosen one (CONTRIBUTING.md:100,630, „no custom index names"). The formula was cross-checked by reproducing the existing IDX_b7eda1156aca7b2a1302cdf88f from it. As a side effect log is left with only deterministically named indexes — IDX_log_financial_query was itself a custom name.

2. Ledger master switch: test gaps (#4521)

All three gaps from the issue, in ledger-master-switch.spec.ts and its sibling:

  • crypto-input-cutover.integration.spec.ts now resets Config.ledger.enabled in an afterEach, matching the three sibling specs that already did (staleness-cutover.integration.spec.ts:331-333, ledger-booking-job.service.spec.ts:71-73, ledger-cutover.service.spec.ts:214-216). Not exploitable before — every beforeEach builds a fresh ConfigService — but it was the one file out of four that differed.
  • Discovery now walks the full prototype chain via MetadataScanner.getAllMethodNames(), the very scanner DfxCronService.onModuleInit uses in production, instead of a single Object.getOwnPropertyNames() level. A cron on an inherited method is registered in production and was invisible to this test; the two views can no longer disagree. No discovered entry is lost — getAllMethodNames is a superset that only drops constructor and accessors.
  • A new test fails on any accounting provider carrying Nest-native @Cron metadata. Such a method is started by @nestjs/schedule directly, so it never reaches DfxCronService — it would be silently absent from discovery: scheduled in production, never shown to consult the master switch, and out of reach of its Process kill-switch as well. Native @Cron is used legitimately elsewhere (transaction-request.service.ts:52,61), so the guard targets the ledger providers, not the import. Green today.

Both checks share one scanProviderMethods() helper so they can never disagree about which methods are in scope. SCHEDULE_CRON_OPTIONS is held as a string literal on purpose: the constant lives in @nestjs/schedule/dist/schedule.constants and is not re-exported from the package root, so importing it would couple the test to the package's dist internals.

3. Non-finite prices in the dashboard aggregation (#4520)

buildLatestBalance now reports a non-finite priceChf through logger.error, once per asset entry, before the Scrypt/else split that multiplies it in either branch. The arithmetic is unchanged, character for character — no ?? 0, no substitution, no skipped entry. Booking a broken price as zero is exactly the masking this codebase avoids, so the guard reports and leaves the value alone; the style follows log-job.service.ts:152-154, which does the same for a non-finite total.

null is deliberately exempt: approxPriceChf is nullable, 144 of 430 production assets hold NULL, and total * null === 0 just as before the round-trip was removed. Logging those would drown the signal. The comparison is strictly !== null so that undefined does not share the exemption — it produces NaN.

Worth recording, because it makes the silence worse than the issue assumed: the damage differs per path. In the else branch NaN poisons the whole blockchain total. In the Scrypt branch a NaN price makes the position vanish instead, because spotChf > 0 is false for NaN. And -Infinity wipes out the entire blockchain group including the healthy assets on it, via rounded <= 0 → continue. All three were completely silent.

Three new tests cover NaN, Infinity and undefined; each asserts one logger.error and the uncorrected aggregate, so a later "fix" that quietly normalises to 0 breaks them. The existing null test gained an assertion that nothing is logged.

Related finding, not fixed here: the same non-finite value also flows through LogJobService.getBalancesByFinancialType (log-job.service.ts:277-287), where Util.roundReadable does not filter it either, so it reaches the byType buckets. That path is already loud, though — log-job.service.ts:152-154,163-165 logs and trips safety mode on a non-finite total. The blockchain aggregation was the only silent one, and that is what this closes. A fix at the root belongs in getAssetLog/getBalancesByFinancialType.

4. AsyncCache.invalidate() outlived by an in-flight refresh

A refresh now captures an instance-wide generation counter when it starts and writes its result back only if the counter is still unchanged. invalidate() bumps it in both its forms, so any refresh already in flight loses its write-back instead of undoing the invalidation for up to a full validity period.

The counter is deliberately instance-wide rather than per key. invalidate('a') therefore also discards an in-flight refresh for 'b' — conservative on purpose and harmless, because the caller still receives its data and only the cache entry is missing, to be re-fetched on next access.

Two things had to change with it:

  • get() now hands the fetched data through instead of reading it back from the cache. return this.cache.get(id).data would be a TypeError on undefined as soon as a write-back is discarded.
  • In-flight promises moved into their own map, which makes an entry without data/updated unrepresentable. The old .finally handler spread a possibly-deleted entry ({ ...this.cache.get(id), update: undefined }) and could leave exactly such a half-written entry behind.

Dedup and fallbackToCache semantics are unchanged; public signatures, forceUpdate and the TTL behaviour are untouched. 19 new tests cover the race, the pass-through, dedup, fallbackToCache in both directions, TTL expiry and both invalidate() forms.

One existing test had to be corrected, and it is worth saying why: bitcoin-fee.service.spec.ts passed only because of the half-written entry. It made cache.has(id) true, so fallbackToCache found something to fall back to and swallowed the error into undefined. The test is named „should throw when fee estimation fails and no cache available" but never asserted that — its own comments conceded the uncertainty („it may return undefined or throw", „The actual behavior depends on AsyncCache implementation", „we just verify the estimateSmartFee was called"). It now asserts what its name promises. This was predicted from reading the code before the suite was run, and the run confirmed it.

Verification

Run locally, all green:

  • full Jest suite (see below)
  • npx eslint and npx prettier --check on every touched file
  • migration-psql-check.spec.ts, which scans migrations above a timestamp cutoff for MSSQL-only patterns

Production measurements for point 1 were taken read-only against the production database (pg_stat_user_indexes, pg_stat_user_tables, EXPLAIN (ANALYZE, BUFFERS)). No DDL was run there.

IDX_b7eda1156aca7b2a1302cdf88f was added to make the Overview chart query
index-only. It cannot: the query selects created, id, totalBalanceChf and
btcPriceChf, and id is neither a key nor an INCLUDE column, so the planner
falls back to IDX_log_financial_query. Production EXPLAIN (ANALYZE, BUFFERS)
over the full 33136-row result: 163.2 ms with id in the select list, 12.8 ms
without it. One column separates the two plans.

The replacement keeps the key columns of IDX_log_financial_query, so all
16687 scans it serves today are unaffected, and carries the two payload
columns as INCLUDE so the chart query becomes index-only-capable. One index
instead of two, roughly 54 MB instead of 88 MB.

CREATE first, both DROPs last: all pending migrations share one transaction
and Postgres holds locks until COMMIT, so the ACCESS EXCLUSIVE taken by a
DROP blocks reads on log for the rest of the run. Building first keeps that
window as late and short as possible.
Reset Config.ledger.enabled in an afterEach in crypto-input-cutover, the one
spec of four that set the flag without restoring it.

Discover cron methods through MetadataScanner.getAllMethodNames, the scanner
DfxCronService uses in production, instead of a single getOwnPropertyNames
level. A cron on an inherited method is registered in production and was
invisible here.

Fail on any accounting provider carrying Nest-native @Cron metadata. Such a
method is started by @nestjs/schedule directly, never reaches DfxCronService,
and would be silently absent from discovery: scheduled in production, never
shown to consult the master switch, and beyond its Process kill-switch too.

Both checks share one scanProviderMethods helper so they cannot disagree
about which methods are in scope.
…ls silently

Moving the dashboard aggregation off the JSON round-trip means NaN, Infinity
and undefined now reach the arithmetic directly; JSON.stringify used to
collapse them to null on the way in. buildLatestBalance now logs such a value
once per asset entry and leaves it strictly alone: booking a broken price as
zero would hide the very defect that needs fixing upstream.

null stays exempt. approxPriceChf is nullable, 144 of 430 production assets
hold NULL, and total * null is 0 exactly as before. The comparison is
strictly !== null so undefined does not share that exemption, since it
produces NaN.

The silence was worse than it looks: in the else branch NaN poisons the whole
blockchain total, in the Scrypt branch it makes the position vanish because
spotChf > 0 is false for NaN, and -Infinity wipes out the entire blockchain
group including the healthy assets on it.

Tests cover all three inputs and assert the uncorrected aggregate, so a later
silent normalisation to zero breaks them.
A refresh started before invalidate() wrote its result back afterwards, with
a fresh timestamp, so the invalidation was undone for up to a full validity
period. A refresh now captures an instance-wide generation counter when it
starts and writes back only if the counter is unchanged. Callers depend on
invalidation taking effect at once: FiatService.updatePrice() writes a price
and then invalidates the repository cache, and fiat.controller.ts states that
assumption in so many words.

The counter is deliberately instance-wide, not per key. invalidate('a') also
discards an in-flight refresh for 'b', which is harmless: the caller still
receives its data, only the cache entry is missing and is re-fetched.

get() now hands the fetched data through instead of reading it back from the
cache, which would be a TypeError on undefined once a write-back is discarded.

In-flight promises move to their own map, so an entry without data/updated is
now unrepresentable. The old finally handler spread a possibly deleted entry
and could leave one behind.

bitcoin-fee.service.spec only passed because of that half-written entry: it
made cache.has(id) true, so fallbackToCache swallowed the error into
undefined. The test claims 'should throw' and never asserted it - its own
comments concede it was unsure what the behaviour was. It now asserts what
its name promises.
@TaprootFreak

Copy link
Copy Markdown
Collaborator Author

Verification status

CI is green across all 12 checks on 43711518d, including the coverage ratchet, CodeQL and all three test shards.

Run locally against the branch before pushing:

Check Result
Full Jest suite 340 suites, 6228 tests, 0 failures
npm run type-check (incl. tests) clean
npm run format:check clean
npx eslint on every touched file clean
migration-psql-check.spec.ts pass

The production measurements behind point 1 were taken read-only (pg_stat_user_indexes, pg_stat_user_tables, EXPLAIN (ANALYZE, BUFFERS)). No DDL was executed against production.

Still open — do not read this as reviewed: the mandatory review pass has not run yet, so this stays a draft. Two things in it deserve a reviewer's attention specifically:

  1. Point 1 deliberately departs from what the issue proposed. The issue asked whether to drop the new index; the measurement showed it fails its purpose only because id is missing from it, so it is repaired rather than dropped. The combined plan itself could not be measured — hypopg is not installed on the production database — and is stated in the description as a conclusion drawn from two separate measurements, not as a measured plan. That inference is the main thing worth challenging.
  2. The migration's lock window. CREATE INDEX first, both DROP INDEX last, because all pending migrations share one transaction and locks are held until COMMIT. This migration is best deployed on its own; batching it with others stretches the window in which log is unreadable.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Follow-ups from the 2026-07-30 performance work

1 participant