Skip to content

perf(gs): queue sheet exports, cap unbounded queries and monitor event-loop delay - #4346

Merged
TaprootFreak merged 7 commits into
developfrom
feat/gs-export-queue
Jul 30, 2026
Merged

perf(gs): queue sheet exports, cap unbounded queries and monitor event-loop delay#4346
TaprootFreak merged 7 commits into
developfrom
feat/gs-export-queue

Conversation

@Danswar

@Danswar Danswar commented Jul 23, 2026

Copy link
Copy Markdown
Contributor

Problem

Part of #4227. Investigation of the reported internal-tooling slowness (07-21/22) showed that the dominant share of slow /gs/db requests is not DB work: queries returning 0 rows from tiny tables (e.g. country, 250 rows) took 5–7.5s because sheet-export syncs fire in aligned bursts and their result post-processing runs synchronously on the event loop. Every in-flight request — including interactive support/compliance calls — absorbs those stalls. Additionally, ~22% of slow exports set no maxLine at all (the DTO leaves it optional), so unbounded full-table pulls are possible by omission.

Changes

  1. Export concurrency queue (GsService): POST /gs/db and POST /gs/db/custom now run through a QueueHandler with maxWorkParallel = 2, a 240s queue timeout (below the Apps-Script 6-min execution cap) and a 240s item timeout (a query that never settles frees its worker slot instead of wedging the queue). Exports are latency-tolerant batch consumers; interactive requests no longer compete with a whole burst at once. Both endpoints report failures (incl. queue timeouts) consistently as HTTP 400 — /gs/db/custom previously surfaced errors as opaque 500s.
  2. QueueHandler load-shedding (shared util): items whose queue timeout fired while still waiting are discarded instead of executed — previously their action ran anyway and the result was silently dropped, doubling load exactly when the queue is backed up. Covered by a new queue-handler.spec.ts.
  3. maxLine default cap (GsService): requests without maxLine (absent or null) now run with a cap of 10000 rows instead of unlimited (on the custom bank_tx export the cap applies per sub-query, and the truncation signal is derived per sub-query). Explicit values are untouched (the escape hatch for deliberate large exports, which also keeps the existing >100k alert mail reachable), and the largest observed no-limit export returns ~1.4k rows, so no existing consumer changes behavior. When a default-capped export actually hits the cap, a WARN log names the identifier and table — truncation is visible, not silent.
  4. Event-loop delay monitor (MonitorEventLoopService): logs mean / p95 / max event-loop delay every 10s (same cadence/level as the existing connection-pool monitor, gated by a new Process.MONITOR_EVENT_LOOP). Makes the next slowness report attributable in one log query instead of an elimination hunt.

Tests

  • gs.service.spec.ts: queue caps concurrency at 2 and preserves per-call results; custom exports route through the same queue; default cap applies for absent and null maxLine, explicit values pass through; queue loops stopped in teardown.
  • queue-handler.spec.ts (new): normal execution, discarded-after-timeout items never run, item timeout frees a wedged slot.
  • queue-handler.spec.ts: additionally covers the synchronous-throw case — a synchronously throwing action must reject with its own error rather than sit until the queue timeout, and the worker slot must be free afterwards. Verified by mutation: reverting the deferral in doWork makes exactly that test fail (Expected substring: "boom" / Received message: "Queue timeout" after 1074 ms).
  • Rebased onto develop on 07-30 (the branch had been conflicting since 07-27). Numbers below are from that rebased head, not the original branch state.
  • Changed suites: 450/450 passing; full suite at HEAD: 330 suites, 6043 passed / 174 skipped, 0 failures.

Verification after deploy

  • EventLoop delay lines appear in the API log; during sheet-sync bursts p95 shows the stall magnitude.
  • Interactive endpoint latency (access-log ms values) during burst minutes should drop; /gs/db throughput is unchanged, individual syncs may queue briefly.
  • Any hit the default maxLine cap WARN identifies a sheet that needs pagination or an explicit limit.

@Danswar

Danswar commented Jul 23, 2026

Copy link
Copy Markdown
Contributor Author

4 review passes to zero findings. Fixed along the way: worker slots could wedge permanently on a never-settling query (item timeout added); timed-out queued exports no longer execute after their caller already got an error (load-shedding in the shared queue util, with new spec coverage); the default maxLine cap moved from the DTO into the service so truncation is detected and WARN-logged per bank_tx sub-query instead of on the concatenated total; .take() on the three joined bank_tx raw sub-queries emitted no SQL LIMIT at all (verified via getSql()) and was replaced with .limit(), making the per-sub-query cap real; /gs/db/custom now reports failures as 400 like /gs/db; plus test-hygiene cleanups (typed internals bridge, queue teardown in all suites).

@Danswar
Danswar marked this pull request as ready for review July 23, 2026 19:09
@Danswar
Danswar force-pushed the feat/gs-export-queue branch from e2b81d3 to a35462e Compare July 27, 2026 12:56
@Danswar

Danswar commented Jul 27, 2026

Copy link
Copy Markdown
Contributor Author

Status 2026-07-27 — rebased, and a correction to this PR's premise

Rebased onto current develop. Two import collisions in gs.service.spec.ts (against the debug-allowlist invariants and the coverage-ratchet changes), both resolved as unions — no behavioural change to the diff.

The premise was partly wrong

This PR was written to address the API-wide slow episodes, on the theory that sheet-export post-processing was starving the Node event loop. Measurements taken during a live episode today refute that theory: DB-backed routes run 4–94× slower while /version, /status, /health/* and /v1/country answer in 1–5 ms, unchanged from baseline. Those are served by the same process and recorded by the same request logger, so the event loop is demonstrably free. A fixed 10 s interval logger also shows identical drift in and out of an episode. Full numbers in #4227.

The time is being spent waiting on database round-trips, not in JavaScript.

What is still worth merging here, independent of that theory

  1. .take(n) with leftJoin on getRawMany() emits no SQL LIMIT. The bank_tx legs were genuinely unbounded; switching to .limit() fixes it. This is a real defect and stands on its own.
  2. A default maxLine cap, so an export that omits it can no longer request an unbounded result set — with a WARN raised only when truncation actually occurs.
  3. Queue plus load-shedding for exports, bounding concurrent export work and freeing worker slots that could previously wedge on a query that never settles.

What is now weaker

The event-loop-delay monitor was included as proof-of-mechanism for a mechanism that turns out not to apply here. It is cheap and still reasonable instrumentation, but it is no longer the point of this PR — happy to drop it for a tighter diff if a reviewer prefers.

How to read this PR now

Load reduction and a bounded-query fix, not the cure for the slow episodes. Sheet-export volume is flat at 15–16k requests/h around the clock and does not rise when an episode starts, so this work reduces a standing background cost rather than removing a trigger. The instrument that would settle the remaining question — locks versus disk I/O on the database side — is the slow-query and lock-wait logging prepared in the infrastructure config, which is still unmerged.

@TaprootFreak
TaprootFreak force-pushed the feat/gs-export-queue branch from a35462e to c44d5b6 Compare July 30, 2026 09:46
@github-actions

Copy link
Copy Markdown

❌ TypeScript: 4 errors

The rebase onto develop combined two non-overlapping import additions for the
same identifiers without git flagging a conflict: develop had added its own
DbQueryDto/UserRole imports to this spec while the branch added a second set.
tsc reported four TS2300 "Duplicate identifier" errors, so the suite could not
compile. Merge DbReturnData into the existing absolute-path DbQueryDto import
and drop the duplicate relative-path and UserRole lines.
- queue-handler: defer the action call into the promise chain. A synchronous
  throw previously escaped doWork without ever calling reject, leaving the
  queue item unsettled and hanging the caller until the queue timeout.
- monitor-event-loop: implement OnModuleDestroy and disable the histogram, so
  its 20ms sampling timer stops on teardown instead of running on.
- gs.service: route identifier and table through Util.sanitizeLogValue in
  warnIfCapped; client-controlled values must never land raw in a log line.
- gs.service: replace any[] with Record<string, unknown>[] in the
  getExtendedBankTxData return type per the no-any rule.
Commit 1547091 deferred the action call in QueueItem.doWork so a synchronous
throw rejects the item instead of leaving it unsettled. Add the regression test
that pins that behaviour: a synchronously throwing action must reject with its
own error (not with a queue timeout), and the worker slot must be free for the
next item afterwards. Also switch the spec to the absolute import path and move
the QueueHandler import into the src/shared group, per CONTRIBUTING.
@TaprootFreak

Copy link
Copy Markdown
Collaborator

Rebased onto current develop (the branch had been conflicting since 07-27) and took it through three full review passes — conformance/CONTRIBUTING plus logic/correctness on each — until no unintended defects were left.

Conflict resolution — one conflict, in gs.controller.ts getExtendedData. develop had added the trigger check, this branch the try/catch. The merged result keeps all three concerns:

  • logAndCheckTrigger(query, jwt) stays before the try block, so its own BadRequestException('Trigger type is required') is not re-wrapped into a generic message.
  • the try/catch is preserved (consistent 400 instead of the previous opaque 500).
  • the catch now uses sanitizeLogFields(query) instead of the raw query.table/query.identifier this branch predates — develop introduced that rule ("Client-controlled values must never land raw in any log line") and the sibling getDbData does exactly this.

Fixed during review:

  • gs.service.spec.ts — duplicate DbQueryDto/UserRole imports. The rebase combined two non-overlapping import additions without git reporting a conflict; tsc failed with four TS2300 errors, so the suite could not compile. This also invalidated the "0 failures" claim in the description, which is corrected above.

  • queue-handler.tsthis.action() was evaluated before the .catch chain existed. A synchronously throwing action therefore never reached reject: the item stayed unsettled and the caller hung until the queue timeout (indefinitely without one). The call is now deferred into the promise chain, and a regression test pins it — it asserts rejection with the action's own error, not a queue timeout, and that the worker slot is free afterwards.

    The test was verified by mutation: reverting the deferral makes exactly that test fail, with Expected substring: "boom" / Received message: "Queue timeout" after 1074 ms — i.e. the item was only settled by the queue timeout, which is the hang being fixed. The other three tests stay green, and with the fix in place it passes in 22 ms.

  • monitor-event-loop.service.ts — the histogram was enabled in the constructor and never disabled; its 20 ms sampling timer survived module teardown. Now OnModuleDestroy disables it.

  • gs.service.ts warnIfCappedidentifier/table were interpolated raw into the warning, against the rule above. Both now go through Util.sanitizeLogValue(x, 64), missing identifier renders as missing.

Deliberately left for the author to decide — please confirm or reject:

  1. limit on a OneToMany join (gs.service.ts, getExtendedBankTxData, buyFiat branch). bank_tx.buyFiats is @OneToMany, so limit bounds join rows while transformResultArray later dedupes by the first key. A BankTx with several BuyFiat rows inflates the count before the limit, so fewer than maxLine distinct bank transactions can come back and trailing IDs go missing from the export. The switch away from take was necessary (take emits no LIMIT with joins), so both variants are wrong in different ways. The correct fix is selecting maxLine + 1 distinct bank_tx.ids in a subquery/CTE before joining — a change to export semantics that wants its own PR and a test with multiple BuyFiat per BankTx. This is the one I would prioritise.
  2. Queue timeout surfaces as HTTP 400. A 240 s queue timeout is a server-capacity condition, but reaches the caller as Bad Request. The pattern predates this PR and QueueHandler is shared by ~20 consumers, so it is not a regression — but this PR is the first to exercise it at scale. Mapping queue timeouts to 503 would match the exception table in CONTRIBUTING.md.
  3. stop() does not reject waiting items (queue-handler.ts). It only ends the processing loop; items still queued are never settled, and handle() keeps accepting new ones. For a queue without a timeout their promise stays open forever. Currently latent — QueueHandler.stop() has no production caller today (only tests, after their items settled) — but it would bite the moment stop() is wired to a teardown hook.
  4. any in the raw bank-tx path. The getExtendedBankTxData return type is now Record<string, unknown>[], but the three getRawMany() calls stay ungeneric, so any still flows through and transformResultArray(data: any[]) accepts it — the annotation alone changes nothing at the call site. Tightening it properly collides with Util.sort<T>: its key parameter is KeyType<T, number>, which collapses to never for Record<string, unknown> (every value is unknown), breaking the existing Util.sort(..., 'id', ...) call. Fixing that means touching shared Util.sort or transformResultArray — out of scope here.
  5. length >= maxLine as the truncation signal. An export with exactly maxLine matching rows reports "rows beyond the cap were not returned" although nothing was cut. Fetching maxLine + 1 and trimming would make the signal exact.
  6. Util.timeout never clears its timer (util.ts, outside this diff). Every fast queued export leaves a live 240 s timer and its closure until natural expiry.

@TaprootFreak

Copy link
Copy Markdown
Collaborator

Note on the ❌ TypeScript: 4 errors comment above — it is stale and does not apply to the current head.

Those four errors were the duplicate DbQueryDto/UserRole imports in gs.service.spec.ts, introduced by the rebase and fixed in 625e18c7a. The bot only removes its previous comment when it posts a new one, and it posts nothing when all counters are zero — so a resolved comment stays visible.

Evidence at the current head (f256c2c2e), from the review job log of run 30536483329:

TSC_ERRORS: 0
ESLINT_ERRORS: 0

All 12 checks are green, including Build and checks, all three test shards, Coverage, Coverage ratchet and CodeQL.

@TaprootFreak
TaprootFreak merged commit 292fbaf into develop Jul 30, 2026
12 checks passed
@TaprootFreak
TaprootFreak deleted the feat/gs-export-queue branch July 30, 2026 11:39
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.

2 participants