test(performance): count startup phases and SQL statements for the J1 launch journey (#1715)

* test(performance): count startup phases and SQL statements for the J1 launch journey Implements plan item A2. With IPTVNATOR_PERF_CAPTURE=1 the main process keeps named counters and registers a main-only performance:read-counters IPC handler; without the flag nothing is counted and the handler does not exist. - debug-trace.ts owns the registry; traceStartupPhase replaces the trace('startup', ...) sites and counts main.startupPhases. - The database worker counts executed statements through better-sqlite3's Statement prototype (the verbose callback expands every statement and made bulk inserts 2-4x slower) and posts the count over its message port, flushed before every other worker message. The main-thread shared connection is counted through a new connection observer in the shared database library. - The first main window freezes main.modulesRegisteredBeforeWindow at creation and main.sqlStatementsBeforeReadyToShow at ready-to-show. - The journey gate drops the ready-to-show that Electron emits for the about:blank detour, so the app sees the real document's first paint, and taps the counters handler; the J1 record reads both counters after the renderer probe completes. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> * test(database): require one SQL statement per exec during initialization The performance capture counts one exec call as one statement, because SQL cannot be split reliably in the counter (trigger bodies contain semicolons). The historical-upgrade driver now wraps exec on every connection initDatabase opens and fails on a batch, so that counting assumption holds for the fresh profile and all historical schemas. Documents the definition in the counter and the architecture docs. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> * test(performance): count SQL statements only for the launch journey Codex review: the M3U import, refresh-cancellation and Xtream benchmarks also run with IPTVNATOR_PERF_CAPTURE=1, so the statement hook wrapped every row of their bulk inserts and changed what they measure. SQL counting now also needs IPTVNATOR_PERF_COUNT_SQL=1, which only the launch journey sets; a harness test fails if another source sets it. Startup phases, the window snapshot and the read handler stay on the capture flag. Without SQL counting no ready-to-show listener is attached, so a zero is never reported for statements nobody counted. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> --------- Co-authored-by: 4gray <fourgray@proton.me> Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-16 22:26:16 -08:00 · 2026-09-27 21:01:26 +02:00
1 parent 31c2cb3bbc
commit 1d9a563d1a
@@ -63,7 +63,8 @@ longer in the DOM, and a source card has a non-empty client rect. Counters are
 frozen at that microtask checkpoint, so bridge calls and mutations issued
 later in the same task are included and everything after it is not.

-Three test-side pieces are injected; production code is not changed:
+Three test-side pieces are injected. The app itself only contributes the
+main-process counters below, which exist only with `IPTVNATOR_PERF_CAPTURE=1`:

 - `journey-renderer-gate.cjs` is loaded into the main process with `-r`, the
  mechanism Playwright uses for its own loader. Playwright resolves
@@ -72,7 +73,15 @@ Three test-side pieces are injected; production code is not changed:
  registered afterwards would race the first document. The gate makes the
  first `loadFile` navigate to `about:blank` and holds the real load until
  the test releases it. A 15 s safety timeout releases it on its own and the
-  iteration is then invalid.
+  iteration is then invalid. Electron emits `ready-to-show` for the first
+  paint of a hidden window, and `about:blank` paints too, so the gate drops
+  that event while the window shows `about:blank`; otherwise the app would
+  show a blank window and freeze its `ready-to-show` counter before its own
+  document exists. Electron emits the event again for the real document's
+  first paint because the window is still hidden, which is the moment
+  production sees. The gate also keeps the listener the app registers with
+  `ipcMain.handle('performance:read-counters')`, so the test can call it from
+  the main process.
 - `journey-renderer-probe.ts` is registered with `addInitScript` on that
  `about:blank` page, so it runs at the start of the real document. It
  records that it ran while the document was still `loading` with zero
@@ -92,12 +101,60 @@ Three test-side pieces are injected; production code is not changed:
 | `renderer.layoutShiftScore`        | Sum of `layout-shift` entries with `hadRecentInput === false`, rounded to three decimals (a shift of 0.0001 flips in and out of the cutoff between runs; the CLS "good" threshold is 0.1, so three decimals keep the counter exact without hiding anything a user could see). The cutoff is sampled in a timer queued from the first `requestAnimationFrame` after the terminal batch, that is after the frame that paints the card has been committed; entries delivered live after the terminal batch are buffered and filtered by the same cutoff. |
 | `renderer.longTasks`               | `longtask` entries over 50 ms up to that same cutoff, which includes the task that rendered the card. The count depends on machine speed, so it is evidence until a run shows it is stable on the CI runner.                                                                                                                                                                                                                                                                                                                                          |

+#### Main-process counters
+
+With `IPTVNATOR_PERF_CAPTURE=1`, which the journey sets,
+`apps/electron-backend/src/app/services/debug-trace.ts` keeps named counters
+in the main process (`services/performance-counters.ts`) and `main.ts`
+registers the `performance:read-counters` IPC handler. Without the flag
+nothing is counted, no listener is attached and the handler does not exist;
+the preload never exposes the channel. SQL statements are counted only with
+`IPTVNATOR_PERF_COUNT_SQL=1` as well, because the hook wraps every statement
+execution: the journey sets both, while the M3U, refresh and Xtream
+benchmarks run with the capture flag alone and keep measuring unwrapped
+statements. A harness test fails if any other source sets the SQL flag. After the renderer probe completes,
+`journey-main-counters.ts` calls the handler through `electronApp.evaluate`
+and the gate's tap.
+
+| Counter                               | Source                                                                                                                                                                                                                                                                                   |
+| ------------------------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
+| `main.modulesRegisteredBeforeWindow`  | `main.startupPhases`, one per `traceStartupPhase` call (the phases printed as `[startup]` trace lines), frozen right after the first main window is constructed.                                                                                                                         |
+| `main.sqlStatementsBeforeReadyToShow` | `main.sqlStatements`, frozen at the first main window's `ready-to-show`. It counts the statements of the main-thread connection (`sql-main`, schema creation and migrations) and of the database worker, which posts its count over its message port ([DB worker](sqlite-db-worker.md)). |
+
+Main-thread statements are counted synchronously. The worker flushes its
+count before every other message it posts, so every worker statement whose
+response the main process has handled is included. The worker count is
+ordered against the worker's responses, not against wall-clock: statements
+whose count is still in flight when `ready-to-show` is dispatched are not.
+One call of `run`, `get`, `all`, `iterate` or `exec` that returns normally is
+one statement; on the launch workloads this matches the number of SQL trace
+lines exactly. An `exec` with several statements would count as one, so the
+shared connection passes one statement per call, and its historical-upgrade
+test fails on a batch.
+
+`main.sqlStatementsBeforeReadyToShow` is not yet deterministic. The main
+thread runs the shared connection's schema creation and migrations (about 90
+statements on the J1 profile) in one synchronous block after the load event,
+and `ready-to-show` is dispatched after it. The stale-download and
+stale-recording recovery that follows (one statement each) races the event,
+so iterations differ by two and the summary marks the counter
+`stable: false`. The database worker runs no statement before the first
+paint.
+Each frozen counter carries its epoch. The record refuses an iteration whose
+window counter was frozen after the gate saw the first load, or whose
+`ready-to-show` counter was frozen before the gate released the real
+document. Running totals at read time are kept under
+`evidence.mainCountersAtRead`, the freeze epochs under
+`evidence.epochs.mainWindowCreated` and `evidence.epochs.mainReadyToShow`, and
+the number of dropped blank `ready-to-show` events under
+`evidence.rendererGateReadyToShowHeldOnBlank`.
+
 Counters are exact: the summary carries the value shared by every measured
 iteration. When iterations disagree, the summary reports the maximum and marks
 the counter `stable: false` under `counterStability`; such a counter is not
 promoted to a guardrail until it is deterministic.

-Two counters from the plan are listed under `unavailable` with the reason
+One counter from the plan is listed under `unavailable` with the reason
 instead of being faked:

 - `renderer.cdTicksToFirstCard`: the `electron-performance` build optimizes
@@ -105,10 +162,6 @@ instead of being faked:
  `window.ng` and `ɵsetProfiler` is unavailable. The probe checks this at the
  terminal moment and the record refuses a build where the hook exists but was
  not counted.
- `main.sqlStatementsBeforeReadyToShow`: SQL statements are only visible as
-  worker-thread trace lines on stdout, which Node forwards asynchronously, so
-  they cannot be ordered against `ready-to-show`. Plan item A2 adds a channel
-  that can be counted.

 ### Wall-clock

@@ -444,6 +444,29 @@ first, this receipt remains distinct from the later authoritative
 exposing the pending request. Disabled profiling performs no receipt clock or
 transport work, and `DatabaseWorkerClient.cancel()` remains fire-and-return.

+With `IPTVNATOR_PERF_CAPTURE=1` and `IPTVNATOR_PERF_COUNT_SQL=1`, the worker
+connection also counts the SQL statements it executes and posts `performance-sql-statements` messages that
+carry only a positive count, never SQL text or bound values. Counts are
+coalesced per microtask and flushed before every other worker message, so a
+response never overtakes the statements that produced it.
+`DatabaseWorkerClient` adds them to the main-process `main.sqlStatements`
+counter and settles nothing. Statements are counted by wrapping the
+execution methods of better-sqlite3's `Statement` prototype and the
+connection's `exec`, not through the `verbose` callback: a callback makes
+better-sqlite3 expand every statement's SQL, which made bulk inserts two to
+four times slower. Counting still adds a JavaScript call per row of a bulk
+insert, so it needs `IPTVNATOR_PERF_COUNT_SQL` on top of the capture flag:
+only the launch journey sets it, and the import benchmarks that run with the
+capture flag measure unwrapped statements. A call that throws is not counted, which matches the SQL
+trace for statements that fail before execution. One `exec` call counts as
+one statement, so initialization passes one statement per call; the
+historical-upgrade test enforces it. The main process counts its
+own shared connection the same way (`services/main-sql-statement-count.ts`,
+through the shared library's connection observer). Without the flag both
+connections are opened unchanged. See
+`workers/database-worker-sql-statement-count.ts` and
+[performance journeys](performance-journeys.md).
+
 ## Renderer Contract

 The preload bridge keeps the existing database methods but adds scoped worker
@@ -30,7 +30,8 @@ IPTVNATOR_TRACE_STARTUP=1 pnpm nx serve electron-backend
    - `IPTVNATOR_TRACE_WINDOW=1` traces BrowserWindow lifecycle and unresponsive events
    - `IPTVNATOR_TRACE_PLAYER=1` traces external-player activity and bounded Embedded MPV runtime-probe stderr
    - `IPTVNATOR_TRACE_RENDERER_CONSOLE=1` mirrors renderer console output into the Electron terminal
-    - `IPTVNATOR_PERF_CAPTURE=1` enables development/test-only, redacted M3U and Xtream preload IPC request/completion markers plus count-only M3U acquire/parse/normalize, Xtream main network/JSON-transform/success-response-ready/cancel-dispatch, and renderer store phase capture; renderer wrappers emit only while the benchmark installs its Symbol hook, benchmark tooling sets the flag explicitly, and production launches must leave it unset
+    - `IPTVNATOR_PERF_CAPTURE=1` enables development/test-only, redacted M3U and Xtream preload IPC request/completion markers plus count-only M3U acquire/parse/normalize, Xtream main network/JSON-transform/success-response-ready/cancel-dispatch, and renderer store phase capture; renderer wrappers emit only while the benchmark installs its Symbol hook, benchmark tooling sets the flag explicitly, and production launches must leave it unset. It also keeps count-only main-process counters (startup phases, database worker SQL statements, and their values at main-window creation and `ready-to-show`) and registers the main-only `performance:read-counters` IPC handler, which the preload does not expose; see [performance journeys](../architecture/performance-journeys.md)
+    - `IPTVNATOR_PERF_COUNT_SQL=1`, together with `IPTVNATOR_PERF_CAPTURE=1`, also counts every SQL statement of the main-process and database-worker connections for `main.sqlStatementsBeforeReadyToShow`; it wraps each statement execution, including every row of a bulk insert, so only the launch journey sets it and the import benchmarks leave it unset
    - `IPTVNATOR_PERF_WORKER_PROFILING=1` enables development/test-only, request-scoped worker receive/work/response-post timestamps, thread CPU, event-loop utilization/delay, count-only playlist serialization/SQLite write/read/deserialization plus Xtream category/content/cache-clear/delete/in-source-search phase events, profiling-only worker cancel-receipt acknowledgements, valid-sample-counted isolate peak memory, and the database worker's idle-only one-shot post-GC heap probe; overlapping database requests are explicitly invalidated instead of misattributed, the performance benchmark sets the flag automatically, and production launches must leave it unset
    - `IPTVNATOR_DISABLE_COMPILE_CACHE=1` disables the main-process V8 compile cache; `IPTVNATOR_COMPILE_CACHE_DIR=<dir>` relocates it. The startup trace reports the outcome as `compile-cache`