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

Implements plan item A2. With IPTVNATOR_PERF_CAPTURE=1 the main process
keeps named counters and registers a main-only performance:read-counters
IPC handler; without the flag nothing is counted and the handler does not
exist.

- debug-trace.ts owns the registry; traceStartupPhase replaces the
  trace('startup', ...) sites and counts main.startupPhases.
- The database worker counts executed statements through better-sqlite3's
  Statement prototype (the verbose callback expands every statement and
  made bulk inserts 2-4x slower) and posts the count over its message
  port, flushed before every other worker message. The main-thread shared
  connection is counted through a new connection observer in the shared
  database library.
- The first main window freezes main.modulesRegisteredBeforeWindow at
  creation and main.sqlStatementsBeforeReadyToShow at ready-to-show.
- The journey gate drops the ready-to-show that Electron emits for the
  about:blank detour, so the app sees the real document's first paint,
  and taps the counters handler; the J1 record reads both counters after
  the renderer probe completes.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
4grayandClaude Opus 5.5 committed 2026-09-27 18:48:29 +02:00
1 parent 9d02f90dfe
commit 37ac72b951
38 files changed
+1817 -73

No files matched your search

@@ -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;
}
@@ -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,14 @@ export async function measureLaunchJourney(
);
try {
await cp(templateDirectory, dataDirectory, { recursive: true });
// IPTVNATOR_PERF_CAPTURE turns on the main-process counters and
// their read handler; see journey-main-counters.ts.
const env = buildElectronLaunchEnvironment(
dataDirectory,
launchOptions({ IPTVNATOR_TRACE_IPC: '1' })
launchOptions({
IPTVNATOR_PERF_CAPTURE: '1',
IPTVNATOR_TRACE_IPC: '1',
})
);
const args = buildElectronLaunchArgs([
'-r',
@@ -188,6 +197,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 +215,7 @@ export async function measureLaunchJourney(
electronVersion,
gate,
ipc,
mainCounters,
pid: electronApp.process().pid ?? -1,
renderer,
spawnEpochMs,
@@ -0,0 +1,126 @@
import assert from 'node:assert/strict';
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<string, number> = {},
frozenAtEpochMs: Record<string, number> = {}
) {
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<string, number>)['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<string, number>)[
'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/
);
});
@@ -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<Record<string, number>>;
readonly frozenAtEpochMs: Readonly<Record<string, number>>;
}
export async function readJourneyMainCounters(
electronApp: ElectronApplication,
gateKey: string
): Promise<unknown> {
return electronApp.evaluate(
async (_electron, input) => {
const gate = (globalThis as unknown as Record<string, unknown>)[
input.gateKey
] as
| { invokeHandler?: (channel: string) => Promise<unknown> }
| 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<string, number> {
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<string, number> {
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<JourneyRendererGateState, 'gatedEpochMs' | 'releasedEpochMs'>
): JourneyMainCountersState {
const snapshot = value as Partial<JourneyMainCountersState> | 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 };
}
@@ -16,6 +16,7 @@ function gate(
gatedEpochMs: 1_020,
gatedMethod: 'loadFile',
passThroughLoads: 0,
readyToShowHeldOnBlank: 1,
releasedEpochMs: 1_150,
timedOut: false,
...overrides,
@@ -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 });
}
@@ -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<unknown>;
release(): GateState;
state: GateState;
}
interface FakeIpcMain {
handle(channel: string, listener: (...args: unknown[]) => unknown): void;
}
interface GateModule {
GATE_KEY: string;
installJourneyRendererGate(
browserWindow: { prototype: Record<string, unknown> },
target: Record<string, unknown>,
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<void> {
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<string, unknown>;
},
{},
{ 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<string, unknown>;
},
{},
{ 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<string, unknown>;
},
{},
{ timeoutMs: 60_000 }
);
await assert.rejects(
api.invokeHandler('performance:read-counters'),
/journey-ipc-handler-tap-missing/
);
api.release();
});
@@ -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);
}
});
@@ -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<string, string>
> = 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,
+14 -11
View File
@@ -7,11 +7,14 @@ import { join, resolve } from 'path';
import { fileURLToPath } from 'url';
import { rendererAppName, rendererAppPort } from './constants';
import {
isStartupTraceEnabled,
isPerformanceCaptureEnabled,
isRendererConsoleTraceEnabled,
isWindowTraceEnabled,
performanceCounters,
trace,
traceStartupPhase,
} from './services/debug-trace';
import { attachMainWindowPerformanceCounters } from './services/performance-counters';
import {
STARTUP_WINDOW_MODE,
store,
@@ -135,19 +138,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 +520,11 @@ export default class App {
...App.getPlatformTitleBarOptions(),
});
App.mainWindow.setMenu(null);
attachMainWindowPerformanceCounters(
App.mainWindow,
performanceCounters,
isPerformanceCaptureEnabled()
);
attachWindowTrace(App.mainWindow);
App.attachWindowStateEvents(App.mainWindow);
// Seeds the F11 tracker's fullscreen state now, while no transition
@@ -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<Record<string, number>> {
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', {
@@ -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;
@@ -66,3 +66,68 @@ 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<string, string>) {
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"}',
]);
});
});
@@ -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,14 @@ export function isPerformanceCaptureEnabled(): boolean {
return readFlag('IPTVNATOR_PERF_CAPTURE');
}
/**
* 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 +191,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] <phase>` 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?.());
}
}
@@ -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<string, unknown>;
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);
});
});
@@ -0,0 +1,37 @@
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, 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)
);
});
}
@@ -0,0 +1,170 @@
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', () => {
it('attaches nothing without the capture flag', () => {
const window = new EventEmitter();
const { registry } = createRegistry();
attachMainWindowPerformanceCounters(window, registry, false);
expect(window.listenerCount('ready-to-show')).toBe(0);
expect(registry.read().counters).toEqual({});
});
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, true);
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, true);
first.emit('ready-to-show');
registry.increment(PERFORMANCE_COUNTER.STARTUP_PHASES, 5);
registry.increment(PERFORMANCE_COUNTER.SQL_STATEMENTS, 5);
attachMainWindowPerformanceCounters(second, registry, true);
second.emit('ready-to-show');
expect(registry.read().counters).toMatchObject({
'main.modulesRegisteredBeforeWindow': 2,
'main.sqlStatementsBeforeReadyToShow': 0,
});
});
});
@@ -0,0 +1,117 @@
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<Record<string, number>>;
/** Epoch milliseconds at which each frozen counter was taken. */
readonly frozenAtEpochMs: Readonly<Record<string, number>>;
}
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<string, number>): Record<string, number> {
return Object.fromEntries(
[...entries].sort(([left], [right]) => left.localeCompare(right))
);
}
export function createPerformanceCounterRegistry(
isEnabled: () => boolean,
readEpochMs: () => number = Date.now
): PerformanceCounterRegistry {
const counters = new Map<string, number>();
const frozenAtEpochMs = new Map<string, number>();
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<IpcMain, 'handle'>,
registry: PerformanceCounterRegistry,
enabled: boolean
): boolean {
if (!enabled) {
return false;
}
ipcMain.handle(PERFORMANCE_COUNTERS_READ_CHANNEL, () => registry.read());
return true;
}
/**
* Freezes the window-relative counters: the startup phases that ran before
* this window existed, and the database statements that ran before its first
* `ready-to-show`. Call right after the window is constructed.
*/
export function attachMainWindowPerformanceCounters(
window: { once(event: 'ready-to-show', listener: () => void): unknown },
registry: PerformanceCounterRegistry,
enabled: boolean
): void {
if (!enabled) {
return;
}
registry.freeze(
PERFORMANCE_COUNTER.STARTUP_PHASES,
PERFORMANCE_COUNTER.MODULES_REGISTERED_BEFORE_WINDOW
);
window.once('ready-to-show', () => {
registry.freeze(
PERFORMANCE_COUNTER.SQL_STATEMENTS,
PERFORMANCE_COUNTER.SQL_STATEMENTS_BEFORE_READY_TO_SHOW
);
});
}
@@ -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<void> {
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);
@@ -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', () => ({
@@ -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<string, unknown>;
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();
}
});
});
@@ -0,0 +1,150 @@
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`.
*
* 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
* counts as one. 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<string, unknown>,
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<string, unknown>;
const restores = [
...STATEMENT_EXECUTION_METHODS.map((method) =>
wrapExecution(statementPrototype, method, record)
),
wrapExecution(
connection as unknown as Record<string, unknown>,
'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<DbWorkerSqlStatementsMessage>;
return type === DB_WORKER_SQL_STATEMENTS_MESSAGE_TYPE &&
Number.isSafeInteger(count) &&
(count as number) > 0
? (count as number)
: null;
}
@@ -0,0 +1,161 @@
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 the real worker connection reports its statements
* over the parent port, without the flag it reports nothing, and the worker
* flushes the count before any response it posts.
*/
const ENV_NAMES = ['IPTVNATOR_PERF_CAPTURE', '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<string, unknown>;
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(
captureFlag: string | undefined,
expectedMessages: number
) {
dataDirectory = mkdtempSync(join(tmpdir(), 'iptvnator-sql-count-'));
process.env['IPTVNATOR_E2E_DATA_DIR'] = dataDirectory;
if (captureFlag === undefined) {
delete process.env['IPTVNATOR_PERF_CAPTURE'];
} else {
process.env['IPTVNATOR_PERF_CAPTURE'] = captureFlag;
}
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 capture is on', async () => {
const messages = await openConnection('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('reports nothing and leaves better-sqlite3 alone without the flag', async () => {
const messages = await openConnection(undefined, 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']);
});
});
@@ -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', () => ({
@@ -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;
@@ -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 {
isPerformanceCaptureEnabled,
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,21 @@ const Database = loadBetterSqlite3();
let db: AppDatabase | null = null;
let sqlite: BetterSqlite3.Database | null = null;
// IPTVNATOR_PERF_CAPTURE=1 only: the main process keeps the running total.
const sqlStatementCount = isPerformanceCaptureEnabled()
? 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<AppDatabase> {
if (db) {
return db;
@@ -70,6 +90,9 @@ export async function getWorkerDatabase(): Promise<AppDatabase> {
? (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');
@@ -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);
}
@@ -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', () => ({
+32 -26
View File
@@ -1,10 +1,17 @@
// 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,
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 +42,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,
isPerformanceCaptureEnabled()
);
// Before the first portal, playlist or update request leaves this process.
applyElectronNetworkDefaults((line) => {
@@ -92,9 +102,7 @@ export default class Main {
}
static bootstrapApp() {
if (isStartupTraceEnabled()) {
trace('startup', 'bootstrap-app');
}
traceStartupPhase('bootstrap-app');
App.main(app, BrowserWindow);
}
@@ -106,9 +114,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 +143,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 +159,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 +180,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 +247,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();
});
+54 -7
View File
@@ -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,54 @@ 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. 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.
`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 +156,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
+18
View File
@@ -444,6 +444,24 @@ 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`, 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. A call that throws is not counted, which matches the SQL
trace for statements that fail before execution. 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
+1 -1
View File
@@ -30,7 +30,7 @@ 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_WORKER_PROFILING=1` enables development/test-only, request-scoped worker receive/work/response-post timestamps, thread CPU, event-loop utilization/delay, count-only playlist serialization/SQLite write/read/deserialization plus Xtream category/content/cache-clear/delete/in-source-search phase events, profiling-only worker cancel-receipt acknowledgements, valid-sample-counted isolate peak memory, and the database worker's idle-only one-shot post-GC heap probe; overlapping database requests are explicitly invalidated instead of misattributed, the performance benchmark sets the flag automatically, and production launches must leave it unset
- `IPTVNATOR_DISABLE_COMPILE_CACHE=1` disables the main-process V8 compile cache; `IPTVNATOR_COMPILE_CACHE_DIR=<dir>` relocates it. The startup trace reports the outcome as `compile-cache`
+3
View File
@@ -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`
+1
View File
@@ -7,3 +7,4 @@
export * from './lib/schema';
export * from './lib/connection';
export * from './lib/path-utils';
export * from './lib/connection-observer';
@@ -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]]);
});
});
@@ -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);
}
@@ -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<typeof schema>;
@@ -1228,6 +1229,7 @@ export async function initDatabase(
? (message?: unknown) => traceSqlStatement(message)
: undefined,
});
notifyDatabaseConnectionOpened(sqlite);
if (isSqlTraceEnabled()) {
traceSql('sql-main', 'open', {
+3
View File
@@ -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"
],