diff --git a/apps/electron-backend-e2e/src/journeys/journey-renderer-gate-client.ts b/apps/electron-backend-e2e/src/journeys/journey-renderer-gate-client.ts index 9fe311cb1..91387fc9d 100644 --- a/apps/electron-backend-e2e/src/journeys/journey-renderer-gate-client.ts +++ b/apps/electron-backend-e2e/src/journeys/journey-renderer-gate-client.ts @@ -12,6 +12,8 @@ export interface JourneyRendererGateState { readonly gatedEpochMs: number | null; readonly gatedMethod: string | null; readonly passThroughLoads: number; + /** `ready-to-show` events dropped while the window was on about:blank. */ + readonly readyToShowHeldOnBlank: number; readonly releasedEpochMs: number | null; readonly timedOut: boolean; } diff --git a/apps/electron-backend-e2e/src/journeys/launch-journey-app.ts b/apps/electron-backend-e2e/src/journeys/launch-journey-app.ts index 93eb52f1e..4e59103d8 100644 --- a/apps/electron-backend-e2e/src/journeys/launch-journey-app.ts +++ b/apps/electron-backend-e2e/src/journeys/launch-journey-app.ts @@ -24,6 +24,10 @@ import { JOURNEY_RENDERER_API_TRACE_CHANNEL, readJourneyMainIpcCapture, } from '../performance/journey-main-ipc-capture'; +import { + assertJourneyMainCounters, + readJourneyMainCounters, +} from '../performance/journey-main-counters'; import { createLaunchJourneyProbeOptions, installJourneyRendererProbe, @@ -124,9 +128,17 @@ export async function measureLaunchJourney( ); try { await cp(templateDirectory, dataDirectory, { recursive: true }); + // IPTVNATOR_PERF_CAPTURE turns on the main-process counters and + // their read handler, IPTVNATOR_PERF_COUNT_SQL the SQL statement + // count behind main.sqlStatementsBeforeReadyToShow; only this journey + // sets it. See journey-main-counters.ts. const env = buildElectronLaunchEnvironment( dataDirectory, - launchOptions({ IPTVNATOR_TRACE_IPC: '1' }) + launchOptions({ + IPTVNATOR_PERF_CAPTURE: '1', + IPTVNATOR_PERF_COUNT_SQL: '1', + IPTVNATOR_TRACE_IPC: '1', + }) ); const args = buildElectronLaunchArgs([ '-r', @@ -188,6 +200,14 @@ export async function measureLaunchJourney( JOURNEY_MAIN_IPC_STATE_KEY, 10_000 ); + // Read after the probe finished, so both frozen counters exist. + const mainCounters = assertJourneyMainCounters( + await readJourneyMainCounters( + electronApp, + JOURNEY_RENDERER_GATE_KEY + ), + gate + ); if (ipc.installedEpochMs > renderer.installed.epochMs) { throw new Error('journey-main-ipc-capture-installed-late'); } @@ -198,6 +218,7 @@ export async function measureLaunchJourney( electronVersion, gate, ipc, + mainCounters, pid: electronApp.process().pid ?? -1, renderer, spawnEpochMs, diff --git a/apps/electron-backend-e2e/src/performance/journey-main-counters.spec.ts b/apps/electron-backend-e2e/src/performance/journey-main-counters.spec.ts new file mode 100644 index 000000000..34684c01d --- /dev/null +++ b/apps/electron-backend-e2e/src/performance/journey-main-counters.spec.ts @@ -0,0 +1,147 @@ +import assert from 'node:assert/strict'; +import { readdirSync, readFileSync } from 'node:fs'; +import { join, relative, resolve } from 'node:path'; +import test from 'node:test'; + +import { + assertJourneyMainCounters, + JOURNEY_MAIN_COUNTER, + JOURNEY_PERFORMANCE_COUNTERS_CHANNEL, +} from './journey-main-counters'; + +const gate = { gatedEpochMs: 1_020, releasedEpochMs: 1_150 }; + +function snapshot( + counters: Record = {}, + frozenAtEpochMs: Record = {} +) { + return { + counters: { + 'main.modulesRegisteredBeforeWindow': 2, + 'main.sqlStatements': 40, + 'main.sqlStatementsBeforeReadyToShow': 12, + 'main.startupPhases': 9, + ...counters, + }, + frozenAtEpochMs: { + 'main.modulesRegisteredBeforeWindow': 1_010, + 'main.sqlStatementsBeforeReadyToShow': 1_300, + ...frozenAtEpochMs, + }, + }; +} + +test('mirrors the channel and counter names of the app', () => { + assert.equal( + JOURNEY_PERFORMANCE_COUNTERS_CHANNEL, + 'performance:read-counters' + ); + assert.deepEqual(Object.values(JOURNEY_MAIN_COUNTER).sort(), [ + 'main.modulesRegisteredBeforeWindow', + 'main.sqlStatements', + 'main.sqlStatementsBeforeReadyToShow', + 'main.startupPhases', + ]); +}); + +test('accepts a snapshot frozen at window creation and after the release', () => { + const value = snapshot(); + assert.deepEqual(assertJourneyMainCounters(value, gate), value); +}); + +test('accepts zero statements before ready-to-show with no running total', () => { + const value = snapshot({ 'main.sqlStatementsBeforeReadyToShow': 0 }); + delete (value.counters as Record)['main.sqlStatements']; + assert.equal( + assertJourneyMainCounters(value, gate).counters[ + 'main.sqlStatementsBeforeReadyToShow' + ], + 0 + ); +}); + +test('rejects malformed or incomplete snapshots', () => { + for (const value of [ + null, + { counters: {} }, + { counters: { 'main.sqlStatements': -1 }, frozenAtEpochMs: {} }, + { counters: { 'main.sqlStatements': 1.5 }, frozenAtEpochMs: {} }, + { counters: [], frozenAtEpochMs: {} }, + ]) { + assert.throws( + () => assertJourneyMainCounters(value, gate), + /malformed/ + ); + } + const unfrozen = snapshot(); + delete (unfrozen.frozenAtEpochMs as Record)[ + 'main.sqlStatementsBeforeReadyToShow' + ]; + assert.throws( + () => assertJourneyMainCounters(unfrozen, gate), + /not-frozen: main.sqlStatementsBeforeReadyToShow/ + ); + assert.throws( + () => + assertJourneyMainCounters(snapshot(), { + gatedEpochMs: null, + releasedEpochMs: 1_150, + }), + /gate-incomplete/ + ); +}); + +test('rejects snapshots that were not frozen at the moments they claim', () => { + assert.throws( + () => + assertJourneyMainCounters( + snapshot({}, { 'main.modulesRegisteredBeforeWindow': 1_030 }), + gate + ), + /window-after-first-load/ + ); + // ready-to-show of about:blank, before the real document was released. + assert.throws( + () => + assertJourneyMainCounters( + snapshot({}, { 'main.sqlStatementsBeforeReadyToShow': 1_100 }), + gate + ), + /ready-to-show-before-release/ + ); + assert.throws( + () => + assertJourneyMainCounters( + snapshot({ 'main.sqlStatements': 11 }), + gate + ), + /total-below-frozen: main.sqlStatements/ + ); + assert.throws( + () => + assertJourneyMainCounters( + snapshot({ 'main.startupPhases': 1 }), + gate + ), + /total-below-frozen: main.startupPhases/ + ); +}); + +test('only the launch journey opts into SQL statement counting', () => { + // The import benchmarks also run with IPTVNATOR_PERF_CAPTURE=1; the SQL + // hook wraps every row of a bulk insert, so they must not enable it. + const sourceRoot = resolve(__dirname, '..'); + const files = readdirSync(sourceRoot, { recursive: true }) + .map(String) + .filter( + (file) => /\.(ts|cjs)$/.test(file) && !/\.spec\.ts$/.test(file) + ); + const optedIn = files + .filter((file) => + readFileSync(join(sourceRoot, file), 'utf8').includes( + 'IPTVNATOR_PERF_COUNT_SQL' + ) + ) + .map((file) => relative(sourceRoot, join(sourceRoot, file))); + assert.deepEqual(optedIn, [join('journeys', 'launch-journey-app.ts')]); +}); diff --git a/apps/electron-backend-e2e/src/performance/journey-main-counters.ts b/apps/electron-backend-e2e/src/performance/journey-main-counters.ts new file mode 100644 index 000000000..e71d37a4b --- /dev/null +++ b/apps/electron-backend-e2e/src/performance/journey-main-counters.ts @@ -0,0 +1,138 @@ +import type { ElectronApplication } from '@playwright/test'; + +import type { JourneyRendererGateState } from '../journeys/journey-renderer-gate-client'; + +/** + * Test-side reader for the main-process performance counters + * (`apps/electron-backend/src/app/services/performance-counters.ts`). The app + * registers `performance:read-counters` only with IPTVNATOR_PERF_CAPTURE=1 + * and the preload does not expose it, so the journey calls the registered + * handler from the main process through the gate's `ipcMain.handle` tap + * (`journey-renderer-gate.cjs`). + */ + +/** Literal of `PERFORMANCE_COUNTERS_READ_CHANNEL`. */ +export const JOURNEY_PERFORMANCE_COUNTERS_CHANNEL = 'performance:read-counters'; + +/** Literals of `PERFORMANCE_COUNTER`. */ +export const JOURNEY_MAIN_COUNTER = { + MODULES_REGISTERED_BEFORE_WINDOW: 'main.modulesRegisteredBeforeWindow', + SQL_STATEMENTS: 'main.sqlStatements', + SQL_STATEMENTS_BEFORE_READY_TO_SHOW: 'main.sqlStatementsBeforeReadyToShow', + STARTUP_PHASES: 'main.startupPhases', +} as const; + +export interface JourneyMainCountersState { + readonly counters: Readonly>; + readonly frozenAtEpochMs: Readonly>; +} + +export async function readJourneyMainCounters( + electronApp: ElectronApplication, + gateKey: string +): Promise { + return electronApp.evaluate( + async (_electron, input) => { + const gate = (globalThis as unknown as Record)[ + input.gateKey + ] as + | { invokeHandler?: (channel: string) => Promise } + | undefined; + if (typeof gate?.invokeHandler !== 'function') { + throw new Error('journey-main-counters-gate-missing'); + } + const snapshot = await gate.invokeHandler(input.channel); + return JSON.parse(JSON.stringify(snapshot ?? null)) as unknown; + }, + { channel: JOURNEY_PERFORMANCE_COUNTERS_CHANNEL, gateKey } + ); +} + +function isCountRecord(value: unknown): value is Record { + return ( + typeof value === 'object' && + value !== null && + !Array.isArray(value) && + Object.values(value).every( + (entry) => Number.isSafeInteger(entry) && (entry as number) >= 0 + ) + ); +} + +function isEpochRecord(value: unknown): value is Record { + return ( + typeof value === 'object' && + value !== null && + !Array.isArray(value) && + Object.values(value).every( + (entry) => typeof entry === 'number' && entry > 0 + ) + ); +} + +/** + * Accepts a snapshot only when it proves the ordering its counters claim: + * the startup phases were frozen when the window was created (before the + * gate saw its first load), and the SQL count at a `ready-to-show` that came + * after the gate released the real document. + */ +export function assertJourneyMainCounters( + value: unknown, + gate: Pick +): JourneyMainCountersState { + const snapshot = value as Partial | null; + if ( + !snapshot || + !isCountRecord(snapshot.counters) || + !isEpochRecord(snapshot.frozenAtEpochMs) + ) { + throw new Error('journey-main-counters-malformed'); + } + const { counters, frozenAtEpochMs } = snapshot; + const frozen = [ + JOURNEY_MAIN_COUNTER.MODULES_REGISTERED_BEFORE_WINDOW, + JOURNEY_MAIN_COUNTER.SQL_STATEMENTS_BEFORE_READY_TO_SHOW, + ]; + for (const name of frozen) { + if ( + counters[name] === undefined || + frozenAtEpochMs[name] === undefined + ) { + throw new Error(`journey-main-counters-not-frozen: ${name}`); + } + } + if (gate.gatedEpochMs === null || gate.releasedEpochMs === null) { + throw new Error('journey-main-counters-gate-incomplete'); + } + if ( + frozenAtEpochMs[JOURNEY_MAIN_COUNTER.MODULES_REGISTERED_BEFORE_WINDOW] > + gate.gatedEpochMs + ) { + throw new Error('journey-main-counters-window-after-first-load'); + } + if ( + frozenAtEpochMs[ + JOURNEY_MAIN_COUNTER.SQL_STATEMENTS_BEFORE_READY_TO_SHOW + ] < gate.releasedEpochMs + ) { + throw new Error('journey-main-counters-ready-to-show-before-release'); + } + const running: Array<[string, string]> = [ + [ + JOURNEY_MAIN_COUNTER.STARTUP_PHASES, + JOURNEY_MAIN_COUNTER.MODULES_REGISTERED_BEFORE_WINDOW, + ], + [ + JOURNEY_MAIN_COUNTER.SQL_STATEMENTS, + JOURNEY_MAIN_COUNTER.SQL_STATEMENTS_BEFORE_READY_TO_SHOW, + ], + ]; + for (const [total, part] of running) { + if ((counters[total] ?? 0) < counters[part]) { + throw new Error( + `journey-main-counters-total-below-frozen: ${total}` + ); + } + } + return { counters, frozenAtEpochMs }; +} diff --git a/apps/electron-backend-e2e/src/performance/journey-renderer-gate-client.spec.ts b/apps/electron-backend-e2e/src/performance/journey-renderer-gate-client.spec.ts index 77a461533..e203d4540 100644 --- a/apps/electron-backend-e2e/src/performance/journey-renderer-gate-client.spec.ts +++ b/apps/electron-backend-e2e/src/performance/journey-renderer-gate-client.spec.ts @@ -16,6 +16,7 @@ function gate( gatedEpochMs: 1_020, gatedMethod: 'loadFile', passThroughLoads: 0, + readyToShowHeldOnBlank: 1, releasedEpochMs: 1_150, timedOut: false, ...overrides, diff --git a/apps/electron-backend-e2e/src/performance/journey-renderer-gate.cjs b/apps/electron-backend-e2e/src/performance/journey-renderer-gate.cjs index bac5ee866..be80ae151 100644 --- a/apps/electron-backend-e2e/src/performance/journey-renderer-gate.cjs +++ b/apps/electron-backend-e2e/src/performance/journey-renderer-gate.cjs @@ -14,9 +14,61 @@ * test calls `globalThis.__iptvnatorJourneyGate.release()`. A safety timeout * releases the gate on its own and records that it did, so a broken test * cannot hang the app; the journey treats a timed-out gate as invalid. + * + * The detour must not change what the app measures. Electron emits + * `ready-to-show` for the first paint of a hidden window, and `about:blank` + * paints too: the app would show the window and freeze its + * `ready-to-show` counters before its own document exists. The gate + * therefore drops `ready-to-show` while the window is on `about:blank`; + * Electron emits it again for the real document's first paint, because the + * window is still hidden, which is the moment production sees. + * + * With `ipcMain` passed in, the gate also keeps the listeners registered + * with `ipcMain.handle` for `TAPPED_IPC_CHANNELS`, so the test can call a + * main-process handler that the preload does not expose (the renderer + * bridge stays unchanged). The registration itself is passed through. */ const GATE_KEY = '__iptvnatorJourneyGate'; const DEFAULT_TIMEOUT_MS = 15000; +const BLANK_URL = 'about:blank'; +const TAPPED_IPC_CHANNELS = ['performance:read-counters']; + +function isShowingBlank(window) { + try { + return window.webContents.getURL() === BLANK_URL; + } catch { + return false; + } +} + +function holdReadyToShowWhileBlank(window, state) { + const originalEmit = window.emit; + if (typeof originalEmit !== 'function') return; + window.emit = function gatedEmit(eventName, ...args) { + if (eventName === 'ready-to-show' && isShowingBlank(window)) { + state.readyToShowHeldOnBlank += 1; + return false; + } + return originalEmit.call(this, eventName, ...args); + }; +} + +function tapIpcHandlers(ipcMain, channels) { + const handlers = new Map(); + const originalHandle = ipcMain.handle; + ipcMain.handle = function tappedHandle(channel, listener) { + const result = originalHandle.call(this, channel, listener); + if (channels.includes(channel)) handlers.set(channel, listener); + return result; + }; + return async function invokeHandler(channel, ...args) { + const listener = handlers.get(channel); + if (!listener) { + throw new Error(`journey-ipc-handler-not-registered: ${channel}`); + } + return listener({ frameId: -1, sender: null }, ...args); + }; +} function installJourneyRendererGate(BrowserWindow, target, options = {}) { const timeoutMs = options.timeoutMs ?? DEFAULT_TIMEOUT_MS; @@ -27,6 +79,7 @@ function installJourneyRendererGate(BrowserWindow, target, options = {}) { gatedEpochMs: null, gatedMethod: null, passThroughLoads: 0, + readyToShowHeldOnBlank: 0, releasedEpochMs: null, timedOut: false, }; @@ -41,7 +94,13 @@ function installJourneyRendererGate(BrowserWindow, target, options = {}) { releaseGate(); } }, timeoutMs); + const invokeHandler = options.ipcMain + ? tapIpcHandlers(options.ipcMain, TAPPED_IPC_CHANNELS) + : async (channel) => { + throw new Error(`journey-ipc-handler-tap-missing: ${channel}`); + }; const api = { + invokeHandler, release() { if (state.releasedEpochMs === null) { state.releasedEpochMs = now(); @@ -68,8 +127,9 @@ function installJourneyRendererGate(BrowserWindow, target, options = {}) { } state.gatedEpochMs = now(); state.gatedMethod = method; + holdReadyToShowWhileBlank(this, state); try { - await this.webContents.loadURL('about:blank'); + await this.webContents.loadURL(BLANK_URL); state.blankLoadedEpochMs = now(); } catch (error) { state.errors.push( @@ -83,7 +143,7 @@ function installJourneyRendererGate(BrowserWindow, target, options = {}) { return api; } -module.exports = { GATE_KEY, installJourneyRendererGate }; +module.exports = { GATE_KEY, installJourneyRendererGate, TAPPED_IPC_CHANNELS }; if ( process.versions && @@ -91,6 +151,6 @@ if ( !process.env['IPTVNATOR_JOURNEY_GATE_MANUAL'] ) { // eslint-disable-next-line @typescript-eslint/no-require-imports - const { BrowserWindow } = require('electron'); - installJourneyRendererGate(BrowserWindow, globalThis); + const { BrowserWindow, ipcMain } = require('electron'); + installJourneyRendererGate(BrowserWindow, globalThis, { ipcMain }); } diff --git a/apps/electron-backend-e2e/src/performance/journey-renderer-gate.spec.ts b/apps/electron-backend-e2e/src/performance/journey-renderer-gate.spec.ts index 12cef8643..a6e44978d 100644 --- a/apps/electron-backend-e2e/src/performance/journey-renderer-gate.spec.ts +++ b/apps/electron-backend-e2e/src/performance/journey-renderer-gate.spec.ts @@ -1,4 +1,5 @@ import assert from 'node:assert/strict'; +import { EventEmitter } from 'node:events'; import test from 'node:test'; interface GateState { @@ -7,22 +8,33 @@ interface GateState { gatedEpochMs: number | null; gatedMethod: string | null; passThroughLoads: number; + readyToShowHeldOnBlank: number; releasedEpochMs: number | null; timedOut: boolean; } interface GateApi { + invokeHandler(channel: string, ...args: unknown[]): Promise; release(): GateState; state: GateState; } +interface FakeIpcMain { + handle(channel: string, listener: (...args: unknown[]) => unknown): void; +} + interface GateModule { GATE_KEY: string; installJourneyRendererGate( browserWindow: { prototype: Record }, target: Record, - options?: { now?: () => number; timeoutMs?: number } + options?: { + ipcMain?: FakeIpcMain; + now?: () => number; + timeoutMs?: number; + } ): GateApi; + TAPPED_IPC_CHANNELS: string[]; } // The e2e project compiles to CommonJS, so the hook is loaded with require. @@ -139,3 +151,104 @@ test('records a failed about:blank navigation and still loads after release', as api.release(); assert.equal(await load, 'loaded:index.html'); }); + +function createEmittingBrowserWindow(log: string[]) { + class EmittingBrowserWindow extends EventEmitter { + url = ''; + webContents = { + getURL: () => this.url, + loadURL: async (url: string) => { + this.url = url; + log.push(`webContents.loadURL:${url}`); + }, + }; + async loadFile(file: string): Promise { + this.url = `file:///${file}`; + log.push(`loadFile:${file}`); + } + } + return EmittingBrowserWindow; +} + +test('holds ready-to-show while the window shows about:blank, then lets the real one through', async () => { + const log: string[] = []; + const EmittingBrowserWindow = createEmittingBrowserWindow(log); + const api = gateModule.installJourneyRendererGate( + EmittingBrowserWindow as unknown as { + prototype: Record; + }, + {}, + { timeoutMs: 60_000 } + ); + const window = new EmittingBrowserWindow(); + window.once('ready-to-show', () => log.push('app:ready-to-show')); + const load = window.loadFile('index.html'); + await settle(); + // Electron's first paint of about:blank. + assert.equal(window.emit('ready-to-show'), false); + window.emit('did-finish-load'); + assert.equal(api.state.readyToShowHeldOnBlank, 1); + + api.release(); + await load; + window.emit('ready-to-show'); + + assert.deepEqual(log, [ + 'webContents.loadURL:about:blank', + 'loadFile:index.html', + 'app:ready-to-show', + ]); + assert.equal(api.state.readyToShowHeldOnBlank, 1); +}); + +test('taps ipcMain.handle for the counters channel and passes registrations through', async () => { + const registered: string[] = []; + const ipcMain: FakeIpcMain = { + handle(channel) { + registered.push(channel); + }, + }; + const api = gateModule.installJourneyRendererGate( + createFakeBrowserWindow([]) as unknown as { + prototype: Record; + }, + {}, + { ipcMain, timeoutMs: 60_000 } + ); + assert.deepEqual(gateModule.TAPPED_IPC_CHANNELS, [ + 'performance:read-counters', + ]); + await assert.rejects( + api.invokeHandler('performance:read-counters'), + /journey-ipc-handler-not-registered: performance:read-counters/ + ); + + ipcMain.handle('performance:read-counters', (event, ...args) => ({ + args, + sender: (event as { sender: unknown }).sender, + })); + ipcMain.handle('db:other', () => 'other'); + + assert.deepEqual(registered, ['performance:read-counters', 'db:other']); + assert.deepEqual(await api.invokeHandler('performance:read-counters', 1), { + args: [1], + sender: null, + }); + await assert.rejects(api.invokeHandler('db:other'), /not-registered/); + api.release(); +}); + +test('refuses handler calls when no ipcMain was tapped', async () => { + const api = gateModule.installJourneyRendererGate( + createFakeBrowserWindow([]) as unknown as { + prototype: Record; + }, + {}, + { timeoutMs: 60_000 } + ); + await assert.rejects( + api.invokeHandler('performance:read-counters'), + /journey-ipc-handler-tap-missing/ + ); + api.release(); +}); diff --git a/apps/electron-backend-e2e/src/performance/launch-journey-record.spec.ts b/apps/electron-backend-e2e/src/performance/launch-journey-record.spec.ts index 4820f1c60..0e67e6e2c 100644 --- a/apps/electron-backend-e2e/src/performance/launch-journey-record.spec.ts +++ b/apps/electron-backend-e2e/src/performance/launch-journey-record.spec.ts @@ -67,10 +67,23 @@ function measurement( gatedEpochMs: 1_020, gatedMethod: 'loadFile', passThroughLoads: 0, + readyToShowHeldOnBlank: 1, releasedEpochMs: 1_150, timedOut: false, }, ipc, + mainCounters: { + counters: { + 'main.modulesRegisteredBeforeWindow': 2, + 'main.sqlStatements': 61, + 'main.sqlStatementsBeforeReadyToShow': 9, + 'main.startupPhases': 9, + }, + frozenAtEpochMs: { + 'main.modulesRegisteredBeforeWindow': 1_010, + 'main.sqlStatementsBeforeReadyToShow': 1_250, + }, + }, pid: 4242, renderer, spawnEpochMs: 1_000, @@ -78,12 +91,14 @@ function measurement( }; } -test('maps the probe and IPC capture to exact counters and spawn-relative wall-clock', () => { +test('maps the probe, IPC capture and main counters to exact counters and spawn-relative wall-clock', () => { const record = toLaunchIterationRecord(2, false, measurement()); assert.equal(record.index, 2); assert.equal(record.warmup, false); assert.equal(record.pid, 4242); assert.deepEqual(record.counters, { + 'main.modulesRegisteredBeforeWindow': 2, + 'main.sqlStatementsBeforeReadyToShow': 9, 'renderer.domMutationsToFirstCard': 480, 'renderer.ipcCallsToFirstCard': 14, 'renderer.layoutShiftScore': 0.123, @@ -99,12 +114,21 @@ test('maps the probe and IPC capture to exact counters and spawn-relative wall-c }); assert.deepEqual(record.evidence['longTaskDurationsMs'], [71.3, 120]); assert.equal(record.evidence['ipcCallsAfterFirstCard'], 3); + assert.deepEqual(record.evidence['mainCountersAtRead'], { + 'main.modulesRegisteredBeforeWindow': 2, + 'main.sqlStatements': 61, + 'main.sqlStatementsBeforeReadyToShow': 9, + 'main.startupPhases': 9, + }); + assert.equal(record.evidence['rendererGateReadyToShowHeldOnBlank'], 1); assert.deepEqual(record.evidence['epochs'], { firstCard: 2_600.04, firstCardPaint: 2_650, loadEventEnd: 1_400.26, mainIpcCaptureInstalled: 1_100, mainProcessStart: 900, + mainReadyToShow: 1_250, + mainWindowCreated: 1_010, rendererGateBlankLoaded: 1_050, rendererGateReleased: 1_150, rendererProbeInstalled: 1_200, @@ -144,8 +168,14 @@ test('rejects measurements whose clocks or probes are inconsistent', () => { }); test('names the counters the harness cannot measure yet', () => { - assert.deepEqual(Object.keys(LAUNCH_JOURNEY_UNAVAILABLE_COUNTERS).sort(), [ - 'main.sqlStatementsBeforeReadyToShow', + assert.deepEqual(Object.keys(LAUNCH_JOURNEY_UNAVAILABLE_COUNTERS), [ 'renderer.cdTicksToFirstCard', ]); }); + +test('never reports a measured counter as unavailable', () => { + const record = toLaunchIterationRecord(0, false, measurement()); + for (const name of Object.keys(LAUNCH_JOURNEY_UNAVAILABLE_COUNTERS)) { + assert.equal(name in record.counters, false, name); + } +}); diff --git a/apps/electron-backend-e2e/src/performance/launch-journey-record.ts b/apps/electron-backend-e2e/src/performance/launch-journey-record.ts index 14343fc0a..b2ce47508 100644 --- a/apps/electron-backend-e2e/src/performance/launch-journey-record.ts +++ b/apps/electron-backend-e2e/src/performance/launch-journey-record.ts @@ -1,15 +1,24 @@ import type { JourneyRendererGateState } from '../journeys/journey-renderer-gate-client'; +import { + JOURNEY_MAIN_COUNTER, + type JourneyMainCountersState, +} from './journey-main-counters'; import type { JourneyMainIpcCaptureState } from './journey-main-ipc-capture'; import type { JourneyRendererProbeState } from './journey-renderer-probe'; import type { JourneyIterationRecord } from './journey-summary'; /** - * Maps one measured launch (renderer probe + main IPC capture) to the - * journey summary's iteration record for J1 "Launch to usable". + * Maps one measured launch (renderer probe, main IPC capture and main-process + * counters) to the journey summary's iteration record for J1 "Launch to + * usable". */ export const LAUNCH_JOURNEY_ID = 'launch'; export const LAUNCH_JOURNEY_COUNTER = { + MODULES_REGISTERED_BEFORE_WINDOW: + JOURNEY_MAIN_COUNTER.MODULES_REGISTERED_BEFORE_WINDOW, + SQL_STATEMENTS_BEFORE_READY_TO_SHOW: + JOURNEY_MAIN_COUNTER.SQL_STATEMENTS_BEFORE_READY_TO_SHOW, DOM_MUTATIONS: 'renderer.domMutationsToFirstCard', IPC_CALLS: 'renderer.ipcCallsToFirstCard', LAYOUT_SHIFT_SCORE: 'renderer.layoutShiftScore', @@ -28,8 +37,6 @@ export const LAUNCH_JOURNEY_WALL_CLOCK = { export const LAUNCH_JOURNEY_UNAVAILABLE_COUNTERS: Readonly< Record > = Object.freeze({ - 'main.sqlStatementsBeforeReadyToShow': - 'SQL statements are only visible as worker stdout trace lines, which are forwarded asynchronously; plan item A2 adds a countable channel.', 'renderer.cdTicksToFirstCard': 'The electron-performance build optimizes scripts (ngDevMode=false), so Angular does not publish window.ng and ɵsetProfiler is unavailable.', }); @@ -38,6 +45,7 @@ export interface LaunchJourneyMeasurement { readonly electronVersion: string; readonly gate: JourneyRendererGateState; readonly ipc: JourneyMainIpcCaptureState; + readonly mainCounters: JourneyMainCountersState; readonly pid: number; readonly renderer: JourneyRendererProbeState; readonly spawnEpochMs: number; @@ -52,7 +60,7 @@ export function toLaunchIterationRecord( warmup: boolean, measurement: LaunchJourneyMeasurement ): JourneyIterationRecord { - const { ipc, renderer, spawnEpochMs } = measurement; + const { ipc, mainCounters, renderer, spawnEpochMs } = measurement; if (renderer.terminal === null || renderer.navigation === null) { throw new Error('launch-journey-record-incomplete-probe'); } @@ -75,6 +83,14 @@ export function toLaunchIterationRecord( } return Object.freeze({ counters: Object.freeze({ + [LAUNCH_JOURNEY_COUNTER.MODULES_REGISTERED_BEFORE_WINDOW]: + mainCounters.counters[ + LAUNCH_JOURNEY_COUNTER.MODULES_REGISTERED_BEFORE_WINDOW + ], + [LAUNCH_JOURNEY_COUNTER.SQL_STATEMENTS_BEFORE_READY_TO_SHOW]: + mainCounters.counters[ + LAUNCH_JOURNEY_COUNTER.SQL_STATEMENTS_BEFORE_READY_TO_SHOW + ], [LAUNCH_JOURNEY_COUNTER.DOM_MUTATIONS]: renderer.counters.domMutations, [LAUNCH_JOURNEY_COUNTER.IPC_CALLS]: ipc.callsBeforeSentinel, @@ -90,6 +106,15 @@ export function toLaunchIterationRecord( firstCardPaint: renderer.firstCardPaintEpochMs, loadEventEnd: renderer.navigation.loadEventEndEpochMs, mainIpcCaptureInstalled: ipc.installedEpochMs, + mainReadyToShow: + mainCounters.frozenAtEpochMs[ + LAUNCH_JOURNEY_COUNTER + .SQL_STATEMENTS_BEFORE_READY_TO_SHOW + ], + mainWindowCreated: + mainCounters.frozenAtEpochMs[ + LAUNCH_JOURNEY_COUNTER.MODULES_REGISTERED_BEFORE_WINDOW + ], mainProcessStart: ipc.processStartEpochMs, rendererGateBlankLoaded: measurement.gate.blankLoadedEpochMs, rendererGateReleased: measurement.gate.releasedEpochMs, @@ -102,6 +127,10 @@ export function toLaunchIterationRecord( pathname: renderer.terminal.pathname, }), ipcCallsAfterFirstCard: ipc.callsAfterSentinel, + // Running totals when the counters were read, after the first card. + mainCountersAtRead: mainCounters.counters, + rendererGateReadyToShowHeldOnBlank: + measurement.gate.readyToShowHeldOnBlank, ipcCallsByMethod: ipc.callsByMethod, longTaskDurationsMs: renderer.longTaskDurationsMs.map(roundTenth), observedTarget: renderer.capabilities.observedTarget, diff --git a/apps/electron-backend/src/app/app.ts b/apps/electron-backend/src/app/app.ts index ee9eae415..e275e1e03 100644 --- a/apps/electron-backend/src/app/app.ts +++ b/apps/electron-backend/src/app/app.ts @@ -7,11 +7,15 @@ import { join, resolve } from 'path'; import { fileURLToPath } from 'url'; import { rendererAppName, rendererAppPort } from './constants'; import { - isStartupTraceEnabled, + isPerformanceCaptureEnabled, isRendererConsoleTraceEnabled, + isSqlStatementCountEnabled, isWindowTraceEnabled, + performanceCounters, trace, + traceStartupPhase, } from './services/debug-trace'; +import { attachMainWindowPerformanceCounters } from './services/performance-counters'; import { STARTUP_WINDOW_MODE, store, @@ -135,19 +139,14 @@ export async function clearElectronServiceWorkerStorage( storages: ['serviceworkers', 'cachestorage'], }); - if (isStartupTraceEnabled()) { - trace('startup', 'electron-service-worker-storage:cleared'); - } + traceStartupPhase('electron-service-worker-storage:cleared'); } catch (error) { console.warn('Failed to clear Electron service worker storage:', error); - if (isStartupTraceEnabled()) { - trace( - 'startup', - 'electron-service-worker-storage:clear-failed', - error - ); - } + traceStartupPhase( + 'electron-service-worker-storage:clear-failed', + () => error + ); } } @@ -522,6 +521,14 @@ export default class App { ...App.getPlatformTitleBarOptions(), }); App.mainWindow.setMenu(null); + attachMainWindowPerformanceCounters( + App.mainWindow, + performanceCounters, + { + capture: isPerformanceCaptureEnabled(), + sqlStatements: isSqlStatementCountEnabled(), + } + ); attachWindowTrace(App.mainWindow); App.attachWindowStateEvents(App.mainWindow); // Seeds the F11 tracker's fullscreen state now, while no transition diff --git a/apps/electron-backend/src/app/services/database-worker-client.spec.ts b/apps/electron-backend/src/app/services/database-worker-client.spec.ts index 5b711f2ba..930e64ce2 100644 --- a/apps/electron-backend/src/app/services/database-worker-client.spec.ts +++ b/apps/electron-backend/src/app/services/database-worker-client.spec.ts @@ -183,6 +183,63 @@ describe('DatabaseWorkerClient', () => { await expect(requestPromise).resolves.toBe(resultIdentity); }); + describe('SQL statement counts', () => { + const PERF_CAPTURE_ENV = 'IPTVNATOR_PERF_CAPTURE'; + const originalCapture = process.env[PERF_CAPTURE_ENV]; + + afterEach(() => { + if (originalCapture === undefined) { + delete process.env[PERF_CAPTURE_ENV]; + } else { + process.env[PERF_CAPTURE_ENV] = originalCapture; + } + }); + + async function emitCountsDuringRequest( + counts: unknown[] + ): Promise> { + const client = createClient(); + const requestPromise = client.request('DB_GET_APP_STATE', { + key: 'counts', + }); + const worker = mockWorkerInstances[0]; + worker.emit('message', { type: 'ready' }); + await flushPromises(); + const request = worker.postMessage.mock.calls[0][0]; + + for (const count of counts) { + worker.emit('message', { + type: 'performance-sql-statements', + count, + }); + } + worker.emit('message', { + type: 'response', + requestId: request.requestId, + success: true, + result: 'state', + }); + + await expect(requestPromise).resolves.toBe('state'); + const { performanceCounters } = await import('./debug-trace'); + return performanceCounters.read().counters; + } + + it('adds worker statement counts to main.sqlStatements with capture on', async () => { + process.env[PERF_CAPTURE_ENV] = '1'; + + await expect( + emitCountsDuringRequest([3, 4, 0, -1, 'x']) + ).resolves.toEqual({ 'main.sqlStatements': 7 }); + }); + + it('counts nothing without the capture flag', async () => { + delete process.env[PERF_CAPTURE_ENV]; + + await expect(emitCountsDuringRequest([3])).resolves.toEqual({}); + }); + }); + it('turns serialized worker errors into rejected Error instances', async () => { const client = createClient(); const requestPromise = client.request('DB_DELETE_PLAYLIST', { diff --git a/apps/electron-backend/src/app/services/database-worker-client.ts b/apps/electron-backend/src/app/services/database-worker-client.ts index 898f09368..a21aace33 100644 --- a/apps/electron-backend/src/app/services/database-worker-client.ts +++ b/apps/electron-backend/src/app/services/database-worker-client.ts @@ -11,10 +11,16 @@ import type { } from '../workers/database-worker.types'; import { isDbTraceEnabled, + performanceCounters, roundTraceDuration, summarizeForTrace, trace, } from './debug-trace'; +import { PERFORMANCE_COUNTER } from './performance-counters'; +import { + DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE, + readSqlStatementsMessageCount, +} from '../workers/database-worker-sql-statement-count'; import { resolveWorkerRuntimeBootstrap } from '../workers/worker-runtime-paths'; type PendingRequest = { @@ -222,6 +228,17 @@ export class DatabaseWorkerClient { return; } + if (message.type === DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE) { + const count = readSqlStatementsMessageCount(message); + if (count !== null) { + performanceCounters.increment( + PERFORMANCE_COUNTER.SQL_STATEMENTS, + count + ); + } + return; + } + const pendingRequest = this.pendingRequests.get(message.requestId); if (!pendingRequest) { return; diff --git a/apps/electron-backend/src/app/services/debug-trace.spec.ts b/apps/electron-backend/src/app/services/debug-trace.spec.ts index c9346f2fd..bd3bbc958 100644 --- a/apps/electron-backend/src/app/services/debug-trace.spec.ts +++ b/apps/electron-backend/src/app/services/debug-trace.spec.ts @@ -66,3 +66,98 @@ describe('debug trace redaction', () => { } }); }); + +describe('startup phase counting', () => { + const FLAGS = ['IPTVNATOR_PERF_CAPTURE', 'IPTVNATOR_TRACE_STARTUP']; + const original = FLAGS.map((name) => [name, process.env[name]] as const); + + afterEach(() => { + for (const [name, value] of original) { + if (value === undefined) { + delete process.env[name]; + } else { + process.env[name] = value; + } + } + jest.restoreAllMocks(); + jest.resetModules(); + }); + + async function runPhases(env: Record) { + for (const name of FLAGS) { + delete process.env[name]; + } + Object.assign(process.env, env); + const log = jest.spyOn(console, 'log').mockImplementation(() => { + /* silenced */ + }); + const payload = jest.fn(() => ({ source: 'did-start-loading' })); + const { performanceCounters, traceStartupPhase } = + await import('./debug-trace'); + + traceStartupPhase('bootstrap-app'); + traceStartupPhase('deferred-events:start', payload); + + return { + counters: performanceCounters.read().counters, + lines: log.mock.calls.map((call) => String(call[0])), + payload, + }; + } + + it('neither counts nor traces nor builds payloads by default', async () => { + const result = await runPhases({}); + + expect(result.counters).toEqual({}); + expect(result.lines).toEqual([]); + expect(result.payload).not.toHaveBeenCalled(); + }); + + it('counts every phase with IPTVNATOR_PERF_CAPTURE=1 without tracing', async () => { + const result = await runPhases({ IPTVNATOR_PERF_CAPTURE: '1' }); + + expect(result.counters).toEqual({ 'main.startupPhases': 2 }); + expect(result.lines).toEqual([]); + expect(result.payload).not.toHaveBeenCalled(); + }); + + it('keeps the startup trace lines unchanged when tracing is on', async () => { + const result = await runPhases({ IPTVNATOR_TRACE_STARTUP: '1' }); + + expect(result.counters).toEqual({}); + expect(result.lines).toEqual([ + '[IPTVnator Trace][startup] bootstrap-app', + '[IPTVnator Trace][startup] deferred-events:start {"source":"did-start-loading"}', + ]); + }); +}); + +describe('SQL statement count opt-in', () => { + const FLAGS = ['IPTVNATOR_PERF_CAPTURE', 'IPTVNATOR_PERF_COUNT_SQL']; + const original = FLAGS.map((name) => [name, process.env[name]] as const); + + afterEach(() => { + for (const [name, value] of original) { + if (value === undefined) { + delete process.env[name]; + } else { + process.env[name] = value; + } + } + }); + + it.each([ + [{}, false], + [{ IPTVNATOR_PERF_CAPTURE: '1' }, false], + [{ IPTVNATOR_PERF_COUNT_SQL: '1' }, false], + [{ IPTVNATOR_PERF_CAPTURE: '1', IPTVNATOR_PERF_COUNT_SQL: '1' }, true], + ])('needs both flags: %j -> %s', async (env, expected) => { + for (const name of FLAGS) { + delete process.env[name]; + } + Object.assign(process.env, env); + const { isSqlStatementCountEnabled } = await import('./debug-trace'); + + expect(isSqlStatementCountEnabled()).toBe(expected); + }); +}); diff --git a/apps/electron-backend/src/app/services/debug-trace.ts b/apps/electron-backend/src/app/services/debug-trace.ts index 87c08da74..d9b37eb5e 100644 --- a/apps/electron-backend/src/app/services/debug-trace.ts +++ b/apps/electron-backend/src/app/services/debug-trace.ts @@ -2,6 +2,10 @@ import { redactSensitiveData, summarizeSqlStatementForTrace, } from '@iptvnator/shared/logging'; +import { + createPerformanceCounterRegistry, + PERFORMANCE_COUNTER, +} from './performance-counters'; const TRACE_ENV_TRUE_VALUES = new Set(['1', 'true', 'yes', 'on']); const TRACE_PREFIX = '[IPTVnator Trace]'; @@ -59,6 +63,26 @@ export function isPerformanceCaptureEnabled(): boolean { return readFlag('IPTVNATOR_PERF_CAPTURE'); } +/** + * SQL statement counting wraps every statement execution, including each + * row of a bulk insert, so it has its own opt-in on top of the capture flag: + * only the launch journey sets it, and the import benchmarks that also run + * with IPTVNATOR_PERF_CAPTURE=1 keep measuring the unwrapped workload. + */ +export function isSqlStatementCountEnabled(): boolean { + return ( + isPerformanceCaptureEnabled() && readFlag('IPTVNATOR_PERF_COUNT_SQL') + ); +} + +/** + * Process-wide performance counters (see `performance-counters.ts`). Every + * call is a no-op unless `IPTVNATOR_PERF_CAPTURE=1`. + */ +export const performanceCounters = createPerformanceCounterRegistry( + isPerformanceCaptureEnabled +); + export function isDbTraceEnabled(): boolean { return isStartupTraceEnabled() || readFlag('IPTVNATOR_TRACE_DB'); } @@ -179,3 +203,18 @@ export function trace(scope: string, message: string, payload?: unknown): void { export function traceSqlStatement(scope: string, sql: unknown): void { trace(scope, 'query', summarizeSqlStatementForTrace(sql)); } + +/** + * One main-process startup phase: counted under `main.startupPhases` when + * performance capture is on, traced as `[startup] ` when startup + * tracing is on. The payload is a thunk so it is only built for the trace. + */ +export function traceStartupPhase( + phase: string, + payload?: () => unknown +): void { + performanceCounters.increment(PERFORMANCE_COUNTER.STARTUP_PHASES); + if (isStartupTraceEnabled()) { + trace('startup', phase, payload?.()); + } +} diff --git a/apps/electron-backend/src/app/services/main-sql-statement-count.spec.ts b/apps/electron-backend/src/app/services/main-sql-statement-count.spec.ts new file mode 100644 index 000000000..144bcf271 --- /dev/null +++ b/apps/electron-backend/src/app/services/main-sql-statement-count.spec.ts @@ -0,0 +1,85 @@ +import Database from 'better-sqlite3'; +import * as shared from '@iptvnator/shared/database'; +import { mkdtempSync, rmSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; +import { countMainProcessSqlStatements } from './main-sql-statement-count'; +import { createPerformanceCounterRegistry } from './performance-counters'; + +const ENV_NAMES = ['IPTVNATOR_E2E_DATA_DIR', 'IPTVNATOR_TRACE_SQL'] as const; +const EXECUTION_METHODS = ['run', 'get', 'all', 'iterate'] as const; + +describe('main-process SQL statement count', () => { + const originalEnv = ENV_NAMES.map((name) => [name, process.env[name]]); + const statementPrototype = (() => { + const probe = new Database(':memory:'); + const prototype = Object.getPrototypeOf( + probe.prepare('SELECT 1') + ) as Record; + probe.close(); + return prototype; + })(); + const originalMethods = EXECUTION_METHODS.map( + (method) => [method, statementPrototype[method]] as const + ); + let dataDirectory: string | null = null; + + afterEach(() => { + for (const [method, original] of originalMethods) { + statementPrototype[method] = original; + } + for (const [name, value] of originalEnv) { + if (value === undefined) { + delete process.env[name as string]; + } else { + process.env[name as string] = value; + } + } + if (dataDirectory) { + rmSync(dataDirectory, { force: true, recursive: true }); + dataDirectory = null; + } + jest.restoreAllMocks(); + }); + + it('registers no connection observer without the capture flag', () => { + const setObserver = jest.fn(); + + countMainProcessSqlStatements( + createPerformanceCounterRegistry(() => true), + false, + setObserver + ); + + expect(setObserver).not.toHaveBeenCalled(); + }); + + it('counts every statement of the shared connection, as the sql-main trace does', async () => { + dataDirectory = mkdtempSync(join(tmpdir(), 'iptvnator-main-sql-')); + process.env['IPTVNATOR_E2E_DATA_DIR'] = dataDirectory; + process.env['IPTVNATOR_TRACE_SQL'] = '1'; + const log = jest.spyOn(console, 'log').mockImplementation(() => { + /* silenced */ + }); + const registry = createPerformanceCounterRegistry(() => true); + + countMainProcessSqlStatements( + registry, + true, + shared.setDatabaseConnectionObserver + ); + try { + await shared.initDatabase(); + } finally { + shared.setDatabaseConnectionObserver(null); + shared.closeDatabase(); + } + + const traced = log.mock.calls.filter((call) => + String(call[0]).startsWith('[IPTVnator Trace][sql-main] query') + ).length; + const counted = registry.read().counters['main.sqlStatements']; + expect(traced).toBeGreaterThan(0); + expect(counted).toBe(traced); + }); +}); diff --git a/apps/electron-backend/src/app/services/main-sql-statement-count.ts b/apps/electron-backend/src/app/services/main-sql-statement-count.ts new file mode 100644 index 000000000..30fab438a --- /dev/null +++ b/apps/electron-backend/src/app/services/main-sql-statement-count.ts @@ -0,0 +1,38 @@ +import { + setDatabaseConnectionObserver, + type DatabaseConnectionObserver, +} from '@iptvnator/shared/database/connection-observer'; +import { countSqlStatementExecutions } from '../workers/database-worker-sql-statement-count'; +import { PERFORMANCE_COUNTER } from './performance-counters'; +import type { PerformanceCounterRegistry } from './performance-counters'; + +/** + * With IPTVNATOR_PERF_CAPTURE=1 and IPTVNATOR_PERF_COUNT_SQL=1, counts the + * SQL statements the main process + * executes into `main.sqlStatements`, next to the database worker's + * statements that `DatabaseWorkerClient` adds. The shared connection + * (`initDatabase`, the `sql-main` trace) runs schema creation and migrations + * on the main thread before the first paint, so a worker-only count would + * miss them. + * + * The hook is installed when that connection opens, before its first + * statement, so better-sqlite3 is not loaded any earlier than without the + * flag. It wraps the `Statement` prototype of this process, which also + * counts statements of any other main-process connection opened later. + */ +export function countMainProcessSqlStatements( + registry: PerformanceCounterRegistry, + enabled: boolean, + setObserver: ( + observer: DatabaseConnectionObserver | null + ) => void = setDatabaseConnectionObserver +): void { + if (!enabled) { + return; + } + setObserver((connection) => { + countSqlStatementExecutions(connection, () => + registry.increment(PERFORMANCE_COUNTER.SQL_STATEMENTS) + ); + }); +} diff --git a/apps/electron-backend/src/app/services/performance-counters.spec.ts b/apps/electron-backend/src/app/services/performance-counters.spec.ts new file mode 100644 index 000000000..653fe0b2e --- /dev/null +++ b/apps/electron-backend/src/app/services/performance-counters.spec.ts @@ -0,0 +1,193 @@ +import { EventEmitter } from 'node:events'; +import { + attachMainWindowPerformanceCounters, + createPerformanceCounterRegistry, + PERFORMANCE_COUNTER, + PERFORMANCE_COUNTERS_READ_CHANNEL, + registerPerformanceCountersHandler, +} from './performance-counters'; + +function createRegistry(enabled = true, epochs = [1_000, 2_000, 3_000]) { + let flag = enabled; + const clock = [...epochs]; + const registry = createPerformanceCounterRegistry( + () => flag, + () => clock.shift() ?? -1 + ); + return { + registry, + setEnabled(value: boolean) { + flag = value; + }, + }; +} + +describe('performance counter registry', () => { + it('counts nothing while capture is disabled', () => { + const { registry } = createRegistry(false); + + registry.increment(PERFORMANCE_COUNTER.SQL_STATEMENTS, 4); + registry.freeze( + PERFORMANCE_COUNTER.SQL_STATEMENTS, + PERFORMANCE_COUNTER.SQL_STATEMENTS_BEFORE_READY_TO_SHOW + ); + + expect(registry.read()).toEqual({ counters: {}, frozenAtEpochMs: {} }); + }); + + it('adds only positive safe integers', () => { + const { registry } = createRegistry(); + + registry.increment('main.sqlStatements'); + registry.increment('main.sqlStatements', 3); + for (const invalid of [0, -2, 1.5, Number.NaN, 2 ** 53]) { + registry.increment('main.sqlStatements', invalid); + } + + expect(registry.read().counters).toEqual({ 'main.sqlStatements': 4 }); + }); + + it('freezes a counter once, with the epoch it was taken at', () => { + const { registry } = createRegistry(); + registry.increment('main.sqlStatements', 5); + + registry.freeze('main.sqlStatements', 'main.frozen'); + registry.increment('main.sqlStatements', 2); + registry.freeze('main.sqlStatements', 'main.frozen'); + + expect(registry.read()).toEqual({ + counters: { 'main.frozen': 5, 'main.sqlStatements': 7 }, + frozenAtEpochMs: { 'main.frozen': 1_000 }, + }); + }); + + it('freezes a counter that was never incremented as zero', () => { + const { registry } = createRegistry(); + + registry.freeze('main.sqlStatements', 'main.frozen'); + + expect(registry.read().counters).toEqual({ 'main.frozen': 0 }); + }); + + it('returns sorted copies that later increments do not change', () => { + const { registry } = createRegistry(); + registry.increment('main.b'); + registry.increment('main.a'); + + const snapshot = registry.read(); + registry.increment('main.a'); + + expect(Object.keys(snapshot.counters)).toEqual(['main.a', 'main.b']); + expect(snapshot.counters['main.a']).toBe(1); + }); +}); + +describe('performance:read-counters handler', () => { + it('is not registered without the capture flag', () => { + const ipcMain = { handle: jest.fn() }; + const { registry } = createRegistry(); + + expect( + registerPerformanceCountersHandler(ipcMain, registry, false) + ).toBe(false); + expect(ipcMain.handle).not.toHaveBeenCalled(); + }); + + it('returns the registry snapshot when the flag is on', async () => { + const ipcMain = { handle: jest.fn() }; + const { registry } = createRegistry(); + registry.increment(PERFORMANCE_COUNTER.STARTUP_PHASES, 2); + + expect( + registerPerformanceCountersHandler(ipcMain, registry, true) + ).toBe(true); + expect(ipcMain.handle).toHaveBeenCalledTimes(1); + const [channel, handler] = ipcMain.handle.mock.calls[0]; + expect(channel).toBe(PERFORMANCE_COUNTERS_READ_CHANNEL); + expect(channel).toBe('performance:read-counters'); + expect(await handler({})).toEqual({ + counters: { 'main.startupPhases': 2 }, + frozenAtEpochMs: {}, + }); + }); +}); + +describe('main window performance counters', () => { + const BOTH_FLAGS = { capture: true, sqlStatements: true }; + + it('attaches nothing without the capture flag', () => { + const window = new EventEmitter(); + const { registry } = createRegistry(); + + attachMainWindowPerformanceCounters(window, registry, { + capture: false, + sqlStatements: false, + }); + + expect(window.listenerCount('ready-to-show')).toBe(0); + expect(registry.read().counters).toEqual({}); + }); + + it('freezes only the startup phases when SQL is not counted', () => { + const window = new EventEmitter(); + const { registry } = createRegistry(); + registry.increment(PERFORMANCE_COUNTER.STARTUP_PHASES, 2); + + attachMainWindowPerformanceCounters(window, registry, { + capture: true, + sqlStatements: false, + }); + window.emit('ready-to-show'); + + expect(window.listenerCount('ready-to-show')).toBe(0); + expect(registry.read().counters).toEqual({ + 'main.modulesRegisteredBeforeWindow': 2, + 'main.startupPhases': 2, + }); + }); + + it('freezes startup phases at creation and SQL at ready-to-show', () => { + const window = new EventEmitter(); + const { registry } = createRegistry(); + registry.increment(PERFORMANCE_COUNTER.STARTUP_PHASES, 2); + registry.increment(PERFORMANCE_COUNTER.SQL_STATEMENTS, 3); + + attachMainWindowPerformanceCounters(window, registry, BOTH_FLAGS); + registry.increment(PERFORMANCE_COUNTER.STARTUP_PHASES); + registry.increment(PERFORMANCE_COUNTER.SQL_STATEMENTS, 4); + window.emit('ready-to-show'); + registry.increment(PERFORMANCE_COUNTER.SQL_STATEMENTS, 9); + + expect(registry.read()).toEqual({ + counters: { + 'main.modulesRegisteredBeforeWindow': 2, + 'main.sqlStatements': 16, + 'main.sqlStatementsBeforeReadyToShow': 7, + 'main.startupPhases': 3, + }, + frozenAtEpochMs: { + 'main.modulesRegisteredBeforeWindow': 1_000, + 'main.sqlStatementsBeforeReadyToShow': 2_000, + }, + }); + }); + + it('keeps the first window values when a window is re-created', () => { + const first = new EventEmitter(); + const second = new EventEmitter(); + const { registry } = createRegistry(); + registry.increment(PERFORMANCE_COUNTER.STARTUP_PHASES, 2); + attachMainWindowPerformanceCounters(first, registry, BOTH_FLAGS); + first.emit('ready-to-show'); + + registry.increment(PERFORMANCE_COUNTER.STARTUP_PHASES, 5); + registry.increment(PERFORMANCE_COUNTER.SQL_STATEMENTS, 5); + attachMainWindowPerformanceCounters(second, registry, BOTH_FLAGS); + second.emit('ready-to-show'); + + expect(registry.read().counters).toMatchObject({ + 'main.modulesRegisteredBeforeWindow': 2, + 'main.sqlStatementsBeforeReadyToShow': 0, + }); + }); +}); diff --git a/apps/electron-backend/src/app/services/performance-counters.ts b/apps/electron-backend/src/app/services/performance-counters.ts new file mode 100644 index 000000000..378ba99e4 --- /dev/null +++ b/apps/electron-backend/src/app/services/performance-counters.ts @@ -0,0 +1,129 @@ +import type { IpcMain } from 'electron'; + +/** + * Named main-process counters for the performance journeys + * (docs/architecture/performance-journeys.md). Everything here is inert + * unless `IPTVNATOR_PERF_CAPTURE=1`: nothing is counted, no listener is + * attached and no IPC handler is registered. Only type imports from + * `electron`, so the database worker and the preload can load + * `debug-trace.ts`, which owns the process-wide registry. + */ +export const PERFORMANCE_COUNTERS_READ_CHANNEL = 'performance:read-counters'; + +export const PERFORMANCE_COUNTER = { + /** Running total of startup trace phases (`traceStartupPhase`). */ + STARTUP_PHASES: 'main.startupPhases', + /** Running total of SQL statements run by main and the DB worker. */ + SQL_STATEMENTS: 'main.sqlStatements', + /** `STARTUP_PHASES` when the first main window was created. */ + MODULES_REGISTERED_BEFORE_WINDOW: 'main.modulesRegisteredBeforeWindow', + /** `SQL_STATEMENTS` when the first main window emitted `ready-to-show`. */ + SQL_STATEMENTS_BEFORE_READY_TO_SHOW: 'main.sqlStatementsBeforeReadyToShow', +} as const; + +export interface PerformanceCountersSnapshot { + readonly counters: Readonly>; + /** Epoch milliseconds at which each frozen counter was taken. */ + readonly frozenAtEpochMs: Readonly>; +} + +export interface PerformanceCounterRegistry { + /** Adds a positive safe integer to a running counter. */ + increment(name: string, by?: number): void; + /** + * Copies the current value of `source` into `target` once; later calls + * keep the first value, so a re-created window cannot move it. + */ + freeze(source: string, target: string): void; + read(): PerformanceCountersSnapshot; +} + +function sortedRecord(entries: Map): Record { + return Object.fromEntries( + [...entries].sort(([left], [right]) => left.localeCompare(right)) + ); +} + +export function createPerformanceCounterRegistry( + isEnabled: () => boolean, + readEpochMs: () => number = Date.now +): PerformanceCounterRegistry { + const counters = new Map(); + const frozenAtEpochMs = new Map(); + + return { + increment(name, by = 1) { + if (!Number.isSafeInteger(by) || by < 1 || !isEnabled()) { + return; + } + counters.set(name, (counters.get(name) ?? 0) + by); + }, + freeze(source, target) { + if (frozenAtEpochMs.has(target) || !isEnabled()) { + return; + } + counters.set(target, counters.get(source) ?? 0); + frozenAtEpochMs.set(target, readEpochMs()); + }, + read() { + return { + counters: sortedRecord(counters), + frozenAtEpochMs: sortedRecord(frozenAtEpochMs), + }; + }, + }; +} + +/** + * Registers `performance:read-counters` only when capture is enabled. The + * preload does not expose the channel, so the renderer bridge is unchanged; + * the journey harness reads it from the main process. + */ +export function registerPerformanceCountersHandler( + ipcMain: Pick, + registry: PerformanceCounterRegistry, + enabled: boolean +): boolean { + if (!enabled) { + return false; + } + ipcMain.handle(PERFORMANCE_COUNTERS_READ_CHANNEL, () => registry.read()); + return true; +} + +export interface MainWindowPerformanceCounterFlags { + /** IPTVNATOR_PERF_CAPTURE=1. */ + readonly capture: boolean; + /** IPTVNATOR_PERF_COUNT_SQL=1 as well; SQL is not counted otherwise. */ + readonly sqlStatements: boolean; +} + +/** + * Freezes the window-relative counters: the startup phases that ran before + * this window existed and, when SQL is counted, the database statements that + * ran before its first `ready-to-show`. Without SQL counting no listener is + * attached, so a zero is never reported for statements nobody counted. Call + * right after the window is constructed. + */ +export function attachMainWindowPerformanceCounters( + window: { once(event: 'ready-to-show', listener: () => void): unknown }, + registry: PerformanceCounterRegistry, + flags: MainWindowPerformanceCounterFlags +): void { + if (!flags.capture) { + return; + } + registry.freeze( + PERFORMANCE_COUNTER.STARTUP_PHASES, + PERFORMANCE_COUNTER.MODULES_REGISTERED_BEFORE_WINDOW + ); + if (!flags.sqlStatements) { + return; + } + window.once('ready-to-show', () => { + registry.freeze( + PERFORMANCE_COUNTER.SQL_STATEMENTS, + PERFORMANCE_COUNTER.SQL_STATEMENTS_BEFORE_READY_TO_SHOW + ); + }); +} diff --git a/apps/electron-backend/src/app/startup/deferred-events.ts b/apps/electron-backend/src/app/startup/deferred-events.ts index 03e41d8f9..54d076987 100644 --- a/apps/electron-backend/src/app/startup/deferred-events.ts +++ b/apps/electron-backend/src/app/startup/deferred-events.ts @@ -43,7 +43,7 @@ import StalkerEvents from '../events/stalker.events'; import XtreamEvents from '../events/xtream.events'; import { registerStreamProbeHandlers } from '../events/stream-probe'; import { registerConnectivityGuardHandlers } from '../events/connectivity-guard.events'; -import { isStartupTraceEnabled, trace } from '../services/debug-trace'; +import { traceStartupPhase } from '../services/debug-trace'; import { AppUpdateService } from '../services/app-update.service'; import { onAppUpdateChannelChange, @@ -115,21 +115,15 @@ export function bootstrapDeferredEvents( export async function finishStartupAfterFirstLoad(): Promise { await initDatabase(); - if (isStartupTraceEnabled()) { - trace('startup', 'init-database:done'); - } + traceStartupPhase('init-database:done'); await resetStaleDownloads(); - if (isStartupTraceEnabled()) { - trace('startup', 'reset-stale-downloads:done'); - } + traceStartupPhase('reset-stale-downloads:done'); await reconcileStaleRecordings(); - if (isStartupTraceEnabled()) { - trace('startup', 'reconcile-stale-recordings:done'); - } + traceStartupPhase('reconcile-stale-recordings:done'); } let fixPathScheduled = false; @@ -153,9 +147,7 @@ export function scheduleDeferredFixPath(): void { import('fix-path') .then(({ default: fixPath }) => { fixPath(); - if (isStartupTraceEnabled()) { - trace('startup', 'fix-path:done'); - } + traceStartupPhase('fix-path:done'); }) .catch((error) => { console.warn('fix-path failed:', error); diff --git a/apps/electron-backend/src/app/workers/database-worker-progress-throttle.spec.ts b/apps/electron-backend/src/app/workers/database-worker-progress-throttle.spec.ts index d0258f4e3..12487093f 100644 --- a/apps/electron-backend/src/app/workers/database-worker-progress-throttle.spec.ts +++ b/apps/electron-backend/src/app/workers/database-worker-progress-throttle.spec.ts @@ -91,6 +91,7 @@ describe('database worker progress throttle wiring', () => { })); jest.doMock('./database.worker-connection', () => ({ closeWorkerDatabase: jest.fn(), + flushWorkerSqlStatementCount: jest.fn(), getWorkerDatabase: jest.fn().mockResolvedValue({}), })); jest.doMock('../database/operations/content.operations', () => ({ diff --git a/apps/electron-backend/src/app/workers/database-worker-sql-statement-count.spec.ts b/apps/electron-backend/src/app/workers/database-worker-sql-statement-count.spec.ts new file mode 100644 index 000000000..ed92ad41f --- /dev/null +++ b/apps/electron-backend/src/app/workers/database-worker-sql-statement-count.spec.ts @@ -0,0 +1,177 @@ +import Database from 'better-sqlite3'; +import { + countSqlStatementExecutions, + createSqlStatementCountReporter, + DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE, + readSqlStatementsMessageCount, + type DbWorkerSqlStatementsMessage, +} from './database-worker-sql-statement-count'; + +/** Runs every execution path the worker's connection uses. */ +function runWorkload(db: Database.Database): void { + db.pragma('foreign_keys = ON'); + db.prepare( + 'CREATE TABLE items (id INTEGER PRIMARY KEY, name TEXT, secret TEXT)' + ).run(); + const insert = db.prepare('INSERT INTO items (name, secret) VALUES (?, ?)'); + db.transaction((rows: string[]) => { + for (const name of rows) { + insert.run(name, 'statement-count-secret'); + } + })(['a', 'b', 'c']); + db.prepare('SELECT * FROM items WHERE id = ?').get(1); + db.prepare('SELECT * FROM items').all(); + for (const row of db.prepare('SELECT id FROM items').iterate()) { + void row; + } + db.exec('DELETE FROM items WHERE id = 3'); + try { + // Fails before execution, like a repeated column migration. + db.exec('ALTER TABLE items ADD COLUMN name TEXT'); + } catch { + // Expected: duplicate column. + } + try { + db.prepare('INSERT INTO items (id, name) VALUES (1, ?)').get('x'); + } catch { + // Expected: get() on a statement that returns no data. + } +} + +describe('database worker SQL statement count', () => { + const connections: Database.Database[] = []; + const restores: Array<() => void> = []; + + function open(options?: Database.Options): Database.Database { + const db = new Database(':memory:', options); + connections.push(db); + return db; + } + + afterEach(() => { + for (const restore of restores.splice(0).reverse()) { + restore(); + } + for (const db of connections.splice(0)) { + db.close(); + } + }); + + it('counts exactly what the SQL trace callback sees, without SQL text', () => { + const traced: string[] = []; + runWorkload(open({ verbose: (sql) => traced.push(String(sql)) })); + + let counted = 0; + const db = open(); + restores.push( + countSqlStatementExecutions(db, () => { + counted += 1; + }) + ); + runWorkload(db); + + // pragma, CREATE, BEGIN, 3 inserts, COMMIT, get, all, iterate, exec + expect(traced).toHaveLength(11); + expect(counted).toBe(traced.length); + }); + + it('wraps once and restores the original methods', () => { + const db = open(); + const statementPrototype = Object.getPrototypeOf( + db.prepare('SELECT 1') + ) as Record; + const originalRun = statementPrototype['run']; + let counted = 0; + const record = () => { + counted += 1; + }; + + const restore = countSqlStatementExecutions(db, record); + const second = countSqlStatementExecutions(db, record); + db.prepare('SELECT 1').get(); + second(); + restore(); + db.prepare('SELECT 1').get(); + + expect(counted).toBe(1); + expect(statementPrototype['run']).toBe(originalRun); + }); + + it('coalesces statements into one message per flush', () => { + const posted: DbWorkerSqlStatementsMessage[] = []; + const scheduled: Array<() => void> = []; + const reporter = createSqlStatementCountReporter( + (message) => posted.push(message), + (callback) => scheduled.push(callback) + ); + + reporter.record(); + reporter.record(); + reporter.record(); + expect(scheduled).toHaveLength(1); + expect(posted).toEqual([]); + + scheduled[0](); + reporter.flush(); + + expect(posted).toEqual([ + { type: DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE, count: 3 }, + ]); + }); + + it('posts pending statements before a synchronous response', () => { + const order: string[] = []; + const scheduled: Array<() => void> = []; + const reporter = createSqlStatementCountReporter( + (message) => order.push(`count:${message.count}`), + (callback) => scheduled.push(callback) + ); + + reporter.record(); + reporter.record(); + // The worker's postMessage wrapper flushes before every message. + reporter.flush(); + order.push('response'); + scheduled[0](); + reporter.record(); + + expect(order).toEqual(['count:2', 'response']); + expect(scheduled).toHaveLength(2); + }); + + it('flushes on its own at the end of the current turn', async () => { + const posted: DbWorkerSqlStatementsMessage[] = []; + const reporter = createSqlStatementCountReporter((message) => + posted.push(message) + ); + + reporter.record(); + reporter.record(); + await Promise.resolve(); + + expect(posted).toEqual([ + { type: DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE, count: 2 }, + ]); + }); + + it('accepts only well-formed count messages', () => { + expect( + readSqlStatementsMessageCount({ + type: DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE, + count: 7, + }) + ).toBe(7); + for (const invalid of [ + null, + 'performance-sql-statements', + { type: DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE }, + { type: DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE, count: 0 }, + { type: DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE, count: -1 }, + { type: DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE, count: 1.5 }, + { type: DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE, count: '3' }, + { type: 'response', count: 3 }, + ]) { + expect(readSqlStatementsMessageCount(invalid)).toBeNull(); + } + }); +}); diff --git a/apps/electron-backend/src/app/workers/database-worker-sql-statement-count.ts b/apps/electron-backend/src/app/workers/database-worker-sql-statement-count.ts new file mode 100644 index 000000000..1f79cccc4 --- /dev/null +++ b/apps/electron-backend/src/app/workers/database-worker-sql-statement-count.ts @@ -0,0 +1,157 @@ +import type BetterSqlite3 from 'better-sqlite3'; + +/** + * Counts the SQL statements the database worker executes and reports the + * count to the main process, where `main.sqlStatements` is kept (see + * `services/performance-counters.ts`). Only active with + * `IPTVNATOR_PERF_CAPTURE=1` and `IPTVNATOR_PERF_COUNT_SQL=1`, which only the + * launch journey sets: the import benchmarks run with the capture flag alone + * and keep measuring unwrapped statements. + * + * The count travels over the worker's message port, which is ordered with + * the worker's responses, instead of the stdout trace lines Node forwards + * asynchronously. Only a number crosses the port: no SQL text and no bound + * values. + * + * Statements are counted at the execution methods of better-sqlite3's + * `Statement` prototype rather than through the `verbose` callback behind + * the SQL trace: with a callback, better-sqlite3 expands every statement's + * SQL and calls into JavaScript with it, which made a 200,000-row insert + * two to four times slower and would distort the import benchmarks that run + * with the same flag. One call of `run`, `get`, `all` or `iterate` that + * returns normally is one statement, which includes pragmas and the + * BEGIN/COMMIT that `db.transaction()` prepares internally. One `exec` call + * also counts as one: SQL cannot be split into statements reliably here + * (trigger bodies contain semicolons), so callers pass one statement per + * call. The database worker never calls `exec`, and the shared connection's + * historical-upgrade test (`libs/shared/database/src/lib/testing/ + * connection-upgrade.ts`) fails on a batch. Calls that throw are not + * counted: the SQL trace skips the + * ones that fail before execution (a migration's `ALTER TABLE` for a column + * that already exists), and they did no work. + */ +export const DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE = + 'performance-sql-statements'; + +export interface DbWorkerSqlStatementsMessage { + type: typeof DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE; + count: number; +} + +export interface SqlStatementCountReporter { + /** Counts one statement; it is posted on the next flush. */ + record(): void; + /** Posts the statements recorded since the last flush, if any. */ + flush(): void; +} + +const STATEMENT_EXECUTION_METHODS = ['run', 'get', 'all', 'iterate'] as const; +const COUNTED = Symbol.for('iptvnator.sqlStatementCount.counted'); + +type ExecutionMethod = ((...args: unknown[]) => unknown) & { + [COUNTED]?: true; +}; + +/** + * Coalesces counts into few messages. A flush is queued as a microtask, so + * a bulk write posts one message rather than one per row; the worker also + * flushes synchronously before posting any other message, so a response can + * never overtake the statements that produced it. + */ +export function createSqlStatementCountReporter( + post: (message: DbWorkerSqlStatementsMessage) => void, + schedule: (callback: () => void) => void = queueMicrotask +): SqlStatementCountReporter { + let pending = 0; + let scheduled = false; + + const flush = (): void => { + scheduled = false; + if (pending === 0) { + return; + } + const count = pending; + pending = 0; + post({ type: DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE, count }); + }; + + return { + record() { + pending += 1; + if (!scheduled) { + scheduled = true; + schedule(flush); + } + }, + flush, + }; +} + +function wrapExecution( + owner: Record, + method: string, + record: () => void +): (() => void) | null { + const original = owner[method] as ExecutionMethod | undefined; + if (typeof original !== 'function' || original[COUNTED]) { + return null; + } + const counted: ExecutionMethod = function countedExecution( + this: unknown, + ...args: unknown[] + ) { + const result = original.apply(this, args); + record(); + return result; + }; + counted[COUNTED] = true; + owner[method] = counted; + return () => { + if (owner[method] === counted) { + owner[method] = original; + } + }; +} + +/** + * Wraps the execution methods of the connection's statements (shared by + * every statement of this worker, since they have one prototype) and the + * connection's own `exec`. Idempotent, so reopening the connection does not + * count twice. Returns a function that removes the wrappers it installed. + */ +export function countSqlStatementExecutions( + connection: BetterSqlite3.Database, + record: () => void +): () => void { + const statementPrototype = Object.getPrototypeOf( + connection.prepare('SELECT 1') + ) as Record; + const restores = [ + ...STATEMENT_EXECUTION_METHODS.map((method) => + wrapExecution(statementPrototype, method, record) + ), + wrapExecution( + connection as unknown as Record, + 'exec', + record + ), + ]; + return () => { + for (const restore of restores) { + restore?.(); + } + }; +} + +/** The count of a well-formed message, or null for anything else. */ +export function readSqlStatementsMessageCount(message: unknown): number | null { + if (typeof message !== 'object' || message === null) { + return null; + } + const { type, count } = message as Partial; + return type === DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE && + Number.isSafeInteger(count) && + (count as number) > 0 + ? (count as number) + : null; +} diff --git a/apps/electron-backend/src/app/workers/database-worker-sql-statement-count.wiring.spec.ts b/apps/electron-backend/src/app/workers/database-worker-sql-statement-count.wiring.spec.ts new file mode 100644 index 000000000..bbaf39ab8 --- /dev/null +++ b/apps/electron-backend/src/app/workers/database-worker-sql-statement-count.wiring.spec.ts @@ -0,0 +1,176 @@ +import Database from 'better-sqlite3'; +import { mkdtempSync, rmSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; +import { MessageChannel, type MessagePort } from 'node:worker_threads'; +import { DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE } from './database-worker-sql-statement-count'; + +/** + * Pins the worker wiring of `database-worker-sql-statement-count.ts`: with + * IPTVNATOR_PERF_CAPTURE=1 and IPTVNATOR_PERF_COUNT_SQL=1 the real worker + * connection reports its statements over the parent port, with the capture + * flag alone (the import benchmarks) or without flags it reports nothing, + * and the worker flushes the count before any response it posts. + */ +const ENV_NAMES = [ + 'IPTVNATOR_PERF_CAPTURE', + 'IPTVNATOR_PERF_COUNT_SQL', + 'IPTVNATOR_E2E_DATA_DIR', +] as const; +const EXECUTION_METHODS = ['run', 'get', 'all', 'iterate'] as const; + +describe('database worker SQL statement count wiring', () => { + const originalEnv = ENV_NAMES.map((name) => [name, process.env[name]]); + const statementPrototype = (() => { + const probe = new Database(':memory:'); + const prototype = Object.getPrototypeOf( + probe.prepare('SELECT 1') + ) as Record; + probe.close(); + return prototype; + })(); + const originalMethods = EXECUTION_METHODS.map( + (method) => [method, statementPrototype[method]] as const + ); + let ports: MessagePort[] = []; + let dataDirectory: string | null = null; + + afterEach(() => { + for (const port of ports) { + port.close(); + } + ports = []; + // The connection wraps the shared Statement prototype; keep other + // spec files in this Jest worker unaffected. + for (const [method, original] of originalMethods) { + statementPrototype[method] = original; + } + for (const [name, value] of originalEnv) { + if (value === undefined) { + delete process.env[name as string]; + } else { + process.env[name as string] = value; + } + } + if (dataDirectory) { + rmSync(dataDirectory, { force: true, recursive: true }); + dataDirectory = null; + } + jest.restoreAllMocks(); + jest.resetModules(); + }); + + function connectPorts(): { messages: unknown[]; workerPort: MessagePort } { + const channel = new MessageChannel(); + ports.push(channel.port1, channel.port2); + const messages: unknown[] = []; + channel.port2.on('message', (message) => messages.push(message)); + jest.doMock('worker_threads', () => ({ + ...jest.requireActual('worker_threads'), + parentPort: channel.port1, + workerData: {}, + })); + return { messages, workerPort: channel.port1 }; + } + + async function openConnection( + flags: Partial>, + expectedMessages: number + ) { + dataDirectory = mkdtempSync(join(tmpdir(), 'iptvnator-sql-count-')); + delete process.env['IPTVNATOR_PERF_CAPTURE']; + delete process.env['IPTVNATOR_PERF_COUNT_SQL']; + Object.assign(process.env, flags); + process.env['IPTVNATOR_E2E_DATA_DIR'] = dataDirectory; + const { messages } = connectPorts(); + const connection = await import('./database.worker-connection'); + await connection.getWorkerDatabase(); + connection.flushWorkerSqlStatementCount(); + connection.closeWorkerDatabase(); + // Port delivery is asynchronous: wait for the expected messages, and + // a few more turns so an unexpected extra message is still seen. + const deadline = Date.now() + 5_000; + while (messages.length < expectedMessages && Date.now() < deadline) { + await new Promise((resolve) => setTimeout(resolve, 5)); + } + await new Promise((resolve) => setTimeout(resolve, 50)); + return messages; + } + + it('reports the connection setup statements when SQL counting is on', async () => { + const messages = await openConnection( + { IPTVNATOR_PERF_CAPTURE: '1', IPTVNATOR_PERF_COUNT_SQL: '1' }, + 2 + ); + + // Seven PRAGMAs on open, then `PRAGMA optimize` on close. + expect(messages).toEqual([ + { type: DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE, count: 7 }, + { type: DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE, count: 1 }, + ]); + expect(JSON.stringify(messages)).not.toMatch(/PRAGMA|journal_mode/i); + }); + + it.each([ + ['without flags', {}], + [ + 'with the capture flag alone, as the import benchmarks run', + { IPTVNATOR_PERF_CAPTURE: '1' }, + ], + ])( + 'reports nothing and leaves better-sqlite3 alone %s', + async (_label, flags) => { + const messages = await openConnection(flags, 0); + + expect(messages).toEqual([]); + for (const [method, original] of originalMethods) { + expect(statementPrototype[method]).toBe(original); + } + } + ); + + it('flushes the count before the worker posts a response', async () => { + const { messages, workerPort } = connectPorts(); + let pendingStatements = 0; + jest.doMock('./database.worker-connection', () => ({ + closeWorkerDatabase: jest.fn(), + flushWorkerSqlStatementCount: jest.fn(() => { + if (pendingStatements > 0) { + workerPort.postMessage({ + type: DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE, + count: pendingStatements, + }); + pendingStatements = 0; + } + }), + getWorkerDatabase: jest.fn(async () => { + pendingStatements = 2; + return {}; + }), + })); + jest.spyOn(console, 'error').mockImplementation(() => undefined); + + await import('./database.worker'); + ports[1].postMessage({ + type: 'request', + operation: 'DB_GET_APP_STATE', + payload: { key: 'sql-count-wiring' }, + requestId: 'request-sql-count', + }); + const deadline = Date.now() + 5_000; + while ( + !messages.some( + (message) => (message as { type?: string }).type === 'response' + ) + ) { + if (Date.now() > deadline) { + throw new Error('database worker did not respond'); + } + await new Promise((resolve) => setTimeout(resolve, 5)); + } + + expect( + messages.map((message) => (message as { type: string }).type) + ).toEqual(['ready', DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE, 'response']); + }); +}); diff --git a/apps/electron-backend/src/app/workers/database-worker-zero-delay-cancellation.spec.ts b/apps/electron-backend/src/app/workers/database-worker-zero-delay-cancellation.spec.ts index b32236964..950995719 100644 --- a/apps/electron-backend/src/app/workers/database-worker-zero-delay-cancellation.spec.ts +++ b/apps/electron-backend/src/app/workers/database-worker-zero-delay-cancellation.spec.ts @@ -82,6 +82,7 @@ describe('database worker zero-delay cancellation', () => { })); jest.doMock('./database.worker-connection', () => ({ closeWorkerDatabase: jest.fn(), + flushWorkerSqlStatementCount: jest.fn(), getWorkerDatabase: jest.fn().mockResolvedValue({}), })); jest.doMock('../database/operations/content.operations', () => ({ diff --git a/apps/electron-backend/src/app/workers/database-worker.types.ts b/apps/electron-backend/src/app/workers/database-worker.types.ts index 2aa403a03..732b80312 100644 --- a/apps/electron-backend/src/app/workers/database-worker.types.ts +++ b/apps/electron-backend/src/app/workers/database-worker.types.ts @@ -1,4 +1,5 @@ import type { WorkerPerformanceCaptureResult } from './worker-performance-capture'; +import type { DbWorkerSqlStatementsMessage } from './database-worker-sql-statement-count'; export const DB_WORKER_OPERATIONS = [ 'DB_HAS_CATEGORIES', @@ -177,4 +178,5 @@ export type DbWorkerMessage = | DbWorkerReadyMessage | DbWorkerEventMessage | DbWorkerPerformanceCancelReceivedMessage + | DbWorkerSqlStatementsMessage | DbWorkerResponseMessage; diff --git a/apps/electron-backend/src/app/workers/database.worker-connection.ts b/apps/electron-backend/src/app/workers/database.worker-connection.ts index 122213d7a..cff5b79cc 100644 --- a/apps/electron-backend/src/app/workers/database.worker-connection.ts +++ b/apps/electron-backend/src/app/workers/database.worker-connection.ts @@ -1,7 +1,7 @@ import type BetterSqlite3 from 'better-sqlite3'; import * as schema from '@iptvnator/shared/database/schema'; import { getIptvnatorDatabasePath } from '@iptvnator/shared/database/path-utils'; -import { workerData } from 'worker_threads'; +import { parentPort, workerData } from 'worker_threads'; import type { AppDatabase } from '../database/database.types'; import { getNativeModuleSearchPaths, @@ -10,10 +10,15 @@ import { registerNativeModuleSearchPaths, } from './worker-runtime-paths'; import { + isSqlStatementCountEnabled, isSqlTraceEnabled, trace, traceSqlStatement, } from '../services/debug-trace'; +import { + countSqlStatementExecutions, + createSqlStatementCountReporter, +} from './database-worker-sql-statement-count'; let drizzleFactory: | (typeof import('drizzle-orm/better-sqlite3'))['drizzle'] @@ -59,6 +64,22 @@ const Database = loadBetterSqlite3(); let db: AppDatabase | null = null; let sqlite: BetterSqlite3.Database | null = null; +// IPTVNATOR_PERF_CAPTURE=1 with IPTVNATOR_PERF_COUNT_SQL=1 only: the main +// process keeps the running total. +const sqlStatementCount = isSqlStatementCountEnabled() + ? createSqlStatementCountReporter((message) => + parentPort?.postMessage(message) + ) + : null; + +/** + * Posts the statements counted since the last flush. The worker calls this + * before every other message so a response never overtakes its statements. + */ +export function flushWorkerSqlStatementCount(): void { + sqlStatementCount?.flush(); +} + export async function getWorkerDatabase(): Promise { if (db) { return db; @@ -70,6 +91,9 @@ export async function getWorkerDatabase(): Promise { ? (sql: string) => traceSqlStatement('sql-worker', sql) : undefined, }); + if (sqlStatementCount) { + countSqlStatementExecutions(sqlite, sqlStatementCount.record); + } sqlite.pragma('foreign_keys = ON'); sqlite.pragma('journal_mode = WAL'); sqlite.pragma('busy_timeout = 5000'); diff --git a/apps/electron-backend/src/app/workers/database.worker.ts b/apps/electron-backend/src/app/workers/database.worker.ts index 73b780635..3f8404593 100644 --- a/apps/electron-backend/src/app/workers/database.worker.ts +++ b/apps/electron-backend/src/app/workers/database.worker.ts @@ -1,6 +1,7 @@ import { migrateAppPlaylists } from '../database/operations/playlist-migration.operations'; import { closeWorkerDatabase, + flushWorkerSqlStatementCount, getWorkerDatabase, } from './database.worker-connection'; import { parentPort, workerData } from 'worker_threads'; @@ -218,6 +219,7 @@ function serializeError(error: unknown) { } function postMessage(message: DbWorkerMessage): void { + flushWorkerSqlStatementCount(); parentPort?.postMessage(message); } diff --git a/apps/electron-backend/src/app/workers/worker-performance-cancellation.spec.ts b/apps/electron-backend/src/app/workers/worker-performance-cancellation.spec.ts index ba613ca64..46154bf7b 100644 --- a/apps/electron-backend/src/app/workers/worker-performance-cancellation.spec.ts +++ b/apps/electron-backend/src/app/workers/worker-performance-cancellation.spec.ts @@ -126,6 +126,7 @@ describe('worker cancellation while performance capture arms', () => { })); jest.doMock('./database.worker-connection', () => ({ closeWorkerDatabase: jest.fn(), + flushWorkerSqlStatementCount: jest.fn(), getWorkerDatabase: jest.fn().mockResolvedValue({}), })); jest.doMock('../database/operations/content.operations', () => ({ @@ -219,6 +220,7 @@ describe('worker cancellation while performance capture arms', () => { })); jest.doMock('./database.worker-connection', () => ({ closeWorkerDatabase: jest.fn(), + flushWorkerSqlStatementCount: jest.fn(), getWorkerDatabase: jest.fn().mockResolvedValue({}), })); jest.doMock('../database/operations/content.operations', () => ({ @@ -288,6 +290,7 @@ describe('worker cancellation while performance capture arms', () => { })); jest.doMock('./database.worker-connection', () => ({ closeWorkerDatabase: jest.fn(), + flushWorkerSqlStatementCount: jest.fn(), getWorkerDatabase: jest.fn().mockResolvedValue({}), })); jest.doMock('../database/operations/playlist.operations', () => ({ @@ -353,6 +356,7 @@ describe('database worker performance control messages', () => { })); jest.doMock('./database.worker-connection', () => ({ closeWorkerDatabase: jest.fn(), + flushWorkerSqlStatementCount: jest.fn(), getWorkerDatabase, })); jest.doMock('./database-worker-post-gc-heap', () => ({ diff --git a/apps/electron-backend/src/main.ts b/apps/electron-backend/src/main.ts index 0961a0f9b..c7b20c4b6 100644 --- a/apps/electron-backend/src/main.ts +++ b/apps/electron-backend/src/main.ts @@ -1,10 +1,18 @@ // Select persistence before eager imports (notably electron-conf) cache userData. import './app/services/electron-profile-bootstrap'; -import { app, BrowserWindow } from 'electron'; +import { app, BrowserWindow, ipcMain } from 'electron'; import App from './app/app'; import PlaylistOpenEvents from './app/events/playlist-open.events'; import SquirrelEvents from './app/events/squirrel.events'; -import { isStartupTraceEnabled, trace } from './app/services/debug-trace'; +import { + isPerformanceCaptureEnabled, + isSqlStatementCountEnabled, + isStartupTraceEnabled, + performanceCounters, + traceStartupPhase, +} from './app/services/debug-trace'; +import { registerPerformanceCountersHandler } from './app/services/performance-counters'; +import { countMainProcessSqlStatements } from './app/services/main-sql-statement-count'; import { readCompileCacheOutcome } from './app/services/compile-cache'; import { applyElectronNetworkDefaults } from './app/util/network-defaults'; import { registerStaticHeaderShims } from './app/services/request-header-overrides.service'; @@ -35,9 +43,12 @@ import { EMBEDDED_MPV_FRAME_COPY, store } from './app/services/store.service'; app.setName('iptvnator'); -if (isStartupTraceEnabled()) { - trace('startup', 'compile-cache', readCompileCacheOutcome()); -} +traceStartupPhase('compile-cache', () => readCompileCacheOutcome()); +// Before anything can open the shared database connection. +countMainProcessSqlStatements( + performanceCounters, + isSqlStatementCountEnabled() +); // Before the first portal, playlist or update request leaves this process. applyElectronNetworkDefaults((line) => { @@ -92,9 +103,7 @@ export default class Main { } static bootstrapApp() { - if (isStartupTraceEnabled()) { - trace('startup', 'bootstrap-app'); - } + traceStartupPhase('bootstrap-app'); App.main(app, BrowserWindow); } @@ -106,9 +115,13 @@ export default class Main { * still guarantees the handlers exist before any renderer invoke). */ static async bootstrapAppEvents() { - if (isStartupTraceEnabled()) { - trace('startup', 'bootstrap-events:start'); - } + traceStartupPhase('bootstrap-events:start'); + // Only with IPTVNATOR_PERF_CAPTURE=1; the preload never exposes it. + registerPerformanceCountersHandler( + ipcMain, + performanceCounters, + isPerformanceCaptureEnabled() + ); const windowCloseGuard = bootstrapWindowCloseGuard((listener) => App.onMainWindowCreated(listener) @@ -131,14 +144,14 @@ export default class Main { windowCloseGuard, }), onTrigger: (source) => { - if (isStartupTraceEnabled()) { - trace('startup', 'deferred-events:start', { source }); - } + traceStartupPhase('deferred-events:start', () => ({ + source, + })); }, onDone: (durationMs) => { - if (isStartupTraceEnabled()) { - trace('startup', 'deferred-events:done', { durationMs }); - } + traceStartupPhase('deferred-events:done', () => ({ + durationMs, + })); }, // The window is open by now; without this a missing chunk would // only show up as an unhandled rejection with no context. @@ -147,9 +160,7 @@ export default class Main { 'Deferred main-process startup failed; portal, EPG, database and download handlers are unavailable:', error ); - if (isStartupTraceEnabled()) { - trace('startup', 'deferred-events:failed', error); - } + traceStartupPhase('deferred-events:failed', () => error); }, }); deferredEvents = deferred; @@ -170,9 +181,7 @@ export default class Main { await module.finishStartupAfterFirstLoad(); - if (isStartupTraceEnabled()) { - trace('startup', 'bootstrap-events:done'); - } + traceStartupPhase('bootstrap-events:done'); // Hydrate process.env.PATH from the user's login shell now — after // the window has loaded and IPC handlers are live. Fire-and-forget @@ -239,9 +248,7 @@ runEmbeddedMpvRuntimeDiagnosticOrContinue(process.argv, () => { // Bootstrap app events after Electron app is ready app.whenReady().then(async () => { - if (isStartupTraceEnabled()) { - trace('startup', 'app.whenReady'); - } + traceStartupPhase('app.whenReady'); await Main.bootstrapAppEvents(); }); diff --git a/docs/architecture/performance-journeys.md b/docs/architecture/performance-journeys.md index 7a737f876..2a698b00b 100644 --- a/docs/architecture/performance-journeys.md +++ b/docs/architecture/performance-journeys.md @@ -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 diff --git a/docs/architecture/sqlite-db-worker.md b/docs/architecture/sqlite-db-worker.md index 088dec70c..4b8e5e92d 100644 --- a/docs/architecture/sqlite-db-worker.md +++ b/docs/architecture/sqlite-db-worker.md @@ -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 diff --git a/docs/development/electron-debugging.md b/docs/development/electron-debugging.md index 1e9f60f55..1d88fc503 100644 --- a/docs/development/electron-debugging.md +++ b/docs/development/electron-debugging.md @@ -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=` relocates it. The startup trace reports the outcome as `compile-cache` diff --git a/libs/shared/database/README.md b/libs/shared/database/README.md index d9fe92911..c1b2e0383 100644 --- a/libs/shared/database/README.md +++ b/libs/shared/database/README.md @@ -28,6 +28,9 @@ import { content, categories, playlists, type Content } from '@iptvnator/shared/ - `closeDatabase()` - Close connection - `getDatabasePath()` - Get database file path +### Connection observer (`connection-observer.ts`) +- `setDatabaseConnectionObserver(observer | null)` - Called by `initDatabase` with each connection it opens, before any statement runs on it. The Electron main process registers one only with `IPTVNATOR_PERF_CAPTURE=1`, to count main-thread SQL statements. The module has no runtime dependencies and is also importable as `@iptvnator/shared/database/connection-observer`. + ## Database Location The SQLite database is stored at: `~/.iptvnator/databases/iptvnator.db` diff --git a/libs/shared/database/src/index.ts b/libs/shared/database/src/index.ts index 9df4dff04..26cfa5705 100644 --- a/libs/shared/database/src/index.ts +++ b/libs/shared/database/src/index.ts @@ -7,3 +7,4 @@ export * from './lib/schema'; export * from './lib/connection'; export * from './lib/path-utils'; +export * from './lib/connection-observer'; diff --git a/libs/shared/database/src/lib/connection-observer.spec.ts b/libs/shared/database/src/lib/connection-observer.spec.ts new file mode 100644 index 000000000..0cc845b34 --- /dev/null +++ b/libs/shared/database/src/lib/connection-observer.spec.ts @@ -0,0 +1,30 @@ +import type Database from 'better-sqlite3'; +import { + notifyDatabaseConnectionOpened, + setDatabaseConnectionObserver, +} from './connection-observer'; + +describe('database connection observer', () => { + afterEach(() => { + setDatabaseConnectionObserver(null); + }); + + it('does nothing when no observer is registered', () => { + expect(() => + notifyDatabaseConnectionOpened({} as Database.Database) + ).not.toThrow(); + }); + + it('passes each opened connection to the registered observer until removed', () => { + const observer = jest.fn(); + const first = { name: 'first' } as unknown as Database.Database; + const second = { name: 'second' } as unknown as Database.Database; + + setDatabaseConnectionObserver(observer); + notifyDatabaseConnectionOpened(first); + setDatabaseConnectionObserver(null); + notifyDatabaseConnectionOpened(second); + + expect(observer.mock.calls).toEqual([[first]]); + }); +}); diff --git a/libs/shared/database/src/lib/connection-observer.ts b/libs/shared/database/src/lib/connection-observer.ts new file mode 100644 index 000000000..8eac84dad --- /dev/null +++ b/libs/shared/database/src/lib/connection-observer.ts @@ -0,0 +1,26 @@ +import type Database from 'better-sqlite3'; + +export type DatabaseConnectionObserver = ( + connection: Database.Database +) => void; + +let observer: DatabaseConnectionObserver | null = null; + +/** + * Registers a callback that `initDatabase` calls with each connection it + * opens, before any statement runs on it; `null` removes it. The Electron + * main process uses it with IPTVNATOR_PERF_CAPTURE=1 to count main-thread + * SQL statements. This module has no runtime dependencies, so registering + * the observer does not load better-sqlite3. + */ +export function setDatabaseConnectionObserver( + next: DatabaseConnectionObserver | null +): void { + observer = next; +} + +export function notifyDatabaseConnectionOpened( + connection: Database.Database +): void { + observer?.(connection); +} diff --git a/libs/shared/database/src/lib/connection.ts b/libs/shared/database/src/lib/connection.ts index 99ef8e184..934ba84bc 100644 --- a/libs/shared/database/src/lib/connection.ts +++ b/libs/shared/database/src/lib/connection.ts @@ -23,6 +23,7 @@ import { } from '@iptvnator/shared/logging'; import * as schema from './schema'; import { getIptvnatorDatabasePath } from './path-utils'; +import { notifyDatabaseConnectionOpened } from './connection-observer'; export type DatabaseInstance = BetterSQLite3Database; @@ -1228,6 +1229,7 @@ export async function initDatabase( ? (message?: unknown) => traceSqlStatement(message) : undefined, }); + notifyDatabaseConnectionOpened(sqlite); if (isSqlTraceEnabled()) { traceSql('sql-main', 'open', { diff --git a/libs/shared/database/src/lib/testing/connection-upgrade.ts b/libs/shared/database/src/lib/testing/connection-upgrade.ts index 94cdaa19a..dcfaa1c47 100644 --- a/libs/shared/database/src/lib/testing/connection-upgrade.ts +++ b/libs/shared/database/src/lib/testing/connection-upgrade.ts @@ -3,6 +3,7 @@ import { readFileSync } from 'node:fs'; import Database from 'better-sqlite3'; import { getTableConfig } from 'drizzle-orm/sqlite-core'; import { closeDatabase, getDatabasePath, initDatabase } from '../connection'; +import { setDatabaseConnectionObserver } from '../connection-observer'; import * as currentSchema from '../schema'; const tables = [ @@ -38,6 +39,31 @@ function seed(sqlite: Database.Database) { } } +/** + * The performance capture counts one `exec` call as one SQL statement + * (apps/electron-backend/src/app/workers/database-worker-sql-statement-count.ts), + * so initialization must pass exactly one statement per `exec`. better-sqlite3 + * refuses to prepare a string with a second statement; other prepare errors + * are left to `exec` itself (for example an idempotent ALTER TABLE). + */ +function requireSingleStatementExec(): string[] { + const batches: string[] = []; + setDatabaseConnectionObserver((connection) => { + const exec = connection.exec; + connection.exec = function singleStatementExec(sql: string) { + try { + connection.prepare(sql); + } catch (error) { + if (error instanceof RangeError) { + batches.push(sql.replace(/\s+/g, ' ').slice(0, 120)); + } + } + return exec.call(this, sql); + }; + }); + return batches; +} + function snapshot(sqlite: Database.Database) { return tables.map((table) => { const columns = sqlite.pragma(`table_info(${table})`) as { @@ -98,6 +124,7 @@ async function main() { console.warn = (...args) => warnings.push(args); console.log = () => undefined; const databasePath = getDatabasePath(); + const execBatches = requireSingleStatementExec(); if (fixture === 'fresh') { await initDatabase(); @@ -157,6 +184,11 @@ async function main() { [], 'Initialization must not silently skip failed migrations' ); + assert.deepEqual( + execBatches, + [], + 'Initialization must pass one SQL statement per exec call' + ); process.stdout.write('upgrade verified'); } diff --git a/tsconfig.base.json b/tsconfig.base.json index 7bcd05ff4..e708d951e 100644 --- a/tsconfig.base.json +++ b/tsconfig.base.json @@ -143,6 +143,9 @@ "@iptvnator/shared/database/path-utils": [ "libs/shared/database/src/lib/path-utils.ts" ], + "@iptvnator/shared/database/connection-observer": [ + "libs/shared/database/src/lib/connection-observer.ts" + ], "@iptvnator/workspace/dashboard/feature": [ "libs/workspace/dashboard/feature/src/index.ts" ],