From 06be713286cbbf75663ac9dcdb4b5c6dcff407b7 Mon Sep 17 00:00:00 2001 From: Ben Dodson Date: Tue, 25 Aug 2026 23:51:08 -0700 Subject: [PATCH] feat(debugger): add bounded performance tracing --- docs/docs/performance-tracing.md | 23 +- npm_modules/cli/debugger/README.md | 17 +- npm_modules/cli/debugger/debugger-actions.js | 34 +- .../cli/debugger/debugger-bootstrap.js | 14 +- .../cli/debugger/debugger-performance.js | 443 ++++++++++++- npm_modules/cli/debugger/debugger-runtime.js | 3 + npm_modules/cli/debugger/debugger-session.js | 42 ++ npm_modules/cli/debugger/debugger-state.js | 16 + npm_modules/cli/debugger/debugger.css | 80 +++ npm_modules/cli/debugger/index.html | 20 +- npm_modules/cli/src/core/packageFiles.spec.ts | 533 +++++++++++++++- npm_modules/cli/src/debugger/server.spec.ts | 349 +++++++++- npm_modules/cli/src/debugger/server.ts | 601 +++++++++++++++++- .../cli/src/utils/daemonClient.spec.ts | 285 ++++++++- npm_modules/cli/src/utils/daemonClient.ts | 301 ++++++++- .../src/valdi/valdi_core/src/Renderer.ts | 21 +- .../valdi_core/src/RootComponentsManager.ts | 45 +- .../valdi/valdi_core/src/ValdiRuntime.d.ts | 2 + .../valdi_core/src/debugging/Messages.ts | 259 +++++++- .../PerformanceTraceMessageHandler.ts | 336 ++++++++++ .../src/valdi/valdi_core/src/utils/Trace.ts | 146 ++++- .../PerformanceTraceMessageHandler.spec.ts | 494 ++++++++++++++ .../test/RootComponentsManager.spec.ts | 93 ++- .../runtime/JavaScript/JavaScriptRuntime.cpp | 55 +- .../runtime/JavaScript/JavaScriptRuntime.hpp | 1 + valdi/test/runtime/Tracer_tests.cpp | 107 ++++ valdi_core/src/valdi_core/cpp/Utils/Trace.cpp | 119 +++- valdi_core/src/valdi_core/cpp/Utils/Trace.hpp | 10 + 28 files changed, 4367 insertions(+), 82 deletions(-) create mode 100644 src/valdi_modules/src/valdi/valdi_core/src/debugging/PerformanceTraceMessageHandler.ts create mode 100644 src/valdi_modules/src/valdi/valdi_core/test/PerformanceTraceMessageHandler.spec.ts diff --git a/docs/docs/performance-tracing.md b/docs/docs/performance-tracing.md index 72f84a9fc..c71922a83 100644 --- a/docs/docs/performance-tracing.md +++ b/docs/docs/performance-tracing.md @@ -6,6 +6,28 @@ To help you debug performance issues, Valdi provides a cross-platform tracing AP ### Recording traces +#### Using the Valdi Debugger + +With a hot reloader connected to the application, run `valdi debugger`, attach +to a native target, and open **Performance**. The **UI Performance** card can +start and stop a renderer trace or capture a bounded interval of up to 15 +seconds. Enable **Renderer events** to include component `onRender()` spans and +ViewModel-change triggers. Exported captures use Chrome Trace JSON and can be +opened in [Perfetto UI](https://ui.perfetto.dev/). Native trace recording is +process-wide; the selected context is recorded as the capture target used to +reach the runtime, not as the origin of each trace event. + +To keep debugger responses bounded before serialization, the native recorder +retains at most 10,000 events, 2 KiB per trace name, and 1 MiB of aggregate +trace-name data per active recording window. Capture results report how many +events were dropped by those limits. Automatically stopped and recently +completed results remain available for retry for one minute before they are +discarded. + +The debugger proxies these operations through `/api/performance/trace/status`, +`start`, `stop`, and `capture`; the application keeps ownership of the recorder, +so captures continue to work across the loopback debugger HTTP connection. + > [!NOTE] > Please make sure to add `//src/valdi_modules/src/valdi/benchmarking` to the `deps` attribute of the `valdi_module()` call in your module's `BUILD.bazel`. @@ -91,4 +113,3 @@ The Valdi runtime traces some default important events that happens during the l - `Valdi.setUserDefinedViewport`: The framework is reacting to a scroll change. - `Valdi.updateVisibility`: The framework is resolving the viewports for the nodes. It is finding out which nodes are visible and which nodes are not visible on the screen. - `Valdi.calculateLayout`: The framework is calculating the frames (rectangles) for the nodes. This can happen because nodes have been inserted/removed, because a layout attribute has changed (like `padding`), or because the available space for the root component has changed (for instance if the window has been resized). This can be an expensive operation. Because of this, you should avoid triggering changes in the elements that will cause a layout pass to happen when scrolling. If you need to move elements or show/hide them when scrolling, prefer using the `translationX`/`translationY` attributes or `opacity` which are not layout attributes and don't trigger layout passes when they change. - diff --git a/npm_modules/cli/debugger/README.md b/npm_modules/cli/debugger/README.md index f741e362e..7a3619ae4 100644 --- a/npm_modules/cli/debugger/README.md +++ b/npm_modules/cli/debugger/README.md @@ -15,7 +15,7 @@ the CLI package. - `debugger-preview-html.js`: inert HTML projection of the hot-reloaded snapshot tree. - `debugger-render.js`: header, target list, tree, preview overlay, inspector, and export rendering. - `debugger-runtime.js`: target discovery, snapshots, runtime log streaming, heap, and copy/export helpers. -- `debugger-performance.js`: Hermes CPU profile controls. +- `debugger-performance.js`: renderer trace and Hermes CPU profile controls. - `debugger-actions.js`: UI actions, command prompt handling, auto-refresh, and externally driven debugger actions. - `debugger-session.js`: `sessionStorage` restore/persist for reload-friendly debugger state. - `debugger-bootstrap.js`: DOM event wiring and boot sequence. @@ -36,15 +36,20 @@ Important routes: - `/api/snapshot`: fetches the selected target's view tree and preview data. - `/api/runtime-logs` and `/api/runtime-logs/stream`: read and stream target logs. - `/api/debugger/state`, `/api/debugger/events`, and `/api/debugger/actions`: keep the browser UI and external agents in sync. +- `/api/performance/trace/*`: start, stop, capture, and export native renderer traces. - `/api/performance/profile/*`: list Hermes contexts and capture CPU profiles. - `/api/devtools/target`: matches the inspected Chromium page to the exact configured preview origin and path. - `/api/devtools/snapshot`, `/api/devtools/highlight`, and `/api/devtools/evaluate`: proxy the explicit web debugger bridge contract through loopback CDP. -Renderer tracing is intentionally not part of this foundation. It requires the -separate runtime and native renderer-instrumentation stack; land that stack -before adding renderer trace routes or controls to this debugger. Hermes CPU -profiling uses the existing inspector transport and has no such prerequisite. -Target input forwarding and data/network provider tabs should likewise land +Renderer tracing uses the runtime debugger protocol and the existing native +trace recorder. Captures are process-wide: the selected context is the capture +target used to reach the runtime, not the origin assigned to every event. +One-shot captures are limited to 15 seconds so the debugger handler can retain +the result before the native recorder's independent safety timeout, and +exported JSON can be opened in Perfetto. Native bounds report dropped event +counts, and retained timeout/retry results expire after one minute. +Hermes CPU profiling uses the existing inspector transport. Target input +forwarding and data/network provider tabs should likewise land with their runtime-side contracts and end-to-end tests rather than as inactive browser-only surfaces. Web-renderer inspection depends on the target page explicitly exposing diff --git a/npm_modules/cli/debugger/debugger-actions.js b/npm_modules/cli/debugger/debugger-actions.js index 20b531fb1..f76a1d15f 100644 --- a/npm_modules/cli/debugger/debugger-actions.js +++ b/npm_modules/cli/debugger/debugger-actions.js @@ -33,7 +33,14 @@ function setActiveSection(section) { } function shouldAutoRefresh() { - return !document.hidden && !state.performance.profileActive; + return ( + !document.hidden && + !state.performance.traceActive && + !state.performance.traceCapturePending && + !state.performance.traceResultPending && + !state.performance.traceStateUnknown && + !state.performance.profileActive + ); } function shouldAutoRefreshLiveSnapshot() { @@ -152,7 +159,8 @@ function detachDebuggerView() { render(); } -function setTargetPort(port) { +async function setTargetPort(port, nextTarget) { + if (!(await preparePerformanceTraceTargetSwitch(nextTarget))) return; elements.portSelect.value = String(port); state.snapshot.target = { ...state.snapshot.target, @@ -160,6 +168,7 @@ function setTargetPort(port) { port, }; state.attached = false; + state.performance.traceSupported = true; state.manualDetach = false; state.followLatestTarget = true; state.rootSnapshotImage = null; @@ -208,7 +217,7 @@ function applyDebuggerAction(action, params = {}) { if (action === 'setPort') { const port = actionNumber(params, 'port'); - if (port !== null) setTargetPort(port); + if (port !== null) void setTargetPort(port, { port }); return; } @@ -247,6 +256,21 @@ function applyDebuggerAction(action, params = {}) { return; } + if (action === 'startRendererTrace') { + void startPerformanceTrace(); + return; + } + + if (action === 'stopRendererTrace') { + void stopPerformanceTrace({}); + return; + } + + if (action === 'captureRendererTrace') { + void capturePerformanceTrace(); + return; + } + if (action === 'refreshHermesContexts') { void refreshProfileContexts({ silent: false }); return; @@ -279,7 +303,7 @@ function runCommand(rawCommand) { addLog( 'info', 'console', - 'Commands: help, section , path, issues, select , connect, refresh, reload, status, snapshot, heap, profile, auto on, auto off, clear.', + 'Commands: help, section , path, issues, select , connect, refresh, reload, status, snapshot, heap, trace, profile, auto on, auto off, clear.', ); } else if (command.startsWith('section ')) { void requestDebuggerAction('setActiveSection', { section: command.slice('section '.length).trim() }); @@ -306,6 +330,8 @@ function runCommand(rawCommand) { void requestDebuggerAction('captureElementSnapshot'); } else if (command === 'heap') { void requestDebuggerAction('dumpHeap'); + } else if (command === 'trace') { + void requestDebuggerAction('captureRendererTrace'); } else if (command === 'profile') { void requestDebuggerAction('captureCpuProfile'); } else if (command === 'auto on') { diff --git a/npm_modules/cli/debugger/debugger-bootstrap.js b/npm_modules/cli/debugger/debugger-bootstrap.js index 4d7abf002..3f953580f 100644 --- a/npm_modules/cli/debugger/debugger-bootstrap.js +++ b/npm_modules/cli/debugger/debugger-bootstrap.js @@ -41,11 +41,12 @@ document.addEventListener('keydown', event => { actionable.click(); }); -function selectTarget(id) { +async function selectTarget(id) { const target = debuggerTargets().find(candidate => candidate.id === id); if (!target) return; + if (!(await preparePerformanceTraceTargetSwitch(target))) return; if (target.daemonPort && target.port) { - setTargetPort(target.port); + await setTargetPort(target.port, target); state.snapshot.target = { ...state.snapshot.target, ...target, @@ -166,6 +167,10 @@ elements.autoRefreshToggle.addEventListener( 'change', () => void requestDebuggerAction('setAutoRefresh', { enabled: elements.autoRefreshToggle.checked }), ); +elements.traceStartButton.addEventListener('click', () => void requestDebuggerAction('startRendererTrace')); +elements.traceStopButton.addEventListener('click', () => void requestDebuggerAction('stopRendererTrace')); +elements.traceCaptureButton.addEventListener('click', () => void requestDebuggerAction('captureRendererTrace')); +elements.traceExportButton.addEventListener('click', exportPerformanceTrace); elements.profileRefreshButton.addEventListener('click', () => void requestDebuggerAction('refreshHermesContexts')); elements.profileStartButton.addEventListener('click', () => void requestDebuggerAction('startCpuProfile')); elements.profileStopButton.addEventListener('click', () => void requestDebuggerAction('stopCpuProfile')); @@ -210,4 +215,7 @@ applyDebuggerSessionDomState(); setAutoRefresh(state.autoRefresh, { silent: true }); installDebuggerSessionPersistence(); void refreshProfileContexts({ silent: true }); -refreshTargets({ silent: restoredDebuggerSession, autoAttach: !state.manualDetach }); +void (async () => { + await recoverPerformanceTraceState(); + await refreshTargets({ silent: restoredDebuggerSession, autoAttach: !state.manualDetach }); +})(); diff --git a/npm_modules/cli/debugger/debugger-performance.js b/npm_modules/cli/debugger/debugger-performance.js index 426be5121..56f4cd663 100644 --- a/npm_modules/cli/debugger/debugger-performance.js +++ b/npm_modules/cli/debugger/debugger-performance.js @@ -1,8 +1,8 @@ -// Hermes CPU profile UI behavior. -function readSecondsInput(input) { +// Renderer trace and Hermes CPU profile UI behavior. +function readSecondsInput(input, maximumSeconds) { const value = Number.parseFloat(input.value); if (!Number.isFinite(value)) return 5; - return Math.max(0.1, Math.min(60, value)); + return Math.max(0.1, Math.min(maximumSeconds, value)); } function formatMs(value) { @@ -10,6 +10,112 @@ function formatMs(value) { return `${value.toFixed(value >= 100 ? 0 : 1)} ms`; } +function traceSummaryText(result) { + const summary = result?.summary; + if (!summary || !result.traceCount) return 'No renderer trace captured.'; + const topComponent = summary.topComponents?.[0]; + const topTrigger = summary.topViewModelTriggers?.[0]; + const parts = [ + `${result.traceCount} events`, + `${summary.durationTraceCount || 0} durations`, + 'process-wide capture', + ]; + if (result.captureTarget?.contextId) { + parts.push(`requested from ${escapeHtml(String(result.captureTarget.contextId))}`); + } + if (result.droppedTraceEventCount) parts.push(`${result.droppedTraceEventCount} dropped`); + if (result.traceEventLimitReached) parts.push('native trace limit reached'); + if (result.elapsedMs !== undefined) parts.push(`window ${formatMs(result.elapsedMs)}`); + if (topComponent) parts.push(`top render ${escapeHtml(topComponent.name)} ${formatMs(topComponent.durationMs)}`); + if (topTrigger) parts.push(`top trigger ${escapeHtml(topTrigger.name)} x${topTrigger.count}`); + return parts.join(' · '); +} + +function traceEventsHtml(result) { + const traces = Array.isArray(result?.traces) ? result.traces : []; + if (!traces.length) return ''; + const baseMicros = traces.reduce((minimum, trace) => Math.min(minimum, trace.startMicros), traces[0].startMicros); + const visibleTraces = traces.slice(0, 80); + const eventLimitText = + visibleTraces.length === traces.length ? '' : ` (first ${visibleTraces.length} of ${traces.length})`; + const rows = visibleTraces.map(trace => { + const durationMs = Math.max(0, trace.endMicros - trace.startMicros) / 1000; + const details = JSON.stringify( + { + name: trace.trace, + threadId: trace.threadId, + startMs: (trace.startMicros - baseMicros) / 1000, + durationMs, + }, + null, + 2, + ); + return ` +
+ +
${escapeHtml(trace.trace)}
+
${escapeHtml(((trace.startMicros - baseMicros) / 1000).toFixed(2))} ms
+
${escapeHtml(formatMs(durationMs))}
+ + 
${escapeHtml(details)}
+
+ `; + }); + return ` +
+
Events${eventLimitText}
+
Start
+
Duration
+
+ ${rows.join('')} + `; +} + +function buildPerformanceTracePerfettoPayload(result) { + const traces = Array.isArray(result?.traces) ? result.traces : []; + const minimumStartMicros = traces.reduce( + (minimum, trace) => Math.min(minimum, trace.startMicros), + traces[0]?.startMicros || 0, + ); + const threadIds = Array.from(new Set(traces.map(trace => trace.threadId))) + .sort((left, right) => left - right) + .slice(0, 256); + const traceEvents = [ + { + name: 'process_name', + ph: 'M', + pid: 1, + args: { name: 'Valdi' }, + }, + ...threadIds.map(threadId => ({ + name: 'thread_name', + ph: 'M', + pid: 1, + tid: threadId, + args: { name: `Valdi thread ${threadId}` }, + })), + ]; + for (const trace of traces) { + const instant = /(?:^|\.)Renderer\.viewModelChange\.[^.]+\..+$/.test(trace.trace); + const event = { + name: trace.trace, + cat: 'valdi', + ph: instant ? 'i' : 'X', + pid: 1, + tid: trace.threadId, + ts: trace.startMicros - minimumStartMicros, + }; + if (instant) event.s = 't'; + else event.dur = Math.max(0, trace.endMicros - trace.startMicros); + traceEvents.push(event); + } + return { + displayTimeUnit: 'ms', + metadata: result?.perfettoMetadata || {}, + traceEvents, + }; +} + function profileSummaryText(result) { const summary = result?.summary; if (!summary || !result.profile) return 'No CPU profile captured.'; @@ -23,6 +129,57 @@ function profileSummaryText(result) { return parts.join(' · '); } +function normalizePerformanceTraceTarget(target) { + const port = Number(target?.port); + if (!Number.isFinite(port) || target?.clientId === undefined || target?.contextId === undefined) return null; + return { + port, + clientId: String(target.clientId), + contextId: String(target.contextId), + }; +} + +function performanceTraceTargetsMatch(left, right) { + const normalizedLeft = normalizePerformanceTraceTarget(left); + const normalizedRight = normalizePerformanceTraceTarget(right); + return Boolean( + normalizedLeft && + normalizedRight && + normalizedLeft.port === normalizedRight.port && + normalizedLeft.clientId === normalizedRight.clientId && + normalizedLeft.contextId === normalizedRight.contextId, + ); +} + +function syncActiveTraceState(result, fallbackTarget) { + state.performance.traceStateUnknown = false; + state.performance.traceActive = Boolean(result?.recording); + state.performance.traceResultPending = Boolean(result?.completedRecordingAvailable); + const resultContextId = result?.recording ? result.contextId : result?.completedContextId; + const resultTarget = + normalizePerformanceTraceTarget(result?.captureTarget) || normalizePerformanceTraceTarget(fallbackTarget); + if ((result?.recording || result?.completedRecordingAvailable) && resultTarget) { + state.performance.activeTraceTarget = { + ...resultTarget, + contextId: resultContextId === undefined ? resultTarget.contextId : String(resultContextId), + }; + } else if (!state.performance.traceCapturePending) { + state.performance.activeTraceTarget = null; + } + persistPerformanceTraceState(); +} + +function persistPerformanceTraceState() { + if (typeof persistDebuggerSessionState === 'function') persistDebuggerSessionState(); +} + +function markPerformanceTraceStateUnknown(target) { + const normalizedTarget = normalizePerformanceTraceTarget(target); + state.performance.traceStateUnknown = true; + if (normalizedTarget) state.performance.activeTraceTarget = normalizedTarget; + persistPerformanceTraceState(); +} + function syncActiveProfileState(activeProfile) { const contextId = activeProfile?.contextId; state.performance.profileActive = Boolean(activeProfile?.profiling); @@ -32,6 +189,33 @@ function syncActiveProfileState(activeProfile) { function renderPerformance() { const perf = state.performance; + const traceTargetAvailable = hasSelectedLiveTarget(); + const traceSupported = perf.traceSupported !== false; + const traceBusy = perf.traceActive || perf.traceCapturePending || perf.traceResultPending || perf.traceStateUnknown; + elements.traceStatusPill.textContent = perf.traceCapturePending + ? 'Capturing' + : perf.traceStateUnknown + ? 'Unknown' + : perf.traceActive + ? 'Recording' + : perf.traceResultPending + ? 'Ready' + : 'Idle'; + elements.traceStatusPill.className = `source-pill ${traceBusy ? 'live' : ''}`; + elements.traceStartButton.disabled = !traceTargetAvailable || !traceSupported || traceBusy; + elements.traceStopButton.disabled = + !traceTargetAvailable || + (!perf.traceActive && !perf.traceResultPending && !perf.traceStateUnknown) || + perf.traceCapturePending; + elements.traceCaptureButton.disabled = !traceTargetAvailable || !traceSupported || perf.traceCapturePending; + elements.traceCaptureButton.textContent = + perf.traceActive || perf.traceResultPending || perf.traceStateUnknown ? 'Stop & Capture' : 'Capture'; + elements.rendererTracingToggle.disabled = traceBusy; + elements.traceDurationInput.disabled = traceBusy; + elements.traceExportButton.disabled = !Array.isArray(perf.lastTrace?.traces); + elements.traceSummary.innerHTML = traceSummaryText(perf.lastTrace); + elements.traceEvents.innerHTML = traceEventsHtml(perf.lastTrace); + elements.profileStatusPill.textContent = perf.profileActive ? 'Recording' : 'Idle'; elements.profileStatusPill.className = `source-pill ${perf.profileActive ? 'live' : ''}`; elements.profileStartButton.disabled = perf.profileActive; @@ -51,6 +235,257 @@ function renderPerformance() { ].join(''); } +async function refreshPerformanceTraceStatus(options) { + const targetParams = + normalizePerformanceTraceTarget(options.target) || + normalizePerformanceTraceTarget(state.performance.activeTraceTarget) || + normalizePerformanceTraceTarget(getSelectedTargetParams()); + if (!targetParams) { + syncActiveTraceState(null); + state.performance.traceSupported = true; + if (options.render !== false) renderPerformance(); + return null; + } + + try { + const result = await apiGet('/api/performance/trace/status', targetParams, { + timeoutMs: options.timeoutMs || 10000, + }); + syncActiveTraceState(result, targetParams); + state.performance.traceSupported = result.tracingSupported === true; + return result; + } catch (error) { + if (!options.silent) addLog('warn', 'trace', error.message); + return null; + } finally { + if (options.render !== false) renderPerformance(); + } +} + +async function startPerformanceTrace() { + const targetParams = normalizePerformanceTraceTarget(getSelectedTargetParams()); + if (!targetParams) return; + const wasUnknown = state.performance.traceStateUnknown === true; + try { + const status = await refreshPerformanceTraceStatus({ silent: true, render: false, target: targetParams }); + if (!status) { + addLog('warn', 'trace', 'Could not verify renderer trace status; start was not sent.'); + return; + } + if (wasUnknown) { + addLog('info', 'trace', 'Recovering the uncertain renderer trace before starting another.'); + await stopPerformanceTrace({ target: targetParams, render: false }); + return; + } + if (status?.recording || status?.completedRecordingAvailable) { + syncActiveTraceState(status, targetParams); + addLog('warn', 'trace', 'A renderer trace is active or waiting to be retrieved. Use Stop first.'); + return; + } + if (status.tracingSupported !== true) { + addLog('warn', 'trace', 'This Valdi runtime does not support renderer trace capture.'); + return; + } + markPerformanceTraceStateUnknown(targetParams); + const result = await apiPost('/api/performance/trace/start', targetParams, { + rendererTracing: elements.rendererTracingToggle.checked, + }); + syncActiveTraceState(result, targetParams); + state.performance.traceSupported = result.tracingSupported !== false; + addLog('info', 'trace', `Started process-wide renderer trace from context ${targetParams.contextId}.`); + } catch (error) { + addLog('error', 'trace', error.message); + const status = await refreshPerformanceTraceStatus({ silent: true, render: false, target: targetParams }); + if (!status) markPerformanceTraceStateUnknown(targetParams); + } finally { + renderPerformance(); + } +} + +async function stopPerformanceTrace(options) { + const targetParams = + normalizePerformanceTraceTarget(options.target) || + normalizePerformanceTraceTarget(state.performance.activeTraceTarget) || + normalizePerformanceTraceTarget(getSelectedTargetParams()); + if (!targetParams) return false; + markPerformanceTraceStateUnknown(targetParams); + const applyResult = result => { + syncActiveTraceState(result, targetParams); + state.performance.traceSupported = result.tracingSupported === true; + state.performance.lastTrace = result; + addLog('info', 'trace', `Captured ${result.traceCount || 0} Valdi trace event(s).`); + if (result.completionError) addLog('warn', 'trace', result.completionError); + return true; + }; + try { + const result = await apiPost('/api/performance/trace/stop', targetParams, {}, { timeoutMs: 30000 }); + return applyResult(result); + } catch (error) { + addLog('error', 'trace', error.message); + const status = await refreshPerformanceTraceStatus({ silent: true, render: false, target: targetParams }); + if (!status) { + markPerformanceTraceStateUnknown(targetParams); + return false; + } + try { + const replayedResult = await apiPost('/api/performance/trace/stop', targetParams, {}, { timeoutMs: 30000 }); + return applyResult(replayedResult); + } catch (replayError) { + addLog('error', 'trace', `Could not retrieve the retained renderer trace: ${replayError.message}`); + markPerformanceTraceStateUnknown(targetParams); + return false; + } + } finally { + if (options.render !== false) renderPerformance(); + } +} + +async function preparePerformanceTraceTargetSwitch(nextTarget) { + const activeTarget = normalizePerformanceTraceTarget(state.performance.activeTraceTarget); + if (!activeTarget) { + if (state.performance.traceActive || state.performance.traceResultPending || state.performance.traceStateUnknown) { + addLog('warn', 'trace', 'Recover the uncertain renderer trace before switching targets.'); + return false; + } + return true; + } + if (performanceTraceTargetsMatch(activeTarget, nextTarget)) return true; + if (state.performance.traceCapturePending) { + addLog('warn', 'trace', 'Wait for the process-wide renderer trace capture to finish before switching targets.'); + return false; + } + if (!state.performance.traceActive && !state.performance.traceResultPending && !state.performance.traceStateUnknown) { + return true; + } + addLog('info', 'trace', 'Stopping the active process-wide renderer trace before switching targets.'); + if (await stopPerformanceTrace({ target: activeTarget, render: false })) return true; + if (!(await isPerformanceTraceTargetVerifiedMissing(activeTarget))) return false; + + state.performance.traceActive = false; + state.performance.traceResultPending = false; + state.performance.traceStateUnknown = false; + state.performance.activeTraceTarget = null; + state.performance.traceSupported = true; + persistPerformanceTraceState(); + addLog('warn', 'trace', 'The previous trace target disconnected; discarded its unrecoverable trace state.'); + return true; +} + +async function isPerformanceTraceTargetVerifiedMissing(target) { + let status; + try { + status = await apiGet('/api/status', { port: target.port }, { timeoutMs: 5000 }); + } catch { + // A transport failure does not prove that the prior context disappeared. + return false; + } + + const portStatus = status?.ports?.find(candidate => Number(candidate.port) === target.port); + if (!portStatus) return false; + // inspectPort reports connected:false for transient connection and inventory failures too. + // Only a successfully connected inventory can prove that the prior target disappeared. + if (portStatus.connected !== true || !Array.isArray(portStatus.clients)) return false; + + const client = portStatus.clients.find(candidate => String(candidate.client_id) === target.clientId); + if (!client) return true; + if (client.contextError !== null && client.contextError !== undefined) return false; + if (!Array.isArray(client.contexts)) return false; + return !client.contexts.some(context => String(context.id) === target.contextId); +} + +async function recoverPerformanceTraceState() { + const target = + normalizePerformanceTraceTarget(state.performance.activeTraceTarget) || + normalizePerformanceTraceTarget(getSelectedTargetParams()); + if (!target) return; + const wasUnknown = state.performance.traceStateUnknown === true; + const status = await refreshPerformanceTraceStatus({ silent: true, render: false, target }); + if (!status) { + if (wasUnknown) markPerformanceTraceStateUnknown(target); + renderPerformance(); + return; + } + if (status.recording || status.completedRecordingAvailable || wasUnknown) { + const completedTarget = { + ...target, + contextId: String(status.completedContextId || target.contextId), + }; + const recovered = await stopPerformanceTrace({ target: completedTarget, render: false }); + if (recovered) { + addLog('info', 'trace', 'Recovered the completed process-wide renderer trace from the runtime.'); + } + } + renderPerformance(); +} + +async function capturePerformanceTrace() { + const durationMs = Math.round(readSecondsInput(elements.traceDurationInput, 15) * 1000); + const targetParams = normalizePerformanceTraceTarget(getSelectedTargetParams()); + if (!targetParams) return; + const wasUnknown = state.performance.traceStateUnknown === true; + try { + const status = await refreshPerformanceTraceStatus({ silent: true, render: false, target: targetParams }); + if (!status) { + addLog('warn', 'trace', 'Could not verify renderer trace status; capture was not sent.'); + return; + } + if (status.recording || status.completedRecordingAvailable || state.performance.traceActive || wasUnknown) { + addLog('info', 'trace', 'Stopping active renderer trace.'); + await stopPerformanceTrace({ target: state.performance.activeTraceTarget || targetParams }); + return; + } + if (status.tracingSupported !== true) { + addLog('warn', 'trace', 'This Valdi runtime does not support renderer trace capture.'); + return; + } + state.performance.traceCapturePending = true; + markPerformanceTraceStateUnknown(targetParams); + renderPerformance(); + addLog('info', 'trace', `Capturing renderer trace for ${(durationMs / 1000).toFixed(1)}s.`); + const result = await apiPost( + '/api/performance/trace/capture', + targetParams, + { + rendererTracing: elements.rendererTracingToggle.checked, + durationMs, + }, + { timeoutMs: durationMs + 15000 }, + ); + syncActiveTraceState(result, targetParams); + state.performance.traceSupported = result.tracingSupported === true; + state.performance.lastTrace = result; + addLog('info', 'trace', `Captured ${result.traceCount || 0} Valdi trace event(s).`); + } catch (error) { + addLog('error', 'trace', error.message); + const status = await refreshPerformanceTraceStatus({ silent: true, render: false, target: targetParams }); + if (status) { + await stopPerformanceTrace({ target: targetParams, render: false }); + } else { + markPerformanceTraceStateUnknown(targetParams); + } + } finally { + state.performance.traceCapturePending = false; + if ( + !state.performance.traceActive && + !state.performance.traceResultPending && + !state.performance.traceStateUnknown + ) { + state.performance.activeTraceTarget = null; + } + renderPerformance(); + } +} + +function exportPerformanceTrace() { + const result = state.performance.lastTrace; + if (!Array.isArray(result?.traces)) return; + downloadJson( + buildPerformanceTracePerfettoPayload(result), + `${targetFilePrefix()}-valdi-trace.json`, + 'Exported Valdi trace JSON for Perfetto.', + ); +} + async function refreshProfileContexts(options) { try { const result = await apiGet('/api/performance/profile/contexts', {}, { timeoutMs: 5000 }); @@ -106,7 +541,7 @@ async function stopCpuProfile() { } async function captureCpuProfile() { - const durationMs = Math.round(readSecondsInput(elements.profileDurationInput) * 1000); + const durationMs = Math.round(readSecondsInput(elements.profileDurationInput, 60) * 1000); const contextId = selectedProfileContextId(); syncActiveProfileState({ profiling: true, contextId }); renderPerformance(); diff --git a/npm_modules/cli/debugger/debugger-runtime.js b/npm_modules/cli/debugger/debugger-runtime.js index 67f656b60..e7ac6dfab 100644 --- a/npm_modules/cli/debugger/debugger-runtime.js +++ b/npm_modules/cli/debugger/debugger-runtime.js @@ -147,6 +147,9 @@ async function refreshTargets(options = {}) { const previousTargetId = state.snapshot.target?.id || null; const selectedTarget = chooseLiveTarget(targets); const targetChanged = selectedTarget.id !== previousTargetId; + if (targetChanged && !(await preparePerformanceTraceTargetSwitch(selectedTarget))) { + return; + } state.snapshot.targets = markSelectedTarget(targets, selectedTarget); state.snapshot.target = { ...state.snapshot.target, diff --git a/npm_modules/cli/debugger/debugger-session.js b/npm_modules/cli/debugger/debugger-session.js index ca548d503..00dd7956f 100644 --- a/npm_modules/cli/debugger/debugger-session.js +++ b/npm_modules/cli/debugger/debugger-session.js @@ -34,6 +34,12 @@ function debuggerSessionPayload() { treeSearch: elements.treeSearch.value, logSearch: elements.logSearch.value, expandedNodeIds: Array.from(state.expandedNodeIds), + rendererTracing: elements.rendererTracingToggle.checked, + traceDuration: elements.traceDurationInput.value, + activeTraceTarget: state.performance.activeTraceTarget, + traceActive: state.performance.traceActive, + traceResultPending: state.performance.traceResultPending, + traceStateUnknown: state.performance.traceStateUnknown, profileDuration: elements.profileDurationInput.value, profileContextId: elements.profileContextSelect.value, }; @@ -107,6 +113,42 @@ function restoreDebuggerSessionState() { if (saved.treeSearch !== undefined) elements.treeSearch.value = String(saved.treeSearch); if (saved.logSearch !== undefined) elements.logSearch.value = String(saved.logSearch); + if (typeof saved.rendererTracing === 'boolean') elements.rendererTracingToggle.checked = saved.rendererTracing; + if (saved.traceDuration !== undefined) elements.traceDurationInput.value = String(saved.traceDuration); + const persistedTraceMayBeActive = + saved.traceStateUnknown === true || saved.traceActive === true || saved.traceResultPending === true; + if (saved.activeTraceTarget && typeof saved.activeTraceTarget === 'object') { + const activeTracePort = Number.parseInt(String(saved.activeTraceTarget.port || ''), 10); + if ( + Number.isFinite(activeTracePort) && + saved.activeTraceTarget.clientId !== undefined && + saved.activeTraceTarget.contextId !== undefined + ) { + state.performance.activeTraceTarget = { + port: activeTracePort, + clientId: String(saved.activeTraceTarget.clientId), + contextId: String(saved.activeTraceTarget.contextId), + }; + } + } + if (state.performance.activeTraceTarget === null && persistedTraceMayBeActive) { + const fallbackTraceTarget = state.snapshot.target || saved.target; + const fallbackTracePort = Number.parseInt(String(fallbackTraceTarget?.port || ''), 10); + if ( + Number.isFinite(fallbackTracePort) && + fallbackTraceTarget?.clientId !== undefined && + fallbackTraceTarget?.contextId !== undefined + ) { + state.performance.activeTraceTarget = { + port: fallbackTracePort, + clientId: String(fallbackTraceTarget.clientId), + contextId: String(fallbackTraceTarget.contextId), + }; + } + } + state.performance.traceActive = false; + state.performance.traceResultPending = false; + state.performance.traceStateUnknown = state.performance.activeTraceTarget !== null || persistedTraceMayBeActive; if (saved.profileDuration !== undefined) elements.profileDurationInput.value = String(saved.profileDuration); if (saved.profileContextId !== undefined) elements.profileContextSelect.value = String(saved.profileContextId); diff --git a/npm_modules/cli/debugger/debugger-state.js b/npm_modules/cli/debugger/debugger-state.js index eccccfabb..815770f54 100644 --- a/npm_modules/cli/debugger/debugger-state.js +++ b/npm_modules/cli/debugger/debugger-state.js @@ -56,6 +56,13 @@ const state = { followLatestTarget: true, exportObjectUrl: null, performance: { + traceActive: false, + traceCapturePending: false, + traceResultPending: false, + traceStateUnknown: false, + activeTraceTarget: null, + traceSupported: true, + lastTrace: null, profileActive: false, activeProfileContextId: null, lastProfile: null, @@ -97,6 +104,15 @@ const elements = { snapshotButton: document.getElementById('snapshotButton'), copyPreviewButton: document.getElementById('copyPreviewButton'), autoRefreshToggle: document.getElementById('autoRefreshToggle'), + rendererTracingToggle: document.getElementById('rendererTracingToggle'), + traceDurationInput: document.getElementById('traceDurationInput'), + traceStartButton: document.getElementById('traceStartButton'), + traceStopButton: document.getElementById('traceStopButton'), + traceCaptureButton: document.getElementById('traceCaptureButton'), + traceExportButton: document.getElementById('traceExportButton'), + traceStatusPill: document.getElementById('traceStatusPill'), + traceSummary: document.getElementById('traceSummary'), + traceEvents: document.getElementById('traceEvents'), profileContextSelect: document.getElementById('profileContextSelect'), profileRefreshButton: document.getElementById('profileRefreshButton'), profileDurationInput: document.getElementById('profileDurationInput'), diff --git a/npm_modules/cli/debugger/debugger.css b/npm_modules/cli/debugger/debugger.css index 33daf2a1d..e15873fc6 100644 --- a/npm_modules/cli/debugger/debugger.css +++ b/npm_modules/cli/debugger/debugger.css @@ -40,6 +40,7 @@ --device-shell: #10110e; --screen-bg: #fffefb; --overlay-label-bg: #10110e; + --trace-detail-bg: #fffdf7; --console-bg: #11110d; --console-surface: #1e1d17; --console-surface-2: #29271f; @@ -81,6 +82,7 @@ --device-shell: #120c16; --screen-bg: #fff8ef; --overlay-label-bg: #120c16; + --trace-detail-bg: #fff7ed; --console-bg: #130d18; --console-surface: #211629; --console-surface-2: #2f1d34; @@ -1107,6 +1109,84 @@ video.valdi-html-node { color: var(--text); } +.trace-events { + display: grid; + gap: 4px; + max-height: 190px; + overflow: auto; + border-top: 1px solid var(--line); + padding-top: 8px; +} + +.trace-events:empty { + display: none; +} + +.trace-events-header, +.trace-event-summary { + display: grid; + grid-template-columns: minmax(0, 1fr) 72px 72px; + gap: 8px; + align-items: baseline; +} + +.trace-events-header { + color: var(--muted); + font-size: 11px; + font-weight: 700; +} + +.trace-event-row { + border: 1px solid var(--line); + border-radius: 6px; + background: var(--surface); + font-family: ui-monospace, SFMono-Regular, Menlo, Monaco, Consolas, 'Liberation Mono', monospace; + font-size: 11px; +} + +.trace-event-summary { + padding: 5px 6px; + cursor: pointer; + list-style: none; +} + +.trace-event-summary::-webkit-details-marker { + display: none; +} + +.trace-event-name::before { + content: '>'; + display: inline-block; + width: 12px; + color: var(--muted); +} + +.trace-event-row[open] .trace-event-name::before { + content: 'v'; +} + +.trace-event-name { + min-width: 0; + overflow: hidden; + text-overflow: ellipsis; + white-space: nowrap; +} + +.trace-event-meta { + color: var(--muted); + text-align: right; +} + +.trace-event-details { + margin: 0; + border-top: 1px solid var(--line); + padding: 7px 8px 8px; + background: var(--trace-detail-bg); + color: var(--text); + white-space: pre-wrap; + overflow-wrap: anywhere; +} + .tabs { display: grid; grid-template-columns: repeat(5, 1fr); diff --git a/npm_modules/cli/debugger/index.html b/npm_modules/cli/debugger/index.html index 924f44f9a..e243e89bf 100644 --- a/npm_modules/cli/debugger/index.html +++ b/npm_modules/cli/debugger/index.html @@ -62,7 +62,7 @@

Daemon Status

+ + + + +
No renderer trace captured.
+
+
CPU
diff --git a/npm_modules/cli/src/core/packageFiles.spec.ts b/npm_modules/cli/src/core/packageFiles.spec.ts index 51084d411..a3589d88e 100644 --- a/npm_modules/cli/src/core/packageFiles.spec.ts +++ b/npm_modules/cli/src/core/packageFiles.spec.ts @@ -86,7 +86,6 @@ describe('npm package contents', () => { for (const deferredSurface of [ 'renderDataProviders', 'renderNetwork', - 'capturePerformanceTrace', 'renderWebPreviewFrame', ]) { expect(orderedBundle).not.toContain(deferredSurface); @@ -1079,6 +1078,12 @@ describe('npm package contents', () => { const performanceSource = fs.readFileSync(path.join(cliRoot, 'debugger', 'debugger-performance.js'), 'utf8'); const bootstrapSource = fs.readFileSync(path.join(cliRoot, 'debugger', 'debugger-bootstrap.js'), 'utf8'); const performanceState = { + traceActive: false, + traceCapturePending: false, + traceResultPending: false, + activeTraceTarget: null, + traceSupported: true, + lastTrace: null, profileActive: false, activeProfileContextId: null as string | null, lastProfile: null, @@ -1094,6 +1099,15 @@ describe('npm package contents', () => { const context = { state: { performance: performanceState }, elements: { + traceStatusPill: { textContent: '', className: '' }, + traceStartButton: { disabled: false }, + traceStopButton: { disabled: true }, + traceCaptureButton: { disabled: false, textContent: '' }, + traceExportButton: { disabled: true }, + rendererTracingToggle: { checked: true, disabled: false }, + traceDurationInput: { value: '5', disabled: false }, + traceSummary: { innerHTML: '' }, + traceEvents: { innerHTML: '' }, profileStatusPill: { textContent: '', className: '' }, profileStartButton, profileStopButton, @@ -1116,6 +1130,7 @@ describe('npm package contents', () => { }), addLog: () => {}, escapeHtml: String, + hasSelectedLiveTarget: () => false, }; await (new vm.Script(`${performanceSource}\nrefreshProfileContexts({ silent: true });`, { @@ -1139,6 +1154,12 @@ describe('npm package contents', () => { }; const pendingCapture = createDeferred(); const performanceState = { + traceActive: false, + traceCapturePending: false, + traceResultPending: false, + activeTraceTarget: null, + traceSupported: true, + lastTrace: null, profileActive: false, activeProfileContextId: null as string | null, lastProfile: null as typeof completedProfile | null, @@ -1156,6 +1177,15 @@ describe('npm package contents', () => { const context = { state: { performance: performanceState }, elements: { + traceStatusPill: { textContent: '', className: '' }, + traceStartButton: { disabled: false }, + traceStopButton: { disabled: true }, + traceCaptureButton: { disabled: false, textContent: '' }, + traceExportButton: { disabled: true }, + rendererTracingToggle: { checked: true, disabled: false }, + traceDurationInput: { value: '5', disabled: false }, + traceSummary: { innerHTML: '' }, + traceEvents: { innerHTML: '' }, profileStatusPill, profileStartButton, profileStopButton, @@ -1168,6 +1198,7 @@ describe('npm package contents', () => { apiPost: () => pendingCapture.promise, addLog: () => {}, escapeHtml: String, + hasSelectedLiveTarget: () => false, }; const captureOperation = new vm.Script(`${performanceSource}\ncaptureCpuProfile();`, { @@ -1194,4 +1225,504 @@ describe('npm package contents', () => { expect(profileStopButton.disabled).toBeTrue(); expect(profileCaptureButton.disabled).toBeFalse(); }); + + it('marks one-shot renderer capture pending until the measurement completes', async () => { + const performanceSource = fs.readFileSync(path.join(cliRoot, 'debugger', 'debugger-performance.js'), 'utf8'); + const completedTrace = { + recording: false, + completedRecordingAvailable: false, + tracingSupported: true, + captureTarget: { port: 13_591, clientId: '1', contextId: 'root' }, + traces: [], + traceCount: 0, + perfetto: { traceEvents: [] }, + }; + const pendingCapture = createDeferred(); + const performanceState = { + traceActive: false, + traceCapturePending: false, + traceResultPending: false, + traceStateUnknown: false, + activeTraceTarget: null as { port: number; clientId: string; contextId: string } | null, + traceSupported: true, + lastTrace: null as typeof completedTrace | null, + profileActive: false, + activeProfileContextId: null, + lastProfile: null, + profileContexts: [], + }; + const traceStatusPill = { textContent: '', className: '' }; + const traceStartButton = { disabled: false }; + const traceCaptureButton = { disabled: false, textContent: '' }; + const rendererTracingToggle = { checked: true, disabled: false }; + const traceDurationInput = { value: '5', disabled: false }; + const context = { + state: { performance: performanceState }, + elements: { + traceStatusPill, + traceStartButton, + traceStopButton: { disabled: true }, + traceCaptureButton, + traceExportButton: { disabled: true }, + rendererTracingToggle, + traceDurationInput, + traceSummary: { innerHTML: '' }, + traceEvents: { innerHTML: '' }, + profileStatusPill: { textContent: '', className: '' }, + profileStartButton: { disabled: false }, + profileStopButton: { disabled: true }, + profileCaptureButton: { disabled: false }, + profileExportButton: { disabled: true }, + profileSummary: { innerHTML: '' }, + profileContextSelect: { value: '', innerHTML: '', disabled: false }, + }, + apiGet: () => Promise.resolve({ recording: false, completedRecordingAvailable: false, tracingSupported: true }), + apiPost: () => pendingCapture.promise, + addLog: () => {}, + escapeHtml: String, + getSelectedTargetParams: () => ({ port: 13_591, clientId: '1', contextId: 'root' }), + hasSelectedLiveTarget: () => true, + }; + + const captureOperation = new vm.Script(`${performanceSource}\ncapturePerformanceTrace();`, { + filename: 'debugger-performance.js', + }).runInNewContext(context) as Promise; + await new Promise(resolve => setImmediate(resolve)); + + expect(performanceState.traceCapturePending).toBeTrue(); + expect(performanceState.traceStateUnknown).toBeTrue(); + expect(performanceState.activeTraceTarget).toEqual({ port: 13_591, clientId: '1', contextId: 'root' }); + expect(traceStatusPill.textContent).toBe('Capturing'); + expect(traceStartButton.disabled).toBeTrue(); + expect(traceCaptureButton.disabled).toBeTrue(); + expect(rendererTracingToggle.disabled).toBeTrue(); + expect(traceDurationInput.disabled).toBeTrue(); + + pendingCapture.resolve(completedTrace); + await captureOperation; + + expect(performanceState.traceCapturePending).toBeFalse(); + expect(performanceState.traceStateUnknown).toBeFalse(); + expect(performanceState.activeTraceTarget).toBeNull(); + expect(performanceState.lastTrace).toBe(completedTrace); + expect(traceStatusPill.textContent).toBe('Idle'); + }); + + it('keeps restored trace uncertainty after failed recovery and clears it only after verified absence', async () => { + const performanceSource = fs.readFileSync(path.join(cliRoot, 'debugger', 'debugger-performance.js'), 'utf8'); + const oldTarget = { port: 13_591, clientId: '1', contextId: 'root' }; + const performanceState = { + traceActive: false, + traceCapturePending: false, + traceResultPending: false, + traceStateUnknown: true, + activeTraceTarget: oldTarget, + traceSupported: true, + lastTrace: null, + }; + let targetPresence = 'transient'; + const context = { + state: { performance: performanceState }, + apiPost: () => Promise.reject(new Error('temporary stop transport failure')), + apiGet: (url: string) => { + if (url === '/api/performance/trace/status') { + return Promise.reject(new Error('temporary status transport failure')); + } + if (targetPresence === 'transient') { + return Promise.reject(new Error('temporary daemon status failure')); + } + return Promise.resolve({ + ports: [ + { + port: oldTarget.port, + connected: targetPresence !== 'disconnected', + clients: [ + { + client_id: oldTarget.clientId, + contexts: targetPresence === 'present' ? [{ id: oldTarget.contextId }] : [], + contextError: null, + }, + ], + }, + ], + }); + }, + addLog: () => {}, + getSelectedTargetParams: () => oldTarget, + renderPerformance: () => {}, + }; + await (new vm.Script(`${performanceSource}\nrenderPerformance = () => {};\nrecoverPerformanceTraceState();`, { + filename: 'debugger-performance.js', + }).runInNewContext(context) as Promise); + + expect(performanceState.traceStateUnknown).toBeTrue(); + expect(performanceState.activeTraceTarget).toEqual(oldTarget); + + const script = new vm.Script( + `${performanceSource}\npreparePerformanceTraceTargetSwitch({ port: 13592, clientId: '2', contextId: 'next' });`, + { filename: 'debugger-performance.js' }, + ); + + const transientResult = await (script.runInNewContext(context) as Promise); + + expect(transientResult).toBeFalse(); + expect(performanceState.traceStateUnknown).toBeTrue(); + expect(performanceState.activeTraceTarget).toEqual(oldTarget); + + targetPresence = 'disconnected'; + const transientDisconnectedResult = await (script.runInNewContext(context) as Promise); + + expect(transientDisconnectedResult).toBeFalse(); + expect(performanceState.traceStateUnknown).toBeTrue(); + expect(performanceState.activeTraceTarget).toEqual(oldTarget); + + targetPresence = 'present'; + const stillPresentResult = await (script.runInNewContext(context) as Promise); + + expect(stillPresentResult).toBeFalse(); + expect(performanceState.traceStateUnknown).toBeTrue(); + expect(performanceState.activeTraceTarget).toEqual(oldTarget); + + targetPresence = 'missing'; + const disconnectedResult = await (script.runInNewContext(context) as Promise); + + expect(disconnectedResult).toBeTrue(); + expect(performanceState.traceActive).toBeFalse(); + expect(performanceState.traceResultPending).toBeFalse(); + expect(performanceState.traceStateUnknown).toBeFalse(); + expect(performanceState.activeTraceTarget).toBeNull(); + }); + + it('restores a persisted active trace target conservatively as unknown', () => { + const sessionSource = fs.readFileSync(path.join(cliRoot, 'debugger', 'debugger-session.js'), 'utf8'); + const savedTarget = { port: 13_591, clientId: '1', contextId: 'root' }; + const persistedStates = [ + { activeTraceTarget: savedTarget }, + { target: savedTarget, traceActive: true }, + { target: savedTarget, traceResultPending: true }, + ]; + + for (const persistedState of persistedStates) { + const performanceState = { + traceActive: false, + traceResultPending: false, + traceStateUnknown: false, + activeTraceTarget: null as typeof savedTarget | null, + }; + const context = { + state: { + activeSection: 'performance', + activeTab: 'overview', + overlayMode: 'live', + autoRefresh: true, + followLatestTarget: true, + manualDetach: false, + selectedNodeId: null, + expandedNodeIds: new Set(), + snapshot: { target: {}, targets: [] }, + performance: performanceState, + }, + elements: { + sectionPanels: [], + portSelect: { value: '' }, + treeSearch: { value: '' }, + logSearch: { value: '' }, + rendererTracingToggle: { checked: true }, + traceDurationInput: { value: '5' }, + profileDurationInput: { value: '5' }, + profileContextSelect: { value: '' }, + }, + window: { + sessionStorage: { + getItem: () => JSON.stringify(persistedState), + setItem: () => {}, + }, + }, + selectedDaemonPort: () => 13_591, + normalizeSection: String, + console: { warn: () => {} }, + }; + + const restored = new vm.Script(`${sessionSource}\nrestoreDebuggerSessionState();`, { + filename: 'debugger-session.js', + }).runInNewContext(context) as boolean; + + expect(restored).toBeTrue(); + expect(performanceState.activeTraceTarget).toEqual(savedTarget); + expect(performanceState.traceActive).toBeFalse(); + expect(performanceState.traceResultPending).toBeFalse(); + expect(performanceState.traceStateUnknown).toBeTrue(); + } + }); + + it('retrieves a retained trace after reload and logs recovery only after Stop succeeds', async () => { + const performanceSource = fs.readFileSync(path.join(cliRoot, 'debugger', 'debugger-performance.js'), 'utf8'); + const target = { port: 13_591, clientId: '1', contextId: 'root' }; + const retainedResult = { + recording: false, + completedRecordingAvailable: false, + tracingSupported: true, + traces: [], + traceCount: 0, + perfettoMetadata: {}, + }; + const performanceState = { + traceActive: false, + traceCapturePending: false, + traceResultPending: false, + traceStateUnknown: true, + activeTraceTarget: target, + traceSupported: true, + lastTrace: null as typeof retainedResult | null, + }; + let stopSucceeds = false; + const logMessages: string[] = []; + const context = { + state: { performance: performanceState }, + apiGet: () => Promise.resolve({ recording: false, completedRecordingAvailable: false, tracingSupported: true }), + apiPost: () => + stopSucceeds ? Promise.resolve(retainedResult) : Promise.reject(new Error('temporary Stop failure')), + addLog: (_level: string, _source: string, message: string) => logMessages.push(message), + getSelectedTargetParams: () => target, + renderPerformance: () => {}, + }; + new vm.Script(`${performanceSource}\nrenderPerformance = () => {};`, { + filename: 'debugger-performance.js', + }).runInNewContext(context); + + await (new vm.Script('recoverPerformanceTraceState();').runInNewContext(context) as Promise); + + expect(performanceState.traceStateUnknown).toBeTrue(); + expect(performanceState.activeTraceTarget).toEqual(target); + expect(logMessages).not.toContain('Recovered the completed process-wide renderer trace from the runtime.'); + + stopSucceeds = true; + await (new vm.Script('recoverPerformanceTraceState();').runInNewContext(context) as Promise); + + expect(performanceState.traceStateUnknown).toBeFalse(); + expect(performanceState.activeTraceTarget).toBeNull(); + expect(performanceState.lastTrace).toBe(retainedResult); + expect(logMessages).toContain('Recovered the completed process-wide renderer trace from the runtime.'); + expect( + await (new vm.Script( + "preparePerformanceTraceTargetSwitch({ port: 13592, clientId: '2', contextId: 'next' });", + ).runInNewContext(context) as Promise), + ).toBeTrue(); + }); + + it('keeps a lost Start response explicitly unknown when status recovery also fails', async () => { + const performanceSource = fs.readFileSync(path.join(cliRoot, 'debugger', 'debugger-performance.js'), 'utf8'); + const target = { port: 13_591, clientId: '1', contextId: 'root' }; + const performanceState = { + traceActive: false, + traceCapturePending: false, + traceResultPending: false, + traceStateUnknown: false, + activeTraceTarget: null as typeof target | null, + traceSupported: true, + lastTrace: null, + }; + let statusCount = 0; + let persistCount = 0; + const context = { + state: { performance: performanceState }, + elements: { + rendererTracingToggle: { checked: true }, + }, + apiGet: () => { + statusCount++; + return statusCount === 1 + ? Promise.resolve({ recording: false, completedRecordingAvailable: false, tracingSupported: true }) + : Promise.reject(new Error('status unavailable')); + }, + apiPost: () => Promise.reject(new Error('lost start response')), + addLog: () => {}, + getSelectedTargetParams: () => target, + persistDebuggerSessionState: () => { + persistCount++; + }, + renderPerformance: () => {}, + }; + + await (new vm.Script(`${performanceSource}\nrenderPerformance = () => {};\nstartPerformanceTrace();`, { + filename: 'debugger-performance.js', + }).runInNewContext(context) as Promise); + + expect(performanceState.traceStateUnknown).toBeTrue(); + expect(performanceState.activeTraceTarget).toEqual(target); + expect(persistCount).toBeGreaterThan(0); + }); + + it('replays Stop after a lost response and retrieves the retained result', async () => { + const performanceSource = fs.readFileSync(path.join(cliRoot, 'debugger', 'debugger-performance.js'), 'utf8'); + const target = { port: 13_591, clientId: '1', contextId: 'root' }; + const retainedResult = { + recording: false, + completedRecordingAvailable: false, + tracingSupported: true, + traces: [], + traceCount: 0, + perfettoMetadata: {}, + }; + const performanceState = { + traceActive: true, + traceCapturePending: false, + traceResultPending: false, + traceStateUnknown: false, + activeTraceTarget: target, + traceSupported: true, + lastTrace: null as typeof retainedResult | null, + }; + let postCount = 0; + const context = { + state: { performance: performanceState }, + apiGet: () => Promise.resolve({ recording: false, completedRecordingAvailable: false, tracingSupported: true }), + apiPost: () => { + postCount++; + return postCount === 1 ? Promise.reject(new Error('lost stop response')) : Promise.resolve(retainedResult); + }, + addLog: () => {}, + getSelectedTargetParams: () => target, + renderPerformance: () => {}, + }; + + const stopped = await (new vm.Script( + `${performanceSource}\nrenderPerformance = () => {};\nstopPerformanceTrace({});`, + { + filename: 'debugger-performance.js', + }, + ).runInNewContext(context) as Promise); + + expect(stopped).toBeTrue(); + expect(postCount).toBe(2); + expect(performanceState.lastTrace).toBe(retainedResult); + expect(performanceState.traceStateUnknown).toBeFalse(); + expect(performanceState.activeTraceTarget).toBeNull(); + }); + + it('blocks Start and Capture when status is unavailable or lacks explicit support', async () => { + const performanceSource = fs.readFileSync(path.join(cliRoot, 'debugger', 'debugger-performance.js'), 'utf8'); + const target = { port: 13_591, clientId: '1', contextId: 'root' }; + const performanceState = { + traceActive: false, + traceCapturePending: false, + traceResultPending: false, + traceStateUnknown: false, + activeTraceTarget: null, + traceSupported: true, + lastTrace: null, + }; + let statusMode = 'unavailable'; + let postCount = 0; + const context = { + state: { performance: performanceState }, + elements: { + rendererTracingToggle: { checked: true }, + traceDurationInput: { value: '1' }, + }, + apiGet: () => + statusMode === 'unavailable' + ? Promise.reject(new Error('status timeout')) + : Promise.resolve({ recording: false, completedRecordingAvailable: false }), + apiPost: () => { + postCount++; + return Promise.resolve({}); + }, + addLog: () => {}, + getSelectedTargetParams: () => target, + renderPerformance: () => {}, + }; + const startScript = new vm.Script(`${performanceSource}\nrenderPerformance = () => {};\nstartPerformanceTrace();`, { + filename: 'debugger-performance.js', + }); + const captureScript = new vm.Script( + `${performanceSource}\nrenderPerformance = () => {};\ncapturePerformanceTrace();`, + { + filename: 'debugger-performance.js', + }, + ); + + await (startScript.runInNewContext(context) as Promise); + await (captureScript.runInNewContext(context) as Promise); + statusMode = 'legacy'; + await (startScript.runInNewContext(context) as Promise); + await (captureScript.runInNewContext(context) as Promise); + + expect(postCount).toBe(0); + }); + + it('does not start unsupported traces while keeping active cleanup enabled', async () => { + const performanceSource = fs.readFileSync(path.join(cliRoot, 'debugger', 'debugger-performance.js'), 'utf8'); + const target = { port: 13_591, clientId: '1', contextId: 'root' }; + const performanceState = { + traceActive: false, + traceCapturePending: false, + traceResultPending: false, + traceStateUnknown: false, + activeTraceTarget: null as typeof target | null, + traceSupported: true, + lastTrace: null, + profileActive: false, + activeProfileContextId: null, + lastProfile: null, + profileContexts: [], + }; + const traceStartButton = { disabled: false }; + const traceStopButton = { disabled: true }; + const traceCaptureButton = { disabled: false, textContent: '' }; + let postCount = 0; + const context = { + state: { performance: performanceState }, + elements: { + traceStatusPill: { textContent: '', className: '' }, + traceStartButton, + traceStopButton, + traceCaptureButton, + traceExportButton: { disabled: true }, + rendererTracingToggle: { checked: true, disabled: false }, + traceDurationInput: { value: '5', disabled: false }, + traceSummary: { innerHTML: '' }, + traceEvents: { innerHTML: '' }, + profileStatusPill: { textContent: '', className: '' }, + profileStartButton: { disabled: false }, + profileStopButton: { disabled: true }, + profileCaptureButton: { disabled: false }, + profileExportButton: { disabled: true }, + profileSummary: { innerHTML: '' }, + profileContextSelect: { value: '', innerHTML: '', disabled: false }, + }, + apiGet: () => + Promise.resolve({ + recording: false, + completedRecordingAvailable: false, + tracingSupported: false, + }), + apiPost: () => { + postCount++; + return Promise.resolve({}); + }, + addLog: () => {}, + escapeHtml: String, + getSelectedTargetParams: () => target, + hasSelectedLiveTarget: () => true, + }; + + await (new vm.Script(`${performanceSource}\nstartPerformanceTrace();`, { + filename: 'debugger-performance.js', + }).runInNewContext(context) as Promise); + await (new vm.Script(`${performanceSource}\ncapturePerformanceTrace();`, { + filename: 'debugger-performance.js', + }).runInNewContext(context) as Promise); + + expect(postCount).toBe(0); + expect(performanceState.traceSupported).toBeFalse(); + performanceState.traceActive = true; + performanceState.activeTraceTarget = target; + new vm.Script(`${performanceSource}\nrenderPerformance();`, { + filename: 'debugger-performance.js', + }).runInNewContext(context); + expect(traceStartButton.disabled).toBeTrue(); + expect(traceCaptureButton.disabled).toBeTrue(); + expect(traceStopButton.disabled).toBeFalse(); + }); }); diff --git a/npm_modules/cli/src/debugger/server.spec.ts b/npm_modules/cli/src/debugger/server.spec.ts index f41feac4a..5e50ad19c 100644 --- a/npm_modules/cli/src/debugger/server.spec.ts +++ b/npm_modules/cli/src/debugger/server.spec.ts @@ -7,7 +7,20 @@ import * as path from 'node:path'; import { valdiDebugger } from '../commands/debugger'; import { ArgumentsResolver } from '../utils/ArgumentsResolver'; import type { DebuggerServerInfo } from './server'; -import { projectDebuggerTreeForJson, startDebuggerServer } from './server'; +import { + MAX_TRACE_EVENT_COUNT, + MAX_TRACE_HTTP_RESPONSE_BYTES, + PerformanceTraceAction, + assertPerformanceTraceContext, + buildPerfettoTracePayload, + decorateTraceResult, + normalizeTraceCaptureDurationMs, + projectDebuggerTreeForJson, + readRecordedTraces, + runPerformanceTraceCapture, + startDebuggerServer, + summarizeTraces, +} from './server'; interface HttpResult { body: string; @@ -936,6 +949,340 @@ describe('debugger server', () => { expect((JSON.parse(second.body) as { error: string }).error).toContain('transition is already in progress'); }); + it('serializes concurrent renderer trace transitions before reading their bodies', async () => { + debuggerServer = await startDebuggerServer({ + assetRoot, + host: '127.0.0.1', + port: await getFreePort(), + strictPort: true, + }); + const traceUrl = new URL('/api/performance/trace/start', debuggerServer.url).toString(); + const first = startStreamingRequest(traceUrl, 'POST', { 'Content-Type': 'application/json' }); + first.request.write('{'); + await new Promise(resolve => setTimeout(resolve, 20)); + + const second = await request(traceUrl, { + method: 'POST', + headers: { 'Content-Type': 'application/json' }, + body: '{}', + }); + first.request.end('invalid'); + await first.result; + + expect(second.statusCode).toBe(500); + expect((JSON.parse(second.body) as { error: string }).error).toContain( + 'renderer trace transition is already in progress', + ); + }); + + it('enforces HTTP methods for renderer trace routes before contacting a target', async () => { + debuggerServer = await startDebuggerServer({ + assetRoot, + host: '127.0.0.1', + port: await getFreePort(), + strictPort: true, + }); + + const status = await request(new URL('/api/performance/trace/status', debuggerServer.url).toString(), { + method: 'POST', + headers: { 'Content-Type': 'application/json' }, + body: '{}', + }); + const start = await request( + new URL('/api/performance/trace/start', debuggerServer.url).toString(), + GET_REQUEST_OPTIONS, + ); + + expect(status.statusCode).toBe(500); + expect((JSON.parse(status.body) as { error: string }).error).toBe('Performance trace status requires GET.'); + expect(start.statusCode).toBe(500); + expect((JSON.parse(start.body) as { error: string }).error).toBe('Performance trace start requires POST.'); + }); + + it('validates renderer trace options before contacting a target', async () => { + debuggerServer = await startDebuggerServer({ + assetRoot, + host: '127.0.0.1', + port: await getFreePort(), + strictPort: true, + }); + + const result = await request(new URL('/api/performance/trace/start', debuggerServer.url).toString(), { + method: 'POST', + headers: { 'Content-Type': 'application/json' }, + body: JSON.stringify({ rendererTracing: 'true' }), + }); + + expect(result.statusCode).toBe(400); + expect((JSON.parse(result.body) as { error: string }).error).toBe( + 'rendererTracing must be a boolean when provided.', + ); + }); + + it('converts bounded renderer traces into summaries and Perfetto events', () => { + const traces = readRecordedTraces([ + { trace: 'Renderer.onRender.App', startMicros: 1000, endMicros: 4000, threadId: 7 }, + { + trace: 'Renderer.viewModelChange.App.title', + startMicros: 4000, + endMicros: 4000, + threadId: 7, + }, + ]); + const summary = summarizeTraces(traces); + const perfetto = buildPerfettoTracePayload(traces, { name: 'Example', contextId: 'root' }, 0); + const renderEvent = perfetto.traceEvents.find(event => event.name === 'Renderer.onRender.App'); + const triggerEvent = perfetto.traceEvents.find(event => event.name === 'Renderer.viewModelChange.App.title'); + + expect(summary.traceCount).toBe(2); + expect(summary.captureScope).toBe('process-wide'); + expect(summary.durationTraceCount).toBe(1); + expect(summary.instantTraceCount).toBe(1); + expect(summary.topComponents).toEqual([{ name: 'App', count: 1, durationMs: 3 }]); + expect(summary.topViewModelTriggers).toEqual([{ name: 'App.title', count: 1 }]); + expect(renderEvent).toEqual(jasmine.objectContaining({ ph: 'X', ts: 0, dur: 3000, tid: 7 })); + expect(renderEvent?.args).toBeUndefined(); + expect(triggerEvent).toEqual(jasmine.objectContaining({ ph: 'i', ts: 3000, s: 't', tid: 7 })); + expect(perfetto.metadata).toEqual({ + captureScope: 'process-wide', + captureTargetContextId: 'root', + captureTargetName: 'Example', + droppedTraceEventCount: 0, + }); + + const fabricatedInstant = buildPerfettoTracePayload( + readRecordedTraces([{ trace: 'Unrelated.trace', startMicros: 1, endMicros: 2, threadId: 1, type: 1 }]), + {}, + 0, + ).traceEvents.find(event => event.name === 'Unrelated.trace'); + expect(fabricatedInstant).toEqual(jasmine.objectContaining({ ph: 'X', dur: 1 })); + }); + + it('drops malformed renderer trace events and caps conversion work', () => { + const malformed = readRecordedTraces([ + { trace: 'valid', startMicros: 1, endMicros: 2, threadId: 1 }, + { trace: '', startMicros: 1, endMicros: 2, threadId: 1 }, + { trace: 'negative', startMicros: -1, endMicros: 2, threadId: 1 }, + { trace: 'backwards', startMicros: 2, endMicros: 1, threadId: 1 }, + { trace: 'unsafe', startMicros: 1, endMicros: 2, threadId: Number.MAX_SAFE_INTEGER + 1 }, + { trace: 'x'.repeat(2049), startMicros: 1, endMicros: 2, threadId: 1 }, + { trace: 'é'.repeat(1025), startMicros: 1, endMicros: 2, threadId: 1 }, + null, + ]); + const manyEvents = Array.from({ length: MAX_TRACE_EVENT_COUNT + 1 }, (_, index) => ({ + trace: `event-${index}`, + startMicros: index, + endMicros: index, + threadId: 1, + })); + + expect(malformed).toEqual([{ trace: 'valid', startMicros: 1, endMicros: 2, threadId: 1 }]); + expect(readRecordedTraces(manyEvents).length).toBe(MAX_TRACE_EVENT_COUNT); + expect(readRecordedTraces([{ trace: 'é'.repeat(1024), startMicros: 1, endMicros: 2, threadId: 1 }]).length).toBe(1); + }); + + it('derives trace truncation from dropped counts rather than an exactly-full result', () => { + const trace = { trace: 'valid', startMicros: 1, endMicros: 2, threadId: 1 }; + const exactlyFull = decorateTraceResult( + { + traces: Array.from({ length: MAX_TRACE_EVENT_COUNT }, () => trace), + droppedTraceEventCount: 0, + }, + {}, + ); + const truncated = decorateTraceResult({ traces: [trace], droppedTraceEventCount: 2 }, {}); + const truncatedPerfettoMetadata = truncated['perfettoMetadata'] as { droppedTraceEventCount: number }; + + expect(exactlyFull['droppedTraceEventCount']).toBe(0); + expect(exactlyFull['traceEventLimitReached']).toBeFalse(); + expect(truncated['droppedTraceEventCount']).toBe(2); + expect(truncated['traceEventLimitReached']).toBeTrue(); + expect(truncatedPerfettoMetadata.droppedTraceEventCount).toBe(2); + }); + + it('bounds the complete HTTP trace result without duplicating Perfetto events', () => { + const escapedTraceName = '\0'.repeat(2048); + const result = decorateTraceResult( + { + recording: false, + contextId: '\0'.repeat(100_000), + completedRecordingAvailable: false, + completionError: '\0'.repeat(100_000), + rendererTracingEnabled: false, + tracingSupported: true, + traces: Array.from({ length: 512 }, (_, index) => ({ + trace: escapedTraceName, + startMicros: index, + endMicros: index + 1, + threadId: 1, + })), + droppedTraceEventCount: 0, + timedOut: false, + }, + { contextId: '\0'.repeat(100_000), name: '\0'.repeat(100_000), port: 13_591 }, + ); + const serialized = JSON.stringify(result); + + expect(Buffer.byteLength(serialized, 'utf8')).toBeLessThanOrEqual(MAX_TRACE_HTTP_RESPONSE_BYTES); + expect(result['perfetto']).toBeUndefined(); + expect(Array.isArray(result['traces'])).toBeTrue(); + expect(result['traceCount'] as number).toBeLessThan(512); + expect(result['traceEventLimitReached']).toBeTrue(); + expect((result['perfettoMetadata'] as { droppedTraceEventCount: number }).droppedTraceEventCount).toBe( + result['droppedTraceEventCount'] as number, + ); + }); + + it('saturates local trace drops at Number.MAX_SAFE_INTEGER', () => { + const result = decorateTraceResult( + { + traces: [ + { trace: 'valid', startMicros: 1, endMicros: 2, threadId: 1 }, + { trace: '', startMicros: 1, endMicros: 2, threadId: 1 }, + ], + droppedTraceEventCount: Number.MAX_SAFE_INTEGER, + }, + {}, + ); + + expect(result['droppedTraceEventCount']).toBe(Number.MAX_SAFE_INTEGER); + }); + + it('clamps renderer trace capture duration and rejects invalid values', () => { + expect(normalizeTraceCaptureDurationMs({})).toBe(5000); + expect(normalizeTraceCaptureDurationMs({ durationMs: -1 })).toBe(100); + expect(normalizeTraceCaptureDurationMs({ durationMs: 40_000 })).toBe(15_000); + expect(normalizeTraceCaptureDurationMs({ durationMs: 123.6 })).toBe(124); + expect(() => normalizeTraceCaptureDurationMs({ durationMs: '5000' })).toThrowError( + Error, + 'durationMs must be a finite number when provided.', + ); + }); + + it('rejects one-shot capture without stopping an existing manual trace', async () => { + const actions: PerformanceTraceAction[] = []; + let waitCalled = false; + + await expectAsync( + runPerformanceTraceCapture( + { durationMs: 100, rendererTracing: true }, + { + send: action => { + actions.push(action); + return Promise.resolve({ + recording: true, + contextId: 'root', + completedRecordingAvailable: false, + tracingSupported: true, + }); + }, + wait: () => { + waitCalled = true; + return Promise.resolve(); + }, + }, + ), + ).toBeRejectedWithError( + Error, + 'A renderer trace recording is already active or waiting to be retrieved for context root. Stop it before one-shot capture.', + ); + + expect(actions).toEqual([PerformanceTraceAction.Status]); + expect(waitCalled).toBeFalse(); + }); + + it('best-effort stops a one-shot trace when waiting fails', async () => { + const actions: PerformanceTraceAction[] = []; + + await expectAsync( + runPerformanceTraceCapture( + { durationMs: 100, rendererTracing: true }, + { + send: action => { + actions.push(action); + if (action === PerformanceTraceAction.Status) { + return Promise.resolve({ + recording: false, + completedRecordingAvailable: false, + tracingSupported: true, + }); + } + return Promise.resolve({ recording: action === PerformanceTraceAction.Start }); + }, + wait: () => Promise.reject(new Error('wait failed')), + }, + ), + ).toBeRejectedWithError(Error, 'wait failed'); + + expect(actions).toEqual([PerformanceTraceAction.Status, PerformanceTraceAction.Start, PerformanceTraceAction.Stop]); + }); + + it('retries a failed stop so a handler-retained timed-out result can be recovered', async () => { + const actions: PerformanceTraceAction[] = []; + let stopCount = 0; + + const result = await runPerformanceTraceCapture( + { durationMs: 100, rendererTracing: true }, + { + send: action => { + actions.push(action); + if (action === PerformanceTraceAction.Status) { + return Promise.resolve({ + recording: false, + completedRecordingAvailable: false, + tracingSupported: true, + }); + } + if (action === PerformanceTraceAction.Stop && ++stopCount === 1) { + return Promise.reject(new Error('transient stop failure')); + } + return Promise.resolve({ recording: action === PerformanceTraceAction.Start, traces: [] }); + }, + wait: () => Promise.resolve(), + }, + ); + + expect(result['traces']).toEqual([]); + expect(actions).toEqual([ + PerformanceTraceAction.Status, + PerformanceTraceAction.Start, + PerformanceTraceAction.Stop, + PerformanceTraceAction.Stop, + ]); + }); + + it('does not start one-shot capture when runtime tracing support is absent', async () => { + const actions: PerformanceTraceAction[] = []; + + await expectAsync( + runPerformanceTraceCapture( + { durationMs: 100, rendererTracing: true }, + { + send: action => { + actions.push(action); + return Promise.resolve({ + recording: false, + completedRecordingAvailable: false, + tracingSupported: false, + }); + }, + wait: () => Promise.resolve(), + }, + ), + ).toBeRejectedWithError(Error, 'This Valdi runtime does not support renderer trace capture.'); + + expect(actions).toEqual([PerformanceTraceAction.Status]); + }); + + it('rejects trace output that does not match the selected context', () => { + expect(() => + assertPerformanceTraceContext(PerformanceTraceAction.Stop, { contextId: 'context-a' }, 'context-b'), + ).toThrowError(Error, 'The Valdi runtime returned trace data for context context-a, expected context-b.'); + expect(() => + assertPerformanceTraceContext(PerformanceTraceAction.Status, { contextId: 'context-a' }, 'context-b'), + ).not.toThrow(); + }); + it('does not serve paths outside the debugger asset root', async () => { debuggerServer = await startDebuggerServer({ assetRoot, diff --git a/npm_modules/cli/src/debugger/server.ts b/npm_modules/cli/src/debugger/server.ts index 4d744e122..44455c2e6 100644 --- a/npm_modules/cli/src/debugger/server.ts +++ b/npm_modules/cli/src/debugger/server.ts @@ -36,6 +36,29 @@ const MAX_DEBUGGER_TREE_NODES = 25_000; const MAX_DEBUGGER_PROJECTION_VALUES = 250_000; const MAX_DEBUGGER_PROJECTION_DEPTH = 64; const MAX_DEBUGGER_PROJECTION_STRING_LENGTH = 50_000; +const DEFAULT_TRACE_CAPTURE_DURATION_MS = 5000; +const MIN_TRACE_CAPTURE_DURATION_MS = 100; +const MAX_TRACE_CAPTURE_DURATION_MS = 15_000; +export const MAX_TRACE_EVENT_COUNT = 10_000; +const MAX_TRACE_NAME_BYTES = 2048; +const MAX_TRACE_THREAD_METADATA_COUNT = 256; +export const MAX_TRACE_HTTP_RESPONSE_BYTES = 4 * 1024 * 1024; +const MAX_TRACE_HTTP_STRING_BYTES = 64 * 1024; +const TRACE_DAEMON_TIMEOUT_MS = 30_000; +const PERFETTO_PROCESS_ID = 1; +const PERFETTO_PROCESS_NAME = 'Valdi'; +const PERFETTO_TRACE_CATEGORY = 'valdi'; +const PROCESS_WIDE_CAPTURE_SCOPE = 'process-wide'; +const TRACE_CAPTURE_TARGET_STRING_KEYS = [ + 'id', + 'name', + 'platform', + 'transport', + 'state', + 'clientId', + 'contextId', + 'applicationId', +] as const; const MIME_TYPES: Record = { '.html': 'text/html; charset=utf-8', @@ -74,6 +97,74 @@ interface ClientWithContexts extends DaemonConnectedClient { contextError: string | null; } +export interface RecordedTrace { + trace: string; + startMicros: number; + endMicros: number; + threadId: number; +} + +export interface PerfettoCaptureMetadata { + captureScope: string; + captureTargetContextId: unknown; + captureTargetName: unknown; + droppedTraceEventCount: number; +} + +export interface PerfettoTraceEvent { + name: string; + cat?: string; + ph: string; + pid: number; + tid?: number; + ts?: number; + dur?: number; + s?: string; + args?: Record; +} + +export interface TraceComponentSummary { + name: string; + count: number; + durationMs: number; +} + +export interface TraceViewModelTriggerSummary { + name: string; + count: number; +} + +export interface RendererTraceSummary { + captureScope: string; + traceCount: number; + durationTraceCount: number; + instantTraceCount: number; + topComponents: TraceComponentSummary[]; + topViewModelTriggers: TraceViewModelTriggerSummary[]; +} + +export interface PerfettoTracePayload { + displayTimeUnit: string; + metadata: PerfettoCaptureMetadata; + traceEvents: PerfettoTraceEvent[]; +} + +export enum PerformanceTraceAction { + Status, + Start, + Stop, +} + +export interface PerformanceTraceCaptureOptions { + durationMs: number; + rendererTracing: boolean; +} + +export interface PerformanceTraceCaptureDependencies { + send(action: PerformanceTraceAction, data: Record): Promise>; + wait(durationMs: number): Promise; +} + interface ActiveProfileSession { conn: HermesConnection; port: number; @@ -159,6 +250,9 @@ const debuggerActions = [ 'clearLogs', 'captureElementSnapshot', 'dumpHeap', + 'startRendererTrace', + 'stopRendererTrace', + 'captureRendererTrace', 'refreshHermesContexts', 'startCpuProfile', 'stopCpuProfile', @@ -173,6 +267,7 @@ let activeLogsDirectory: string | null = null; let activeWebPreviewTarget: WebPreviewDebuggerTarget | null = null; let activeProfileSession: ActiveProfileSession | null = null; let profileTransitionInProgress = false; +let traceTransitionInProgress = false; const debuggerUiState = createDebuggerUiState(); function getDefaultAssetRoot(): string { @@ -260,9 +355,28 @@ function portName(port: number): string { return 'custom'; } +function truncateStringForJson(value: string, maximumBytes: number): string { + if (Buffer.byteLength(JSON.stringify(value), 'utf8') <= maximumBytes) return value; + const suffix = '…'; + let minimumLength = 0; + let maximumLength = value.length; + let truncated = suffix; + while (minimumLength <= maximumLength) { + const candidateLength = Math.floor((minimumLength + maximumLength) / 2); + const candidate = `${value.slice(0, candidateLength)}${suffix}`; + if (Buffer.byteLength(JSON.stringify(candidate), 'utf8') <= maximumBytes) { + truncated = candidate; + minimumLength = candidateLength + 1; + } else { + maximumLength = candidateLength - 1; + } + } + return truncated; +} + function errorPayload(error: unknown): { error: string } { return { - error: error instanceof Error ? error.message : String(error), + error: truncateStringForJson(error instanceof Error ? error.message : String(error), MAX_TRACE_HTTP_STRING_BYTES), }; } @@ -817,6 +931,19 @@ function sendJson(response: ServerResponse, status: number, payload: unknown): v response.end(JSON.stringify(payload)); } +function sendTraceJson(response: ServerResponse, status: number, payload: unknown): void { + const serialized = JSON.stringify(payload); + if (Buffer.byteLength(serialized, 'utf8') > MAX_TRACE_HTTP_RESPONSE_BYTES) { + sendJson(response, 500, { error: 'Valdi performance trace response exceeded the HTTP size limit.' }); + return; + } + response.writeHead(status, { + 'Content-Type': 'application/json; charset=utf-8', + 'Cache-Control': 'no-store', + }); + response.end(serialized); +} + async function readJsonBody(request: IncomingMessage): Promise> { const chunks: Buffer[] = []; let byteLength = 0; @@ -862,6 +989,24 @@ function readBodyNumber(body: Record, key: string, fallback: nu return Number.isNaN(parsed) ? fallback : parsed; } +function readRendererTracing(body: Record): boolean { + const value = body['rendererTracing']; + if (value === undefined) return true; + if (typeof value !== 'boolean') { + throw new ApiRequestError(400, 'rendererTracing must be a boolean when provided.'); + } + return value; +} + +export function normalizeTraceCaptureDurationMs(body: Record): number { + const value = body['durationMs']; + if (value === undefined) return DEFAULT_TRACE_CAPTURE_DURATION_MS; + if (typeof value !== 'number' || !Number.isFinite(value)) { + throw new ApiRequestError(400, 'durationMs must be a finite number when provided.'); + } + return clampNumber(Math.round(value), MIN_TRACE_CAPTURE_DURATION_MS, MAX_TRACE_CAPTURE_DURATION_MS); +} + function readBodyString(body: Record, key: string): string | undefined { const value = body[key]; if (value === undefined || value === null || value === '') return undefined; @@ -1761,6 +1906,24 @@ async function resolveClient( return { clients, client }; } +function createDaemonTargetPayload( + port: number, + client: DaemonConnectedClient, + context: RemoteContext, +): Record { + return { + id: `${port}:${client.client_id}:${context.id}`, + name: context.rootComponentName || client.application_id || `Client ${client.client_id}`, + platform: client.platform || portName(port), + transport: `daemon:${port}`, + state: 'attached', + port, + clientId: client.client_id, + contextId: context.id, + applicationId: client.application_id, + }; +} + function flattenTargets( port: number, clients: ClientWithContexts[], @@ -1866,6 +2029,414 @@ async function inspectHeap(request: IncomingMessage, searchParams: URLSearchPara }); } +async function sendPerformanceTraceMessage( + searchParams: URLSearchParams, + action: PerformanceTraceAction, + data: Record, +): Promise> { + const port = readNumber(searchParams, 'port', STANDALONE_PORT); + return await withConnection(port, async conn => { + const { client, context } = await resolveTarget(searchParams, conn); + + let result: Record; + if (action === PerformanceTraceAction.Status) { + result = await conn.performanceTraceStatus(client.client_id, { contextId: context.id }, TRACE_DAEMON_TIMEOUT_MS); + } else if (action === PerformanceTraceAction.Start) { + const rendererTracing = data['rendererTracing']; + if (typeof rendererTracing !== 'boolean') { + throw new TypeError('Performance trace start requires a rendererTracing boolean.'); + } + result = await conn.performanceTraceStart( + client.client_id, + { + contextId: context.id, + rendererTracing, + }, + TRACE_DAEMON_TIMEOUT_MS, + ); + } else { + result = await conn.performanceTraceStop(client.client_id, { contextId: context.id }, TRACE_DAEMON_TIMEOUT_MS); + } + + assertPerformanceTraceContext(action, result, context.id); + + return decorateTraceResult(result, createDaemonTargetPayload(port, client, context)); + }); +} + +export function assertPerformanceTraceContext( + action: PerformanceTraceAction, + result: Record, + expectedContextId: string, +): void { + if (action !== PerformanceTraceAction.Status && result['contextId'] !== expectedContextId) { + throw new Error( + `The Valdi runtime returned trace data for context ${String(result['contextId'])}, expected ${expectedContextId}.`, + ); + } +} + +async function inspectPerformanceTraceStatus( + request: IncomingMessage, + searchParams: URLSearchParams, +): Promise> { + if (request.method !== 'GET') { + throw new Error('Performance trace status requires GET.'); + } + return await sendPerformanceTraceMessage(searchParams, PerformanceTraceAction.Status, {}); +} + +async function startPerformanceTrace( + request: IncomingMessage, + searchParams: URLSearchParams, +): Promise> { + if (request.method !== 'POST') { + throw new Error('Performance trace start requires POST.'); + } + return await runTraceTransition(async () => { + const body = await readJsonBody(request); + return await sendPerformanceTraceMessage(searchParams, PerformanceTraceAction.Start, { + rendererTracing: readRendererTracing(body), + }); + }); +} + +async function stopPerformanceTrace( + request: IncomingMessage, + searchParams: URLSearchParams, +): Promise> { + if (request.method !== 'POST') { + throw new Error('Performance trace stop requires POST.'); + } + return await runTraceTransition( + async () => await sendPerformanceTraceMessage(searchParams, PerformanceTraceAction.Stop, {}), + ); +} + +async function capturePerformanceTrace( + request: IncomingMessage, + searchParams: URLSearchParams, +): Promise> { + if (request.method !== 'POST') { + throw new Error('Performance trace capture requires POST.'); + } + return await runTraceTransition(async () => { + const body = await readJsonBody(request); + const options: PerformanceTraceCaptureOptions = { + durationMs: normalizeTraceCaptureDurationMs(body), + rendererTracing: readRendererTracing(body), + }; + return await runPerformanceTraceCapture(options, { + send: async (action, data) => await sendPerformanceTraceMessage(searchParams, action, data), + wait: delay, + }); + }); +} + +export async function runPerformanceTraceCapture( + options: PerformanceTraceCaptureOptions, + dependencies: PerformanceTraceCaptureDependencies, +): Promise> { + const status = await dependencies.send(PerformanceTraceAction.Status, {}); + if (status['tracingSupported'] !== true) { + throw new Error('This Valdi runtime does not support renderer trace capture.'); + } + if (status['recording'] || status['completedRecordingAvailable']) { + const contextId = status['contextId'] ?? status['completedContextId']; + const contextSuffix = typeof contextId === 'string' ? ` for context ${contextId}` : ''; + throw new Error( + `A renderer trace recording is already active or waiting to be retrieved${contextSuffix}. Stop it before one-shot capture.`, + ); + } + + await dependencies.send(PerformanceTraceAction.Start, { rendererTracing: options.rendererTracing }); + try { + await dependencies.wait(options.durationMs); + } catch (waitError) { + try { + await dependencies.send(PerformanceTraceAction.Stop, {}); + } catch (cleanupError) { + throw new Error( + `${errorPayload(waitError).error} Best-effort renderer trace cleanup also failed: ${errorPayload(cleanupError).error}`, + ); + } + throw waitError; + } + + try { + return await dependencies.send(PerformanceTraceAction.Stop, {}); + } catch (stopError) { + try { + return await dependencies.send(PerformanceTraceAction.Stop, {}); + } catch (cleanupError) { + throw new Error( + `${errorPayload(stopError).error} Best-effort renderer trace cleanup also failed: ${errorPayload(cleanupError).error}`, + ); + } + } +} + +async function runTraceTransition(transition: () => Promise): Promise { + if (traceTransitionInProgress) { + throw new Error('Another renderer trace transition is already in progress.'); + } + + traceTransitionInProgress = true; + try { + return await transition(); + } finally { + traceTransitionInProgress = false; + } +} + +export function decorateTraceResult( + result: Record, + captureTarget: Record, +): Record { + const traces = readRecordedTraces(result['traces']); + const receivedTraceCount = Array.isArray(result['traces']) ? result['traces'].length : 0; + const runtimeDroppedTraceCount = + typeof result['droppedTraceEventCount'] === 'number' && + Number.isSafeInteger(result['droppedTraceEventCount']) && + result['droppedTraceEventCount'] >= 0 + ? Math.max(0, result['droppedTraceEventCount']) + : 0; + const localDroppedTraceCount = Math.max(0, receivedTraceCount - traces.length); + const initialDroppedTraceEventCount = saturatingAdd(runtimeDroppedTraceCount, localDroppedTraceCount); + const boundedCaptureTarget: Record = {}; + for (const key of TRACE_CAPTURE_TARGET_STRING_KEYS) { + const value = captureTarget[key]; + if (typeof value === 'string') { + boundedCaptureTarget[key] = truncateStringForJson(value, MAX_TRACE_HTTP_STRING_BYTES); + } + } + if (typeof captureTarget['port'] === 'number' && Number.isFinite(captureTarget['port'])) { + boundedCaptureTarget['port'] = captureTarget['port']; + } + const boundedContextId = + typeof result['contextId'] === 'string' + ? truncateStringForJson(result['contextId'], MAX_TRACE_HTTP_STRING_BYTES) + : undefined; + const boundedCompletedContextId = + typeof result['completedContextId'] === 'string' + ? truncateStringForJson(result['completedContextId'], MAX_TRACE_HTTP_STRING_BYTES) + : undefined; + const boundedCompletionError = + typeof result['completionError'] === 'string' + ? truncateStringForJson(result['completionError'], MAX_TRACE_HTTP_STRING_BYTES) + : undefined; + + const buildResult = (includedTraceCount: number): Record => { + const includedTraces = traces.slice(0, includedTraceCount); + const droppedTraceEventCount = saturatingAdd(initialDroppedTraceEventCount, traces.length - includedTraceCount); + const perfettoMetadata = buildPerfettoCaptureMetadata(boundedCaptureTarget, droppedTraceEventCount); + return { + recording: result['recording'] === true, + contextId: boundedContextId, + completedRecordingAvailable: result['completedRecordingAvailable'] === true, + completedContextId: boundedCompletedContextId, + completionError: boundedCompletionError, + rendererTracingEnabled: result['rendererTracingEnabled'] === true, + tracingSupported: result['tracingSupported'] === true, + startedAtEpochMs: typeof result['startedAtEpochMs'] === 'number' ? result['startedAtEpochMs'] : undefined, + elapsedMs: typeof result['elapsedMs'] === 'number' ? result['elapsedMs'] : undefined, + timedOut: result['timedOut'] === true, + traces: includedTraces, + captureScope: PROCESS_WIDE_CAPTURE_SCOPE, + captureTarget: boundedCaptureTarget, + traceCount: includedTraces.length, + droppedTraceEventCount, + traceEventLimitReached: droppedTraceEventCount > 0, + summary: summarizeTraces(includedTraces), + perfettoMetadata, + }; + }; + + let minimumTraceCount = 0; + let maximumTraceCount = traces.length; + let boundedResult = buildResult(0); + if (Buffer.byteLength(JSON.stringify(boundedResult), 'utf8') > MAX_TRACE_HTTP_RESPONSE_BYTES) { + throw new Error('Valdi performance trace response metadata exceeds the HTTP size limit.'); + } + while (minimumTraceCount <= maximumTraceCount) { + const candidateTraceCount = Math.floor((minimumTraceCount + maximumTraceCount) / 2); + const candidate = buildResult(candidateTraceCount); + if (Buffer.byteLength(JSON.stringify(candidate), 'utf8') <= MAX_TRACE_HTTP_RESPONSE_BYTES) { + boundedResult = candidate; + minimumTraceCount = candidateTraceCount + 1; + } else { + maximumTraceCount = candidateTraceCount - 1; + } + } + return boundedResult; +} + +function saturatingAdd(left: number, right: number): number { + return left >= Number.MAX_SAFE_INTEGER - right ? Number.MAX_SAFE_INTEGER : left + right; +} + +export function readRecordedTraces(value: unknown): RecordedTrace[] { + if (!Array.isArray(value)) return []; + const values = value as unknown[]; + const traces: RecordedTrace[] = []; + const inputCount = Math.min(values.length, MAX_TRACE_EVENT_COUNT); + for (let index = 0; index < inputCount; index++) { + const item = values[index]; + if (item === null || typeof item !== 'object' || Array.isArray(item)) continue; + const candidate = item as Record; + const trace = candidate['trace']; + const startMicros = candidate['startMicros']; + const endMicros = candidate['endMicros']; + const threadId = candidate['threadId']; + if ( + typeof trace !== 'string' || + trace.length === 0 || + Buffer.byteLength(trace, 'utf8') > MAX_TRACE_NAME_BYTES || + typeof startMicros !== 'number' || + !Number.isSafeInteger(startMicros) || + startMicros < 0 || + typeof endMicros !== 'number' || + !Number.isSafeInteger(endMicros) || + endMicros < startMicros || + typeof threadId !== 'number' || + !Number.isSafeInteger(threadId) || + threadId < 0 + ) { + continue; + } + const recordedTrace: RecordedTrace = { + trace, + startMicros, + endMicros, + threadId, + }; + traces.push(recordedTrace); + } + return traces; +} + +export function summarizeTraces(traces: readonly RecordedTrace[]): RendererTraceSummary { + let durationTraceCount = 0; + let instantTraceCount = 0; + const componentDurations = new Map(); + const viewModelTriggers = new Map(); + + for (const trace of traces) { + if (isRendererViewModelChangeTrace(trace.trace)) { + instantTraceCount += 1; + } else { + durationTraceCount += 1; + } + + const durationMicros = Math.max(0, trace.endMicros - trace.startMicros); + const renderMatch = trace.trace.match(/(?:^|\.)Renderer\.onRender\.([^.]+)$/); + if (renderMatch?.[1]) { + const componentName = renderMatch[1]; + const componentSummary = componentDurations.get(componentName) ?? { count: 0, durationMicros: 0 }; + componentSummary.count += 1; + componentSummary.durationMicros += durationMicros; + componentDurations.set(componentName, componentSummary); + } + + const triggerMatch = trace.trace.match(/(?:^|\.)Renderer\.viewModelChange\.([^.]+)\.(.+)$/); + if (triggerMatch?.[1] && triggerMatch[2]) { + const trigger = `${triggerMatch[1]}.${triggerMatch[2]}`; + viewModelTriggers.set(trigger, (viewModelTriggers.get(trigger) ?? 0) + 1); + } + } + + return { + captureScope: PROCESS_WIDE_CAPTURE_SCOPE, + traceCount: traces.length, + durationTraceCount, + instantTraceCount, + topComponents: Array.from(componentDurations.entries()) + .map(([name, value]) => ({ + name, + count: value.count, + durationMs: value.durationMicros / 1000, + })) + .sort((left, right) => right.durationMs - left.durationMs) + .slice(0, 12), + topViewModelTriggers: Array.from(viewModelTriggers.entries()) + .map(([name, count]) => ({ name, count })) + .sort((left, right) => right.count - left.count) + .slice(0, 12), + }; +} + +export function isRendererViewModelChangeTrace(traceName: string): boolean { + return /(?:^|\.)Renderer\.viewModelChange\.[^.]+\..+$/.test(traceName); +} + +export function buildPerfettoTracePayload( + traces: readonly RecordedTrace[], + captureTarget: Record, + droppedTraceEventCount: number, +): PerfettoTracePayload { + const minStartMicros = traces.reduce( + (minimum, trace) => Math.min(minimum, trace.startMicros), + traces[0]?.startMicros ?? 0, + ); + const threadIds = Array.from(new Set(traces.map(trace => trace.threadId))) + .sort((left, right) => left - right) + .slice(0, MAX_TRACE_THREAD_METADATA_COUNT); + const traceEvents: PerfettoTraceEvent[] = [ + { + name: 'process_name', + ph: 'M', + pid: PERFETTO_PROCESS_ID, + args: { name: PERFETTO_PROCESS_NAME }, + }, + ]; + + for (const threadId of threadIds) { + traceEvents.push({ + name: 'thread_name', + ph: 'M', + pid: PERFETTO_PROCESS_ID, + tid: threadId, + args: { name: `Valdi thread ${threadId}` }, + }); + } + + for (const trace of traces) { + const isInstant = isRendererViewModelChangeTrace(trace.trace); + const event: PerfettoTraceEvent = { + name: trace.trace, + cat: PERFETTO_TRACE_CATEGORY, + ph: isInstant ? 'i' : 'X', + pid: PERFETTO_PROCESS_ID, + tid: trace.threadId, + ts: trace.startMicros - minStartMicros, + }; + if (isInstant) { + event.s = 't'; + } else { + event.dur = Math.max(0, trace.endMicros - trace.startMicros); + } + traceEvents.push(event); + } + + return { + displayTimeUnit: 'ms', + metadata: buildPerfettoCaptureMetadata(captureTarget, droppedTraceEventCount), + traceEvents, + }; +} + +function buildPerfettoCaptureMetadata( + captureTarget: Record, + droppedTraceEventCount: number, +): PerfettoCaptureMetadata { + return { + captureScope: PROCESS_WIDE_CAPTURE_SCOPE, + captureTargetContextId: captureTarget['contextId'], + captureTargetName: captureTarget['name'], + droppedTraceEventCount, + }; +} + async function dispatchInput( request: IncomingMessage, searchParams: URLSearchParams, @@ -2179,6 +2750,26 @@ async function handleApi(request: IncomingMessage, response: ServerResponse, url return; } + if (url.pathname === '/api/performance/trace/status') { + sendTraceJson(response, 200, await inspectPerformanceTraceStatus(request, url.searchParams)); + return; + } + + if (url.pathname === '/api/performance/trace/start') { + sendTraceJson(response, 200, await startPerformanceTrace(request, url.searchParams)); + return; + } + + if (url.pathname === '/api/performance/trace/stop') { + sendTraceJson(response, 200, await stopPerformanceTrace(request, url.searchParams)); + return; + } + + if (url.pathname === '/api/performance/trace/capture') { + sendTraceJson(response, 200, await capturePerformanceTrace(request, url.searchParams)); + return; + } + if (url.pathname === '/api/performance/profile/status') { sendJson(response, 200, profileStatusPayload()); return; @@ -2211,7 +2802,13 @@ async function handleApi(request: IncomingMessage, response: ServerResponse, url sendJson(response, 404, { error: `Unknown API route ${url.pathname}` }); } catch (error) { - sendJson(response, error instanceof ApiRequestError ? error.statusCode : 500, clientErrorPayload(error)); + const status = error instanceof ApiRequestError ? error.statusCode : 500; + const payload = clientErrorPayload(error); + if (url.pathname.startsWith('/api/performance/trace/')) { + sendTraceJson(response, status, payload); + } else { + sendJson(response, status, payload); + } } } diff --git a/npm_modules/cli/src/utils/daemonClient.spec.ts b/npm_modules/cli/src/utils/daemonClient.spec.ts index 93b934d81..0e45cf2ce 100644 --- a/npm_modules/cli/src/utils/daemonClient.spec.ts +++ b/npm_modules/cli/src/utils/daemonClient.spec.ts @@ -1,7 +1,13 @@ import 'jasmine'; import { EventEmitter } from 'node:events'; import type { Socket } from 'node:net'; -import { DaemonConnection } from './daemonClient'; +import { + DaemonConnection, + DaemonMsgType, + MAX_DAEMON_INNER_PAYLOAD_BYTES, + MAX_DAEMON_PACKET_PAYLOAD_BYTES, + MAX_DAEMON_TRACE_PAYLOAD_BYTES, +} from './daemonClient'; const TEST_MAGIC = Buffer.from([0x33, 0xc6, 0x00, 0x01]); @@ -66,7 +72,7 @@ class CustomResponseSocket extends EventEmitter { forward_client_payload: { client_id: 1, payload_string: JSON.stringify({ - type: -1000, + type: DaemonMsgType.CUSTOM_RESPONSE, requestId: this.request['requestId'], body: { handled: true, data: { contractVersion: 1 } }, }), @@ -86,6 +92,110 @@ class CustomResponseSocket extends EventEmitter { } } +// net.Socket uses EventEmitter semantics, which this protocol test mirrors. +// eslint-disable-next-line unicorn/prefer-event-target +class TraceResponseSocket extends EventEmitter { + readonly remotePort = 13_591; + readonly messageTypes: number[] = []; + readonly messageBodies: Array> = []; + + constructor( + private readonly makeResponse?: ( + messageType: number, + requestBody: Record, + ) => Record, + ) { + super(); + } + + write(data: Buffer, callback?: (error?: Error) => void): boolean { + const packet = JSON.parse(data.subarray(8).toString('utf8')) as Record; + const event = packet['event'] as Record | undefined; + const payloadFromClient = event?.['payload_from_client'] as Record | undefined; + if (payloadFromClient) { + const request = JSON.parse(String(payloadFromClient['payload_string'])) as Record; + const messageType = Number(request['type']); + const requestBody = request['body'] as Record; + this.messageTypes.push(messageType); + this.messageBodies.push(requestBody); + const recording = messageType === DaemonMsgType.PERFORMANCE_TRACE_START_REQUEST; + const defaultBody: Record = { + recording, + contextId: recording ? requestBody['contextId'] : undefined, + completedRecordingAvailable: false, + rendererTracingEnabled: recording, + tracingSupported: true, + }; + if (messageType === DaemonMsgType.PERFORMANCE_TRACE_STOP_REQUEST) { + defaultBody['contextId'] = requestBody['contextId']; + defaultBody['traces'] = []; + defaultBody['traceEventCount'] = 0; + defaultBody['droppedTraceEventCount'] = 0; + defaultBody['timedOut'] = false; + } + const innerResponse = this.makeResponse?.(messageType, requestBody) ?? { + type: -messageType, + body: defaultBody, + }; + const response = { + request: { + forward_client_payload: { + client_id: 1, + payload_string: JSON.stringify({ + requestId: request['requestId'], + ...innerResponse, + }), + }, + request_id: `device-response-${this.messageTypes.length}`, + }, + }; + queueMicrotask(() => this.emit('data', encodeTestPacket(response))); + } + callback?.(); + return true; + } + + destroy(): this { + this.emit('close'); + return this; + } +} + +// net.Socket uses EventEmitter semantics, which this protocol test mirrors. +// eslint-disable-next-line unicorn/prefer-event-target +class PassiveSocket extends EventEmitter { + readonly remotePort = 13_591; + destroyedError: Error | undefined; + + write(_data: Buffer, callback?: (error?: Error) => void): boolean { + callback?.(); + return true; + } + + destroy(error?: Error): this { + this.destroyedError = error; + this.emit('close'); + return this; + } +} + +function makeTraceStopResponse(trace: Record): (messageType: number) => Record { + return messageType => ({ + type: -messageType, + body: { + recording: false, + contextId: 'root', + completedRecordingAvailable: false, + rendererTracingEnabled: false, + tracingSupported: true, + traces: [trace], + traceEventCount: 1, + droppedTraceEventCount: 0, + timedOut: false, + }, + }); +} + describe('DaemonConnection', () => { it('surfaces runtime error responses from debugger requests', async () => { const socket = new ErrorResponseSocket(); @@ -119,4 +229,175 @@ describe('DaemonConnection', () => { connection.close(); } }); + + it('routes renderer trace status, start, and stop through the runtime protocol', async () => { + const socket = new TraceResponseSocket(); + const connection = new DaemonConnection(socket as unknown as Socket); + + try { + const status = await connection.performanceTraceStatus('1', { contextId: 'root' }, 1000); + const start = await connection.performanceTraceStart('1', { contextId: 'root', rendererTracing: true }, 1000); + const stop = await connection.performanceTraceStop('1', { contextId: 'root' }, 1000); + + expect(socket.messageTypes).toEqual([ + DaemonMsgType.PERFORMANCE_TRACE_STATUS_REQUEST, + DaemonMsgType.PERFORMANCE_TRACE_START_REQUEST, + DaemonMsgType.PERFORMANCE_TRACE_STOP_REQUEST, + ]); + expect(socket.messageBodies).toEqual([ + { contextId: 'root' }, + { contextId: 'root', rendererTracing: true }, + { contextId: 'root' }, + ]); + expect(status['recording']).toBeFalse(); + expect(start['recording']).toBeTrue(); + expect(stop['recording']).toBeFalse(); + expect(stop['contextId']).toBe('root'); + expect(stop.traces).toEqual([]); + } finally { + connection.close(); + } + }); + + it('rejects a trace response with the wrong discriminator', async () => { + const socket = new TraceResponseSocket(() => ({ + type: DaemonMsgType.PERFORMANCE_TRACE_STOP_RESPONSE, + body: {}, + })); + const connection = new DaemonConnection(socket as unknown as Socket); + + try { + await expectAsync(connection.performanceTraceStatus('1', { contextId: 'root' }, 1000)).toBeRejectedWithError( + /expected -6/, + ); + } finally { + connection.close(); + } + }); + + it('rejects a trace response with a malformed body schema', async () => { + const socket = new TraceResponseSocket(messageType => ({ + type: -messageType, + body: { recording: 'yes' }, + })); + const connection = new DaemonConnection(socket as unknown as Socket); + + try { + await expectAsync(connection.performanceTraceStatus('1', { contextId: 'root' }, 1000)).toBeRejectedWithError( + /invalid recording/, + ); + } finally { + connection.close(); + } + }); + + it('enforces the renderer trace name and timestamp contract', async () => { + const invalidTraces = [ + { trace: '', startMicros: 1, endMicros: 2, threadId: 1 }, + { trace: 'é'.repeat(1025), startMicros: 1, endMicros: 2, threadId: 1 }, + { trace: 'backwards', startMicros: 2, endMicros: 1, threadId: 1 }, + { trace: 'unsafe', startMicros: 1, endMicros: 2, threadId: Number.MAX_SAFE_INTEGER + 1 }, + ]; + + for (const trace of invalidTraces) { + const socket = new TraceResponseSocket(makeTraceStopResponse(trace)); + const connection = new DaemonConnection(socket as unknown as Socket); + try { + await expectAsync(connection.performanceTraceStop('1', { contextId: 'root' }, 1000)).toBeRejectedWithError( + /malformed trace event/, + ); + } finally { + connection.close(); + } + } + + const validSocket = new TraceResponseSocket( + makeTraceStopResponse({ trace: 'é'.repeat(1024), startMicros: 1, endMicros: 2, threadId: 1 }), + ); + const validConnection = new DaemonConnection(validSocket as unknown as Socket); + try { + const result = await validConnection.performanceTraceStop('1', { contextId: 'root' }, 1000); + expect(result.traces.length).toBe(1); + } finally { + validConnection.close(); + } + }); + + it('rejects oversized trace context and completion-error metadata', async () => { + const socket = new TraceResponseSocket(messageType => ({ + type: -messageType, + body: { + recording: false, + contextId: 'x'.repeat(4097), + completedRecordingAvailable: false, + completionError: 'x'.repeat(64 * 1024 + 1), + rendererTracingEnabled: false, + tracingSupported: true, + }, + })); + const connection = new DaemonConnection(socket as unknown as Socket); + + try { + await expectAsync(connection.performanceTraceStatus('1', { contextId: 'root' }, 1000)).toBeRejectedWithError( + /invalid contextId/, + ); + } finally { + connection.close(); + } + }); + + it('accepts a valid heap response larger than the trace-specific payload limit', async () => { + const heapDumpJSON = 'x'.repeat(MAX_DAEMON_TRACE_PAYLOAD_BYTES + 1024); + const socket = new TraceResponseSocket(messageType => ({ + type: -messageType, + body: { memoryUsageBytes: heapDumpJSON.length, heapDumpJSON }, + })); + const connection = new DaemonConnection(socket as unknown as Socket); + + try { + const result = (await connection.dumpHeap('1', false)) as Record; + expect((result['heapDumpJSON'] as string).length).toBe(heapDumpJSON.length); + } finally { + connection.close(); + } + }); + + it('rejects a trace response larger than the trace-specific payload limit', async () => { + const socket = new TraceResponseSocket(messageType => ({ + type: -messageType, + body: { + recording: false, + completedRecordingAvailable: false, + rendererTracingEnabled: false, + tracingSupported: true, + padding: 'x'.repeat(MAX_DAEMON_TRACE_PAYLOAD_BYTES), + }, + })); + const connection = new DaemonConnection(socket as unknown as Socket); + + try { + await expectAsync(connection.performanceTraceStatus('1', { contextId: 'root' }, 1000)).toBeRejectedWithError( + /performance trace payload exceeds/, + ); + } finally { + connection.close(); + } + }); + + it('rejects an oversized outer packet from its header before buffering its payload', () => { + const socket = new PassiveSocket(); + const connection = new DaemonConnection(socket as unknown as Socket); + const header = Buffer.alloc(8); + TEST_MAGIC.copy(header, 0); + header.writeUInt32LE(MAX_DAEMON_PACKET_PAYLOAD_BYTES + 1, 4); + + socket.emit('data', header); + + expect(socket.destroyedError?.message).toContain('payload exceeds'); + connection.close(); + }); + + it('keeps the generic inner payload limit larger than the trace-specific limit', () => { + expect(MAX_DAEMON_INNER_PAYLOAD_BYTES).toBeGreaterThan(MAX_DAEMON_TRACE_PAYLOAD_BYTES); + }); }); diff --git a/npm_modules/cli/src/utils/daemonClient.ts b/npm_modules/cli/src/utils/daemonClient.ts index 83fa04187..8f00b88be 100644 --- a/npm_modules/cli/src/utils/daemonClient.ts +++ b/npm_modules/cli/src/utils/daemonClient.ts @@ -51,6 +51,12 @@ export const enum DaemonMsgType { TAKE_ELEMENT_SNAPSHOT_RESPONSE = -4, DUMP_HEAP_REQUEST = 5, DUMP_HEAP_RESPONSE = -5, + PERFORMANCE_TRACE_STATUS_REQUEST = 6, + PERFORMANCE_TRACE_STATUS_RESPONSE = -6, + PERFORMANCE_TRACE_START_REQUEST = 7, + PERFORMANCE_TRACE_START_RESPONSE = -7, + PERFORMANCE_TRACE_STOP_REQUEST = 8, + PERFORMANCE_TRACE_STOP_RESPONSE = -8, CUSTOM_REQUEST = 1000, CUSTOM_RESPONSE = -1000, } @@ -88,13 +94,56 @@ export interface RemoteContext { rootComponentName: string; } +export interface PerformanceTraceStatusRequestBody extends Record { + contextId?: string; +} + +export interface PerformanceTraceStartRequestBody extends Record { + contextId: string; + rendererTracing?: boolean; +} + +export interface PerformanceTraceStopRequestBody extends Record { + contextId: string; +} + +export interface DaemonPerformanceTraceStatusBody extends Record { + recording: boolean; + contextId?: string; + completedRecordingAvailable: boolean; + completedContextId?: string; + completionError?: string; + rendererTracingEnabled: boolean; + tracingSupported: boolean; + startedAtEpochMs?: number; + elapsedMs?: number; +} + +export interface DaemonPerformanceTraceStopBody extends DaemonPerformanceTraceStatusBody { + traces: Array>; + traceEventCount: number; + droppedTraceEventCount: number; + timedOut: boolean; +} + // ─── Packet encoding ───────────────────────────────────────────────────────── const MAGIC = Buffer.from([0x33, 0xc6, 0x00, 0x01]); const HEADER_SIZE = 8; // 4 magic + 4 uint32LE length +// Heap dumps and element snapshots legitimately exceed trace-sized payloads. Keep generic +// framing bounded while applying the tighter trace limit once the inner request is identified. +export const MAX_DAEMON_INNER_PAYLOAD_BYTES = 64 * 1024 * 1024; +export const MAX_DAEMON_PACKET_PAYLOAD_BYTES = 128 * 1024 * 1024; +export const MAX_DAEMON_TRACE_PAYLOAD_BYTES = 4 * 1024 * 1024; +const MAX_DAEMON_BUFFERED_BYTES = HEADER_SIZE + MAX_DAEMON_PACKET_PAYLOAD_BYTES; function encodePacket(json: object): Buffer { - const payload = Buffer.from(JSON.stringify(json), 'utf8'); + const serialized = JSON.stringify(json); + const payloadLength = Buffer.byteLength(serialized, 'utf8'); + if (payloadLength > MAX_DAEMON_PACKET_PAYLOAD_BYTES) { + throw new Error(`ValdiPacket payload exceeds the ${MAX_DAEMON_PACKET_PAYLOAD_BYTES}-byte limit.`); + } + const payload = Buffer.from(serialized, 'utf8'); const header = Buffer.alloc(8); MAGIC.copy(header, 0); header.writeUInt32LE(payload.length, 4); @@ -114,15 +163,139 @@ interface PendingRequest { reject: (err: Error) => void; } +interface PendingPayloadRequest extends PendingRequest { + maxPayloadBytes: number; +} + +const MAX_DAEMON_TRACE_EVENT_COUNT = 10_000; +const MAX_DAEMON_TRACE_NAME_BYTES = 2048; +const MAX_DAEMON_TRACE_CONTEXT_ID_BYTES = 4096; +const MAX_DAEMON_TRACE_ERROR_BYTES = 64 * 1024; + +function isRecord(value: unknown): value is Record { + return value !== null && typeof value === 'object' && !Array.isArray(value); +} + +function isPerformanceTraceMessageType(value: unknown): boolean { + return ( + value === DaemonMsgType.PERFORMANCE_TRACE_STATUS_REQUEST || + value === DaemonMsgType.PERFORMANCE_TRACE_STATUS_RESPONSE || + value === DaemonMsgType.PERFORMANCE_TRACE_START_REQUEST || + value === DaemonMsgType.PERFORMANCE_TRACE_START_RESPONSE || + value === DaemonMsgType.PERFORMANCE_TRACE_STOP_REQUEST || + value === DaemonMsgType.PERFORMANCE_TRACE_STOP_RESPONSE + ); +} + +function isPerformanceTraceRequestType(value: DaemonMsgType): boolean { + return ( + value === DaemonMsgType.PERFORMANCE_TRACE_STATUS_REQUEST || + value === DaemonMsgType.PERFORMANCE_TRACE_START_REQUEST || + value === DaemonMsgType.PERFORMANCE_TRACE_STOP_REQUEST + ); +} + +function assertOptionalFiniteNumber(body: Record, key: string): void { + const value = body[key]; + if (value !== undefined && (typeof value !== 'number' || !Number.isFinite(value))) { + throw new TypeError(`Valdi runtime trace response has an invalid ${key}.`); + } +} + +function assertOptionalBoundedString( + body: Record, + key: string, + maximumBytes: number, + allowEmpty: boolean, +): void { + const value = body[key]; + if ( + value !== undefined && + (typeof value !== 'string' || + (!allowEmpty && value.length === 0) || + Buffer.byteLength(value, 'utf8') > maximumBytes) + ) { + throw new TypeError(`Valdi runtime trace response has an invalid ${key}.`); + } +} + +function validatePerformanceTraceStatusBody(value: unknown): DaemonPerformanceTraceStatusBody { + if (!isRecord(value)) { + throw new TypeError('Valdi runtime trace response body must be an object.'); + } + for (const key of ['recording', 'completedRecordingAvailable', 'rendererTracingEnabled', 'tracingSupported']) { + if (typeof value[key] !== 'boolean') { + throw new TypeError(`Valdi runtime trace response has an invalid ${key}.`); + } + } + assertOptionalBoundedString(value, 'contextId', MAX_DAEMON_TRACE_CONTEXT_ID_BYTES, false); + assertOptionalBoundedString(value, 'completedContextId', MAX_DAEMON_TRACE_CONTEXT_ID_BYTES, false); + assertOptionalBoundedString(value, 'completionError', MAX_DAEMON_TRACE_ERROR_BYTES, true); + assertOptionalFiniteNumber(value, 'startedAtEpochMs'); + assertOptionalFiniteNumber(value, 'elapsedMs'); + if (value['recording'] && (typeof value['contextId'] !== 'string' || value['contextId'].length === 0)) { + throw new Error('Valdi runtime trace response is recording without a contextId.'); + } + if ( + value['completedRecordingAvailable'] && + (typeof value['completedContextId'] !== 'string' || value['completedContextId'].length === 0) + ) { + throw new Error('Valdi runtime trace response has a completed recording without a completedContextId.'); + } + return value as unknown as DaemonPerformanceTraceStatusBody; +} + +function validatePerformanceTraceStopBody(value: unknown): DaemonPerformanceTraceStopBody { + const status = validatePerformanceTraceStatusBody(value); + const body = status as unknown as Record; + const traces = body['traces']; + if (!Array.isArray(traces) || traces.length > MAX_DAEMON_TRACE_EVENT_COUNT) { + throw new TypeError('Valdi runtime trace stop response has an invalid traces array.'); + } + for (const trace of traces) { + if ( + !isRecord(trace) || + typeof trace['trace'] !== 'string' || + trace['trace'].length === 0 || + Buffer.byteLength(trace['trace'], 'utf8') > MAX_DAEMON_TRACE_NAME_BYTES || + typeof trace['startMicros'] !== 'number' || + !Number.isSafeInteger(trace['startMicros']) || + trace['startMicros'] < 0 || + typeof trace['endMicros'] !== 'number' || + !Number.isSafeInteger(trace['endMicros']) || + trace['endMicros'] < trace['startMicros'] || + typeof trace['threadId'] !== 'number' || + !Number.isSafeInteger(trace['threadId']) || + trace['threadId'] < 0 + ) { + throw new TypeError('Valdi runtime trace stop response contains a malformed trace event.'); + } + } + if ( + typeof body['traceEventCount'] !== 'number' || + !Number.isSafeInteger(body['traceEventCount']) || + body['traceEventCount'] < 0 || + body['traceEventCount'] !== traces.length || + typeof body['droppedTraceEventCount'] !== 'number' || + !Number.isSafeInteger(body['droppedTraceEventCount']) || + body['droppedTraceEventCount'] < 0 || + typeof body['timedOut'] !== 'boolean' + ) { + throw new TypeError('Valdi runtime trace stop response has invalid completion metadata.'); + } + if (typeof body['contextId'] !== 'string' || body['contextId'].length === 0) { + throw new TypeError('Valdi runtime trace stop response has an invalid contextId.'); + } + return value as DaemonPerformanceTraceStopBody; +} + export class DaemonConnection { private socket: net.Socket; private recvBuf: Buffer = Buffer.alloc(0); - private recvChunks: Buffer[] = []; - private recvLen = 0; private reqCounter = 0; private msgCounter = 0; private pendingRequests = new Map(); - private payloadListeners = new Map(); + private payloadListeners = new Map(); // Resolved when the device sends its initial configure request (session ready) private configureReady: PendingRequest | null = null; // Saved from the device's configure handshake @@ -155,20 +328,18 @@ export class DaemonConnection { } private onData(chunk: Buffer): void { - this.recvChunks.push(chunk); - this.recvLen += chunk.length; + const bufferedLength = this.recvBuf.length + chunk.length; + if (bufferedLength > MAX_DAEMON_BUFFERED_BYTES) { + this.failProtocol(`ValdiPacket buffered data exceeds the ${MAX_DAEMON_BUFFERED_BYTES}-byte limit.`); + return; + } + this.recvBuf = this.recvBuf.length === 0 ? chunk : Buffer.concat([this.recvBuf, chunk], bufferedLength); this.drainBuffer(); } private drainBuffer(): void { for (;;) { - if (this.recvLen < HEADER_SIZE) break; - - // Materialise the flat buffer only when we actually have enough data to inspect. - if (this.recvBuf.length < this.recvLen) { - this.recvBuf = Buffer.concat(this.recvChunks, this.recvLen); - this.recvChunks = [this.recvBuf]; - } + if (this.recvBuf.length < HEADER_SIZE) break; if ( this.recvBuf[0] !== 0x33 || @@ -176,27 +347,41 @@ export class DaemonConnection { this.recvBuf[2] !== 0x00 || this.recvBuf[3] !== 0x01 ) { - this.socket.destroy(new Error('ValdiPacket: bad magic')); + this.failProtocol('ValdiPacket: bad magic'); break; } const payloadLen = this.recvBuf.readUInt32LE(4); - if (this.recvLen < HEADER_SIZE + payloadLen) break; + if (payloadLen > MAX_DAEMON_PACKET_PAYLOAD_BYTES) { + this.failProtocol(`ValdiPacket payload exceeds the ${MAX_DAEMON_PACKET_PAYLOAD_BYTES}-byte limit.`); + break; + } + if (this.recvBuf.length < HEADER_SIZE + payloadLen) break; const raw = this.recvBuf.subarray(HEADER_SIZE, HEADER_SIZE + payloadLen).toString('utf8'); const consumed = HEADER_SIZE + payloadLen; this.recvBuf = this.recvBuf.subarray(consumed); - this.recvLen -= consumed; - this.recvChunks = this.recvLen > 0 ? [this.recvBuf] : []; try { - this.dispatchMessage(JSON.parse(raw) as Record); + const parsed = JSON.parse(raw) as unknown; + if (parsed === null || typeof parsed !== 'object' || Array.isArray(parsed)) { + throw new Error('ValdiPacket payload must be a JSON object.'); + } + this.dispatchMessage(parsed as Record); } catch { - // ignore malformed packets + this.failProtocol('ValdiPacket payload contains malformed JSON.'); + break; } } } + private failProtocol(message: string): void { + const error = new Error(message); + this.recvBuf = Buffer.alloc(0); + this.rejectAllPending(error); + this.socket.destroy(error); + } + private dispatchMessage(msg: Record): void { if (msg['request']) { // The device sends us incoming requests (configure handshake, and Messages.ts responses @@ -218,15 +403,45 @@ export class DaemonConnection { const fcp = req['forward_client_payload'] as Record | undefined; if (fcp) { try { - const inner = JSON.parse(fcp['payload_string'] as string) as Record; - const msgId = String(inner['requestId']); + const payloadString = fcp['payload_string']; + if (typeof payloadString !== 'string') { + throw new TypeError('Valdi debugger inner payload must be a string.'); + } + const payloadBytes = Buffer.byteLength(payloadString, 'utf8'); + if (payloadBytes > MAX_DAEMON_INNER_PAYLOAD_BYTES) { + this.failProtocol( + `Valdi debugger inner payload exceeds the ${MAX_DAEMON_INNER_PAYLOAD_BYTES}-byte limit.`, + ); + return; + } + const parsed = JSON.parse(payloadString) as unknown; + if (parsed === null || typeof parsed !== 'object' || Array.isArray(parsed)) { + throw new Error('Valdi debugger inner payload must be a JSON object.'); + } + const inner = parsed as Record; + const requestId = inner['requestId']; + if (typeof requestId !== 'string' || requestId.length === 0) { + throw new TypeError('Valdi debugger inner payload must have a requestId.'); + } + const msgId = requestId; const listener = this.payloadListeners.get(msgId); + const payloadLimit = listener?.maxPayloadBytes ?? MAX_DAEMON_INNER_PAYLOAD_BYTES; + if ( + payloadBytes > payloadLimit || + (isPerformanceTraceMessageType(inner['type']) && payloadBytes > MAX_DAEMON_TRACE_PAYLOAD_BYTES) + ) { + this.failProtocol( + `Valdi debugger performance trace payload exceeds the ${MAX_DAEMON_TRACE_PAYLOAD_BYTES}-byte limit.`, + ); + return; + } if (listener) { this.payloadListeners.delete(msgId); listener.resolve(inner); } } catch { - // ignore malformed inner payload + this.failProtocol('Valdi debugger inner payload is malformed.'); + return; } } } @@ -340,6 +555,12 @@ export class DaemonConnection { ): Promise> { const msgId = this.nextMsgId(); const payloadString = JSON.stringify({ type: msgType, requestId: msgId, body }); + const maxPayloadBytes = isPerformanceTraceRequestType(msgType) + ? MAX_DAEMON_TRACE_PAYLOAD_BYTES + : MAX_DAEMON_INNER_PAYLOAD_BYTES; + if (Buffer.byteLength(payloadString, 'utf8') > maxPayloadBytes) { + throw new Error(`Valdi debugger request payload exceeds the ${maxPayloadBytes}-byte limit.`); + } const resultPromise = new Promise>((resolve, reject) => { const timer = setTimeout(() => { @@ -347,6 +568,7 @@ export class DaemonConnection { reject(new Error('Timeout waiting for device response. Is the app running?')); }, timeoutMs); this.payloadListeners.set(msgId, { + maxPayloadBytes, resolve: v => { clearTimeout(timer); resolve(v); @@ -381,6 +603,9 @@ export class DaemonConnection { ); const response = await resultPromise; + if (response['requestId'] !== msgId) { + throw new Error('The Valdi runtime returned a debugger response with a mismatched requestId.'); + } if (response['type'] === DaemonMsgType.ERROR_RESPONSE) { const body = response['body']; const message = @@ -389,6 +614,11 @@ export class DaemonConnection { : undefined; throw new Error(message === undefined ? 'The Valdi runtime rejected the debugger request.' : String(message)); } + if (response['type'] !== -msgType) { + throw new Error( + `The Valdi runtime returned debugger response type ${String(response['type'])}; expected ${-msgType}.`, + ); + } return response; } @@ -418,6 +648,33 @@ export class DaemonConnection { return resp['body']; } + async performanceTraceStatus( + clientId: string, + body: PerformanceTraceStatusRequestBody, + timeoutMs: number, + ): Promise { + const resp = await this.forwardAndWait(clientId, DaemonMsgType.PERFORMANCE_TRACE_STATUS_REQUEST, body, timeoutMs); + return validatePerformanceTraceStatusBody(resp['body']); + } + + async performanceTraceStart( + clientId: string, + body: PerformanceTraceStartRequestBody, + timeoutMs: number, + ): Promise { + const resp = await this.forwardAndWait(clientId, DaemonMsgType.PERFORMANCE_TRACE_START_REQUEST, body, timeoutMs); + return validatePerformanceTraceStatusBody(resp['body']); + } + + async performanceTraceStop( + clientId: string, + body: PerformanceTraceStopRequestBody, + timeoutMs: number, + ): Promise { + const resp = await this.forwardAndWait(clientId, DaemonMsgType.PERFORMANCE_TRACE_STOP_REQUEST, body, timeoutMs); + return validatePerformanceTraceStopBody(resp['body']); + } + close(): void { this.socket.destroy(); } diff --git a/src/valdi_modules/src/valdi/valdi_core/src/Renderer.ts b/src/valdi_modules/src/valdi/valdi_core/src/Renderer.ts index 347ffce8e..ac848eeea 100644 --- a/src/valdi_modules/src/valdi/valdi_core/src/Renderer.ts +++ b/src/valdi_modules/src/valdi/valdi_core/src/Renderer.ts @@ -28,7 +28,7 @@ import { classNames } from './utils/ClassNames'; import { enumeratePropertyList, PropertyList, propertyListToObject } from './utils/PropertyList'; import { computeUniqueId } from './utils/RenderedVirtualNodeUtils'; import { RendererError } from './utils/RendererError'; -import { trace } from './utils/Trace'; +import { isTracingSupported, trace } from './utils/Trace'; const EMPTY_OBJECT = Object.freeze({}); const EMPTY_ARRAY = Object.freeze([]) as []; @@ -579,6 +579,7 @@ export class Renderer implements IRenderer { private observers: RendererObserver[] = []; private nextAnimationCancelToken: CancelToken = 0; private eventListener: IRendererEventListener | undefined = undefined; + private rendererTracingEnabled = false; private allowedRootElementTypes?: StringSet; /** Moves buffered during render; flushed in top-down order at end to avoid bottom-up attach (ANR). */ @@ -2137,9 +2138,14 @@ export class Renderer implements IRenderer { currentComponent.rendering = true; // this.log('Rendering component ', currentComponent.ctr.name); + const componentToRender = componentInstance; try { - componentInstance.onRender(); + if (this.rendererTracingEnabled) { + trace(`Renderer.onRender.${currentComponent.ctr.name}`, () => componentToRender.onRender()); + } else { + componentToRender.onRender(); + } } catch (err: any) { this.popToVirtualNode(currentComponent.virtualNode); this.onUncaughtError(`Failed to render component '${currentComponent.ctr.name}'`, err); @@ -2225,6 +2231,9 @@ export class Renderer implements IRenderer { if (this.eventListener) { this.eventListener.onComponentViewModelPropertyChange(name); } + if (this.rendererTracingEnabled) { + trace(`Renderer.viewModelChange.${currentComponent.ctr.name}.${name}`, () => {}); + } // this.log('View model property ', name, ' changed for component ', currentComponent.ctr.name); } } @@ -2734,6 +2743,14 @@ export class Renderer implements IRenderer { return this.eventListener; } + setTracingEnabled(enabled: boolean): void { + this.rendererTracingEnabled = enabled && isTracingSupported(); + } + + isTracingEnabled(): boolean { + return this.rendererTracingEnabled; + } + private collectElements(node: VirtualNode, output: IRenderedElement[]) { if (node.element) { output.push(getRenderedElementBridge(this, node.element)); diff --git a/src/valdi_modules/src/valdi/valdi_core/src/RootComponentsManager.ts b/src/valdi_modules/src/valdi/valdi_core/src/RootComponentsManager.ts index fc2ef8cdb..d7c2fd13d 100644 --- a/src/valdi_modules/src/valdi/valdi_core/src/RootComponentsManager.ts +++ b/src/valdi_modules/src/valdi/valdi_core/src/RootComponentsManager.ts @@ -22,6 +22,8 @@ import { import { DebugLevel, SubmitDebugMessageFunc } from './debugging/DebugMessage'; import { DaemonClientMessageType, Messages, RemoteValdiContext } from './debugging/Messages'; import { NativeAppearanceDebugSettings } from './debugging/NativeAppearanceDebugSettings'; +import { PerformanceTraceMessageHandler } from './debugging/PerformanceTraceMessageHandler'; +import { toError } from './utils/ErrorUtils'; import { trace } from './utils/Trace'; interface StashedRootComponentHandle { @@ -53,6 +55,9 @@ export class RootComponentsManager implements IRootComponentsManager, IDaemonCli private reloadedContextIds?: string[]; private nativeAppearanceDebugSettings?: NativeAppearanceDebugSettings; + private readonly performanceTraceMessageHandler = PerformanceTraceMessageHandler.create( + contextId => this.rootComponents[contextId]?.renderer, + ); constructor( readonly rendererFactory: RendererFactory, @@ -66,6 +71,7 @@ export class RootComponentsManager implements IRootComponentsManager, IDaemonCli } stashData(): any { + this.abortPerformanceTrace(); const handles: StashedRootComponentHandle[] = []; for (const contextId in this.rootComponents) { const rootComponentHandle = this.rootComponents[contextId]!; @@ -230,6 +236,8 @@ export class RootComponentsManager implements IRootComponentsManager, IDaemonCli return; } + this.abortPerformanceTraceForContext(contextId); + withLocalNativeRefs(contextId, () => { // Render once empty, so that we can destroy the whole tree handle.renderer.renderRoot(() => {}); @@ -308,6 +316,8 @@ export class RootComponentsManager implements IRootComponentsManager, IDaemonCli return; } + this.abortPerformanceTraceForContext(contextId); + trace(`destroyRoot.${handle.componentPath.symbolName}`, () => { delete this.rootComponents[contextId]; handle.disposeFunction(); @@ -316,6 +326,22 @@ export class RootComponentsManager implements IRootComponentsManager, IDaemonCli }); } + private abortPerformanceTrace(): void { + try { + this.performanceTraceMessageHandler.abortRecording(); + } catch (error) { + console.warn('Failed to stop an active performance trace while disposing root components.', error); + } + } + + private abortPerformanceTraceForContext(contextId: string): void { + try { + this.performanceTraceMessageHandler.abortRecordingForContext(contextId); + } catch (error) { + console.warn(`Failed to stop the active performance trace for context ${contextId}.`, error); + } + } + attributeChanged(contextId: string, nodeId: number, attributeName: string, attributeValue: any): void { const handle = this.rootComponents[contextId]; if (!handle) { @@ -344,7 +370,24 @@ export class RootComponentsManager implements IRootComponentsManager, IDaemonCli } onMessage(message: ReceivedDaemonClientMessage): void { - if (message.message.type === DaemonClientMessageType.LIST_CONTEXTS_REQUEST) { + if (message.message.type === DaemonClientMessageType.PERFORMANCE_TRACE_STATUS_REQUEST) { + const status = this.performanceTraceMessageHandler.getStatus(); + message.respond(requestId => Messages.performanceTraceStatusResponse(requestId, status)); + } else if (message.message.type === DaemonClientMessageType.PERFORMANCE_TRACE_START_REQUEST) { + try { + const status = this.performanceTraceMessageHandler.startRecording(message.message.body); + message.respond(requestId => Messages.performanceTraceStartResponse(requestId, status)); + } catch (error) { + message.respond(requestId => Messages.errorResponse(requestId, toError(error))); + } + } else if (message.message.type === DaemonClientMessageType.PERFORMANCE_TRACE_STOP_REQUEST) { + try { + const result = this.performanceTraceMessageHandler.stopRecording(message.message.body); + message.respond(requestId => Messages.performanceTraceStopResponse(requestId, result)); + } catch (error) { + message.respond(requestId => Messages.errorResponse(requestId, toError(error))); + } + } else if (message.message.type === DaemonClientMessageType.LIST_CONTEXTS_REQUEST) { const contexts: RemoteValdiContext[] = []; for (const treeId in this.rootComponents) { diff --git a/src/valdi_modules/src/valdi/valdi_core/src/ValdiRuntime.d.ts b/src/valdi_modules/src/valdi/valdi_core/src/ValdiRuntime.d.ts index 7c42b7d17..5803f0a8d 100644 --- a/src/valdi_modules/src/valdi/valdi_core/src/ValdiRuntime.d.ts +++ b/src/valdi_modules/src/valdi/valdi_core/src/ValdiRuntime.d.ts @@ -163,6 +163,8 @@ export interface ValdiRuntime extends RuntimeBase { startTraceRecording(): number; stopTraceRecording(id: number): any[]; + /** Optional so valdi_core remains compatible with older native and web runtime implementations. */ + stopTraceRecordingWithStats?(id: number): any[]; submitDebugMessage: SubmitDebugMessageFunc; diff --git a/src/valdi_modules/src/valdi/valdi_core/src/debugging/Messages.ts b/src/valdi_modules/src/valdi/valdi_core/src/debugging/Messages.ts index 0c92977a1..b1ab83640 100644 --- a/src/valdi_modules/src/valdi/valdi_core/src/debugging/Messages.ts +++ b/src/valdi_modules/src/valdi/valdi_core/src/debugging/Messages.ts @@ -10,6 +10,12 @@ export const enum DaemonClientMessageType { TAKE_ELEMENT_SNAPSHOT_RESPONSE = -4, DUMP_HEAP_REQUEST = 5, DUMP_HEAP_RESPONSE = -5, + PERFORMANCE_TRACE_STATUS_REQUEST = 6, + PERFORMANCE_TRACE_STATUS_RESPONSE = -6, + PERFORMANCE_TRACE_START_REQUEST = 7, + PERFORMANCE_TRACE_START_RESPONSE = -7, + PERFORMANCE_TRACE_STOP_REQUEST = 8, + PERFORMANCE_TRACE_STOP_RESPONSE = -8, CUSTOM_REQUEST = 1000, CUSTOM_RESPONSE = -1000, } @@ -50,6 +56,45 @@ export interface DumpHeapResponseBody { heapDumpJSON: string; } +export interface PerformanceTraceStatusRequestBody { + contextId?: string; +} + +export interface PerformanceTraceStartRequestBody { + contextId: string; + rendererTracing?: boolean; +} + +export interface PerformanceTraceStopRequestBody { + contextId: string; +} + +export interface PerformanceTraceEvent { + trace: string; + startMicros: number; + endMicros: number; + threadId: number; +} + +export interface PerformanceTraceStatusBody { + recording: boolean; + contextId: string | undefined; + completedRecordingAvailable: boolean; + completedContextId: string | undefined; + completionError: string | undefined; + rendererTracingEnabled: boolean; + tracingSupported: boolean; + startedAtEpochMs: number | undefined; + elapsedMs: number | undefined; +} + +export interface PerformanceTraceStopBody extends PerformanceTraceStatusBody { + traces: PerformanceTraceEvent[]; + traceEventCount: number; + droppedTraceEventCount: number; + timedOut: boolean; +} + export interface CustomMessageRequestBody { identifier: string; data: any; @@ -60,6 +105,141 @@ export interface CustomMessageResponseBody { data: any | undefined; } +export const MAX_PERFORMANCE_TRACE_MESSAGE_BYTES = 4 * 1024 * 1024; +export const MAX_PERFORMANCE_TRACE_CONTEXT_ID_BYTES = 4096; +export const MAX_PERFORMANCE_TRACE_ERROR_BYTES = 64 * 1024; +const MAX_DEBUGGER_ERROR_STACK_BYTES = 128 * 1024; + +function utf8ByteLength(value: string, maximumBytes: number): number { + let byteLength = 0; + for (let index = 0; index < value.length; index++) { + const codeUnit = value.charCodeAt(index); + if (codeUnit <= 0x7f) { + byteLength += 1; + } else if (codeUnit <= 0x7ff) { + byteLength += 2; + } else if (codeUnit >= 0xd800 && codeUnit <= 0xdbff) { + const nextCodeUnit = value.charCodeAt(index + 1); + if (nextCodeUnit >= 0xdc00 && nextCodeUnit <= 0xdfff) { + byteLength += 4; + index++; + } else { + byteLength += 3; + } + } else { + byteLength += 3; + } + if (byteLength > maximumBytes) return byteLength; + } + return byteLength; +} + +function serializedByteLength(value: unknown, maximumBytes: number): number { + return utf8ByteLength(JSON.stringify(value), maximumBytes); +} + +export function truncateDebuggerString(value: string, maximumSerializedBytes: number): string { + if (serializedByteLength(value, maximumSerializedBytes) <= maximumSerializedBytes) return value; + + const suffix = '…'; + let minimumLength = 0; + let maximumLength = value.length; + let truncated = suffix; + while (minimumLength <= maximumLength) { + const candidateLength = Math.floor((minimumLength + maximumLength) / 2); + const candidate = `${value.slice(0, candidateLength)}${suffix}`; + if (serializedByteLength(candidate, maximumSerializedBytes) <= maximumSerializedBytes) { + truncated = candidate; + minimumLength = candidateLength + 1; + } else { + maximumLength = candidateLength - 1; + } + } + return truncated; +} + +export function isPerformanceTraceContextIdWithinLimit(contextId: string): boolean { + return ( + contextId.length > 0 && + serializedByteLength(contextId, MAX_PERFORMANCE_TRACE_CONTEXT_ID_BYTES) <= MAX_PERFORMANCE_TRACE_CONTEXT_ID_BYTES + ); +} + +export function truncatePerformanceTraceError(error: string): string { + return truncateDebuggerString(error, MAX_PERFORMANCE_TRACE_ERROR_BYTES); +} + +function sanitizeOptionalTraceString(value: string | undefined, maximumSerializedBytes: number): string | undefined { + return value === undefined ? undefined : truncateDebuggerString(value, maximumSerializedBytes); +} + +function sanitizePerformanceTraceStatusBody(body: PerformanceTraceStatusBody): PerformanceTraceStatusBody { + return { + ...body, + contextId: sanitizeOptionalTraceString(body.contextId, MAX_PERFORMANCE_TRACE_CONTEXT_ID_BYTES), + completedContextId: sanitizeOptionalTraceString(body.completedContextId, MAX_PERFORMANCE_TRACE_CONTEXT_ID_BYTES), + completionError: sanitizeOptionalTraceString(body.completionError, MAX_PERFORMANCE_TRACE_ERROR_BYTES), + }; +} + +function saturatingAdd(left: number, right: number): number { + return left >= Number.MAX_SAFE_INTEGER - right ? Number.MAX_SAFE_INTEGER : left + right; +} + +function serializePerformanceTraceMessage( + type: DaemonClientMessageType, + requestId: string, + body: PerformanceTraceStatusBody, +): string { + const serialized = JSON.stringify({ type, requestId, body: sanitizePerformanceTraceStatusBody(body) }); + if (utf8ByteLength(serialized, MAX_PERFORMANCE_TRACE_MESSAGE_BYTES) > MAX_PERFORMANCE_TRACE_MESSAGE_BYTES) { + throw new Error('Valdi performance trace response exceeds the protocol size limit.'); + } + return serialized; +} + +function serializePerformanceTraceStopMessage(requestId: string, body: PerformanceTraceStopBody): string { + const sanitizedStatus = sanitizePerformanceTraceStatusBody(body); + const originalTraces = body.traces; + const originalDroppedTraceEventCount = + Number.isSafeInteger(body.droppedTraceEventCount) && body.droppedTraceEventCount >= 0 + ? body.droppedTraceEventCount + : 0; + const serializeTracePrefix = (traceCount: number): string => { + const omittedTraceCount = originalTraces.length - traceCount; + const boundedBody: PerformanceTraceStopBody = { + ...body, + ...sanitizedStatus, + traces: originalTraces.slice(0, traceCount), + traceEventCount: traceCount, + droppedTraceEventCount: saturatingAdd(originalDroppedTraceEventCount, omittedTraceCount), + }; + return JSON.stringify({ + type: DaemonClientMessageType.PERFORMANCE_TRACE_STOP_RESPONSE, + requestId, + body: boundedBody, + }); + }; + + let minimumTraceCount = 0; + let maximumTraceCount = originalTraces.length; + let serialized = serializeTracePrefix(0); + if (utf8ByteLength(serialized, MAX_PERFORMANCE_TRACE_MESSAGE_BYTES) > MAX_PERFORMANCE_TRACE_MESSAGE_BYTES) { + throw new Error('Valdi performance trace response metadata exceeds the protocol size limit.'); + } + while (minimumTraceCount <= maximumTraceCount) { + const candidateTraceCount = Math.floor((minimumTraceCount + maximumTraceCount) / 2); + const candidate = serializeTracePrefix(candidateTraceCount); + if (utf8ByteLength(candidate, MAX_PERFORMANCE_TRACE_MESSAGE_BYTES) <= MAX_PERFORMANCE_TRACE_MESSAGE_BYTES) { + serialized = candidate; + minimumTraceCount = candidateTraceCount + 1; + } else { + maximumTraceCount = candidateTraceCount - 1; + } + } + return serialized; +} + export type ErrorResponse = DaemonClientMessageBase; export type ListContextsRequest = DaemonClientMessageBase; export type ListContextsResponse = DaemonClientMessageBase< @@ -91,6 +271,31 @@ export type TakeElementSnapshotResponse = DaemonClientMessageBase< string >; +export type PerformanceTraceStatusRequest = DaemonClientMessageBase< + DaemonClientMessageType.PERFORMANCE_TRACE_STATUS_REQUEST, + PerformanceTraceStatusRequestBody +>; +export type PerformanceTraceStatusResponse = DaemonClientMessageBase< + DaemonClientMessageType.PERFORMANCE_TRACE_STATUS_RESPONSE, + PerformanceTraceStatusBody +>; +export type PerformanceTraceStartRequest = DaemonClientMessageBase< + DaemonClientMessageType.PERFORMANCE_TRACE_START_REQUEST, + PerformanceTraceStartRequestBody +>; +export type PerformanceTraceStartResponse = DaemonClientMessageBase< + DaemonClientMessageType.PERFORMANCE_TRACE_START_RESPONSE, + PerformanceTraceStatusBody +>; +export type PerformanceTraceStopRequest = DaemonClientMessageBase< + DaemonClientMessageType.PERFORMANCE_TRACE_STOP_REQUEST, + PerformanceTraceStopRequestBody +>; +export type PerformanceTraceStopResponse = DaemonClientMessageBase< + DaemonClientMessageType.PERFORMANCE_TRACE_STOP_RESPONSE, + PerformanceTraceStopBody +>; + export type CustomMessageRequest = DaemonClientMessageBase< DaemonClientMessageType.CUSTOM_REQUEST, CustomMessageRequestBody @@ -109,6 +314,12 @@ export type DaemonClientMessage = | TakeElementSnapshotResponse | DumpHeapRequest | DumpHeapResponse + | PerformanceTraceStatusRequest + | PerformanceTraceStatusResponse + | PerformanceTraceStartRequest + | PerformanceTraceStartResponse + | PerformanceTraceStopRequest + | PerformanceTraceStopResponse | CustomMessageRequest | CustomMessageResponse | ErrorResponse; @@ -174,6 +385,42 @@ export namespace Messages { }); } + export function performanceTraceStatusRequest(requestId: string, body: PerformanceTraceStatusRequestBody): string { + return JSON.stringify({ + type: DaemonClientMessageType.PERFORMANCE_TRACE_STATUS_REQUEST, + requestId, + body, + }); + } + + export function performanceTraceStatusResponse(requestId: string, body: PerformanceTraceStatusBody): string { + return serializePerformanceTraceMessage(DaemonClientMessageType.PERFORMANCE_TRACE_STATUS_RESPONSE, requestId, body); + } + + export function performanceTraceStartRequest(requestId: string, body: PerformanceTraceStartRequestBody): string { + return JSON.stringify({ + type: DaemonClientMessageType.PERFORMANCE_TRACE_START_REQUEST, + requestId, + body, + }); + } + + export function performanceTraceStartResponse(requestId: string, body: PerformanceTraceStatusBody): string { + return serializePerformanceTraceMessage(DaemonClientMessageType.PERFORMANCE_TRACE_START_RESPONSE, requestId, body); + } + + export function performanceTraceStopRequest(requestId: string, body: PerformanceTraceStopRequestBody): string { + return JSON.stringify({ + type: DaemonClientMessageType.PERFORMANCE_TRACE_STOP_REQUEST, + requestId, + body, + }); + } + + export function performanceTraceStopResponse(requestId: string, body: PerformanceTraceStopBody): string { + return serializePerformanceTraceStopMessage(requestId, body); + } + export function customMessageRequest(requestId: string, body: CustomMessageRequestBody) { return JSON.stringify({ type: DaemonClientMessageType.CUSTOM_REQUEST, @@ -190,7 +437,7 @@ export namespace Messages { }); } - export function errorResponse(requestId: string, error: string | Error) { + export function errorResponse(requestId: string, error: string | Error): string { let message: string; let stack: string | undefined; if (typeof error === 'string') { @@ -201,11 +448,15 @@ export namespace Messages { } const body: ErrorBody = { - message, - stack, + message: truncateDebuggerString(message, MAX_PERFORMANCE_TRACE_ERROR_BYTES), + stack: sanitizeOptionalTraceString(stack, MAX_DEBUGGER_ERROR_STACK_BYTES), }; - return JSON.stringify({ type: DaemonClientMessageType.ERROR_RESPONSE, requestId, body }); + const serialized = JSON.stringify({ type: DaemonClientMessageType.ERROR_RESPONSE, requestId, body }); + if (utf8ByteLength(serialized, MAX_PERFORMANCE_TRACE_MESSAGE_BYTES) > MAX_PERFORMANCE_TRACE_MESSAGE_BYTES) { + throw new Error('Valdi debugger error response exceeds the protocol size limit.'); + } + return serialized; } export function parse(senderClientId: number, jsonBlob: any): DaemonClientMessage { diff --git a/src/valdi_modules/src/valdi/valdi_core/src/debugging/PerformanceTraceMessageHandler.ts b/src/valdi_modules/src/valdi/valdi_core/src/debugging/PerformanceTraceMessageHandler.ts new file mode 100644 index 000000000..1907e33c7 --- /dev/null +++ b/src/valdi_modules/src/valdi/valdi_core/src/debugging/PerformanceTraceMessageHandler.ts @@ -0,0 +1,336 @@ +import { isTracingSupported, startTraceRecording, stopTraceRecordingWithStats } from '../utils/Trace'; +import type { TraceRecordingResult } from '../utils/Trace'; +import type { + PerformanceTraceStartRequestBody, + PerformanceTraceStatusBody, + PerformanceTraceStopBody, + PerformanceTraceStopRequestBody, +} from './Messages'; +import { + isPerformanceTraceContextIdWithinLimit, + MAX_PERFORMANCE_TRACE_CONTEXT_ID_BYTES, + truncatePerformanceTraceError, +} from './Messages'; + +export const PERFORMANCE_TRACE_HANDLER_TIMEOUT_MS = 20_000; +export const PERFORMANCE_TRACE_RESULT_TTL_MS = 60_000; + +export interface PerformanceTraceRenderer { + setTracingEnabled(enabled: boolean): void; + isTracingEnabled(): boolean; +} + +export type PerformanceTraceRendererResolver = (contextId: string) => PerformanceTraceRenderer | undefined; + +export interface PerformanceTraceRuntime { + cancelTimeout(timeoutId: number): void; + isTracingSupported(): boolean; + nowMs(): number; + nowEpochMs(): number; + scheduleTimeout(callback: () => void, timeoutMs: number): number; + startTraceRecording(): number; + stopTraceRecording(recordingId: number): TraceRecordingResult; +} + +const defaultPerformanceTraceRuntime: PerformanceTraceRuntime = { + cancelTimeout: timeoutId => clearTimeout(timeoutId), + isTracingSupported, + nowMs: () => performance.now(), + nowEpochMs: () => Date.now(), + scheduleTimeout: (callback, timeoutMs) => setTimeout(callback, timeoutMs), + startTraceRecording, + stopTraceRecording: stopTraceRecordingWithStats, +}; + +function errorMessage(error: unknown): string { + return truncatePerformanceTraceError(error instanceof Error ? `${error.name}: ${error.message}` : String(error)); +} + +function appendCompletionError(existing: string | undefined, next: string): string { + return truncatePerformanceTraceError(existing ? `${existing} ${next}` : next); +} + +export class PerformanceTraceMessageHandler { + private recordingId: number | undefined; + private recordingStartedAtMs: number | undefined; + private recordingStartedAtEpochMs: number | undefined; + private rendererTracingWasEnabled: boolean | undefined; + private activeContextId: string | undefined; + private activeRenderer: PerformanceTraceRenderer | undefined; + private recordingTimeoutId: number | undefined; + private completedRecording: PerformanceTraceStopBody | undefined; + private completedRecordingExpiryTimeoutId: number | undefined; + private recentlyCompletedRecording: PerformanceTraceStopBody | undefined; + private recentlyCompletedRecordingExpiryTimeoutId: number | undefined; + + static create(getRendererForContextId: PerformanceTraceRendererResolver): PerformanceTraceMessageHandler { + return new PerformanceTraceMessageHandler(getRendererForContextId, defaultPerformanceTraceRuntime); + } + + constructor( + private readonly getRendererForContextId: PerformanceTraceRendererResolver, + private readonly traceRuntime: PerformanceTraceRuntime, + ) {} + + startRecording(body: PerformanceTraceStartRequestBody): PerformanceTraceStatusBody { + if (this.recordingId !== undefined) { + throw new Error('A Valdi performance trace recording is already active.'); + } + if (this.completedRecording !== undefined) { + throw new Error( + `A completed timed-out Valdi performance trace for context ${this.completedRecording.contextId} is waiting to be retrieved.`, + ); + } + const contextId = this.requireContextId(body.contextId); + const rendererTracing = this.readRendererTracing(body.rendererTracing); + const renderer = this.getRendererForContextId(contextId); + if (!renderer) { + throw new Error(`No Valdi renderer found for context ${contextId}.`); + } + + const rendererTracingWasEnabled = renderer.isTracingEnabled(); + const startedAtMs = this.traceRuntime.nowMs(); + const startedAtEpochMs = this.traceRuntime.nowEpochMs(); + try { + renderer.setTracingEnabled(rendererTracing); + const recordingId = this.traceRuntime.startTraceRecording(); + this.clearRecentlyCompletedRecording(); + this.rendererTracingWasEnabled = rendererTracingWasEnabled; + this.recordingId = recordingId; + this.recordingStartedAtMs = startedAtMs; + this.recordingStartedAtEpochMs = startedAtEpochMs; + this.activeContextId = contextId; + this.activeRenderer = renderer; + this.recordingTimeoutId = this.traceRuntime.scheduleTimeout( + () => this.completeTimedOutRecording(recordingId), + PERFORMANCE_TRACE_HANDLER_TIMEOUT_MS, + ); + } catch (error) { + const recordingId = this.recordingId; + if (recordingId !== undefined) { + this.completeActiveRecording(recordingId, false); + } else { + this.clearActiveRecordingState(); + renderer.setTracingEnabled(rendererTracingWasEnabled); + } + throw error; + } + + return this.getStatus(); + } + + stopRecording(body: PerformanceTraceStopRequestBody): PerformanceTraceStopBody { + const requestedContextId = this.requireContextId(body.contextId); + const recordingId = this.recordingId; + if (recordingId !== undefined) { + this.assertContextMatches(requestedContextId, this.activeContextId); + const result = this.completeActiveRecording(recordingId, false); + this.storeRecentlyCompletedRecording(result); + return result; + } + + const completedRecording = this.completedRecording; + if (completedRecording !== undefined) { + this.assertContextMatches(requestedContextId, completedRecording.contextId); + this.clearCompletedRecording(); + const result = { + ...completedRecording, + completedRecordingAvailable: false, + completedContextId: undefined, + }; + this.storeRecentlyCompletedRecording(result); + return result; + } + + const recentlyCompletedRecording = this.recentlyCompletedRecording; + if (recentlyCompletedRecording !== undefined) { + this.assertContextMatches(requestedContextId, recentlyCompletedRecording.contextId); + return recentlyCompletedRecording; + } + + throw new Error('No Valdi performance trace recording is active or waiting to be retrieved.'); + } + + getStatus(): PerformanceTraceStatusBody { + const startedAtMs = this.recordingStartedAtMs; + const recording = this.recordingId !== undefined; + const completedRecording = this.completedRecording; + return { + recording, + contextId: recording ? this.activeContextId : undefined, + completedRecordingAvailable: completedRecording !== undefined, + completedContextId: completedRecording?.contextId, + completionError: completedRecording?.completionError, + rendererTracingEnabled: + this.activeRenderer?.isTracingEnabled() ?? completedRecording?.rendererTracingEnabled ?? false, + tracingSupported: this.traceRuntime.isTracingSupported(), + startedAtEpochMs: recording ? this.recordingStartedAtEpochMs : completedRecording?.startedAtEpochMs, + elapsedMs: + recording && startedAtMs !== undefined + ? this.traceRuntime.nowMs() - startedAtMs + : completedRecording?.elapsedMs, + }; + } + + abortRecording(): void { + const recordingId = this.recordingId; + const result = recordingId === undefined ? undefined : this.completeActiveRecording(recordingId, false); + this.clearCompletedRecording(); + this.clearRecentlyCompletedRecording(); + if (result?.completionError) { + throw new Error(result.completionError); + } + } + + abortRecordingForContext(contextId: string): void { + if ( + this.activeContextId === contextId || + this.completedRecording?.contextId === contextId || + this.recentlyCompletedRecording?.contextId === contextId + ) { + this.abortRecording(); + } + } + + private completeTimedOutRecording(recordingId: number): void { + if (this.recordingId !== recordingId) { + return; + } + this.storeCompletedRecording(this.completeActiveRecording(recordingId, true)); + } + + private completeActiveRecording(recordingId: number, timedOut: boolean): PerformanceTraceStopBody { + const renderer = this.activeRenderer; + const contextId = this.activeContextId; + const rendererTracingWasEnabled = this.rendererTracingWasEnabled; + const startedAtMs = this.recordingStartedAtMs; + const startedAtEpochMs = this.recordingStartedAtEpochMs; + const elapsedMs = startedAtMs === undefined ? undefined : this.traceRuntime.nowMs() - startedAtMs; + let traceResult: TraceRecordingResult = { traces: [], droppedTraceEventCount: 0 }; + let completionError: string | undefined; + let rendererTracingEnabled = false; + + try { + traceResult = this.traceRuntime.stopTraceRecording(recordingId); + } catch (error) { + completionError = truncatePerformanceTraceError( + `Failed to stop Valdi performance trace recording: ${errorMessage(error)}`, + ); + } finally { + this.clearActiveRecordingState(); + if (rendererTracingWasEnabled !== undefined) { + try { + renderer?.setTracingEnabled(rendererTracingWasEnabled); + } catch (error) { + const restoreError = `Failed to restore Renderer tracing: ${errorMessage(error)}`; + completionError = appendCompletionError(completionError, restoreError); + } + } + try { + rendererTracingEnabled = renderer?.isTracingEnabled() ?? false; + } catch (error) { + const statusError = `Failed to read Renderer tracing state: ${errorMessage(error)}`; + completionError = appendCompletionError(completionError, statusError); + } + } + + const traces = traceResult.traces; + + return { + recording: false, + contextId, + completedRecordingAvailable: false, + completedContextId: undefined, + completionError, + rendererTracingEnabled, + tracingSupported: this.traceRuntime.isTracingSupported(), + startedAtEpochMs, + elapsedMs, + traces, + traceEventCount: traces.length, + droppedTraceEventCount: traceResult.droppedTraceEventCount, + timedOut, + }; + } + + private assertContextMatches(requestedContextId: string, activeContextId: string | undefined): void { + if (requestedContextId !== activeContextId) { + throw new Error( + `Valdi performance trace recording belongs to context ${String(activeContextId)}, not ${requestedContextId}.`, + ); + } + } + + private requireContextId(contextId: string): string { + if (typeof contextId !== 'string' || contextId.length === 0) { + throw new Error('A non-empty contextId is required for Valdi performance tracing.'); + } + if (!isPerformanceTraceContextIdWithinLimit(contextId)) { + throw new Error( + `Valdi performance trace contextId exceeds the ${MAX_PERFORMANCE_TRACE_CONTEXT_ID_BYTES}-byte serialized limit.`, + ); + } + return contextId; + } + + private readRendererTracing(rendererTracing: boolean | undefined): boolean { + if (rendererTracing !== undefined && typeof rendererTracing !== 'boolean') { + throw new Error('rendererTracing must be a boolean when provided.'); + } + return rendererTracing !== false; + } + + private clearActiveRecordingState(): void { + const timeoutId = this.recordingTimeoutId; + this.recordingTimeoutId = undefined; + if (timeoutId !== undefined) { + this.traceRuntime.cancelTimeout(timeoutId); + } + this.recordingId = undefined; + this.recordingStartedAtMs = undefined; + this.recordingStartedAtEpochMs = undefined; + this.rendererTracingWasEnabled = undefined; + this.activeContextId = undefined; + this.activeRenderer = undefined; + } + + private storeCompletedRecording(recording: PerformanceTraceStopBody): void { + this.clearCompletedRecording(); + this.completedRecording = recording; + this.completedRecordingExpiryTimeoutId = this.traceRuntime.scheduleTimeout(() => { + if (this.completedRecording === recording) { + this.completedRecording = undefined; + this.completedRecordingExpiryTimeoutId = undefined; + } + }, PERFORMANCE_TRACE_RESULT_TTL_MS); + } + + private clearCompletedRecording(): void { + const timeoutId = this.completedRecordingExpiryTimeoutId; + this.completedRecording = undefined; + this.completedRecordingExpiryTimeoutId = undefined; + if (timeoutId !== undefined) { + this.traceRuntime.cancelTimeout(timeoutId); + } + } + + private storeRecentlyCompletedRecording(recording: PerformanceTraceStopBody): void { + this.clearRecentlyCompletedRecording(); + this.recentlyCompletedRecording = recording; + this.recentlyCompletedRecordingExpiryTimeoutId = this.traceRuntime.scheduleTimeout(() => { + if (this.recentlyCompletedRecording === recording) { + this.recentlyCompletedRecording = undefined; + this.recentlyCompletedRecordingExpiryTimeoutId = undefined; + } + }, PERFORMANCE_TRACE_RESULT_TTL_MS); + } + + private clearRecentlyCompletedRecording(): void { + const timeoutId = this.recentlyCompletedRecordingExpiryTimeoutId; + this.recentlyCompletedRecording = undefined; + this.recentlyCompletedRecordingExpiryTimeoutId = undefined; + if (timeoutId !== undefined) { + this.traceRuntime.cancelTimeout(timeoutId); + } + } +} diff --git a/src/valdi_modules/src/valdi/valdi_core/src/utils/Trace.ts b/src/valdi_modules/src/valdi/valdi_core/src/utils/Trace.ts index 8209b8ac7..9f43782b6 100644 --- a/src/valdi_modules/src/valdi/valdi_core/src/utils/Trace.ts +++ b/src/valdi_modules/src/valdi/valdi_core/src/utils/Trace.ts @@ -9,6 +9,121 @@ export interface RecordedTrace { threadId: number; } +export interface TraceRecordingResult { + traces: RecordedTrace[]; + droppedTraceEventCount: number; +} + +const MAX_RECORDED_TRACE_COUNT = 10_000; +const MAX_TRACE_NAME_BYTES = 2048; + +/** + * Keep the serialized trace array below the daemon's 4 MiB trace-message limit. + * The remaining 1 MiB is reserved for the response envelope and completion metadata. + */ +export const MAX_SERIALIZED_TRACE_EVENTS_BYTES = 3 * 1024 * 1024; + +function utf8ByteLength(value: string, maximumBytes: number): number { + let byteLength = 0; + for (let index = 0; index < value.length; index++) { + const codeUnit = value.charCodeAt(index); + if (codeUnit <= 0x7f) { + byteLength += 1; + } else if (codeUnit <= 0x7ff) { + byteLength += 2; + } else if (codeUnit >= 0xd800 && codeUnit <= 0xdbff) { + const nextCodeUnit = value.charCodeAt(index + 1); + if (nextCodeUnit >= 0xdc00 && nextCodeUnit <= 0xdfff) { + byteLength += 4; + index++; + } else { + byteLength += 3; + } + } else { + byteLength += 3; + } + if (byteLength > maximumBytes) { + return byteLength; + } + } + return byteLength; +} + +function incrementDroppedTraceEventCount(value: number): number { + return value >= Number.MAX_SAFE_INTEGER ? Number.MAX_SAFE_INTEGER : value + 1; +} + +function normalizeNativeDroppedTraceEventCount(value: any): number { + if (typeof value !== 'number' || !Number.isFinite(value) || !Number.isInteger(value) || value < 0) { + return 0; + } + return Math.min(value, Number.MAX_SAFE_INTEGER); +} + +function decodeTraceRecordingResult( + result: any[], + firstTraceIndex: number, + nativeDroppedTraceEventCount: number, +): TraceRecordingResult { + const traces: RecordedTrace[] = []; + let droppedTraceEventCount = nativeDroppedTraceEventCount; + let serializedTraceBytes = 2; // Opening and closing brackets for the trace array. + + for (let index = firstTraceIndex; index < result.length; index += 4) { + if (result.length - index < 4) { + droppedTraceEventCount = incrementDroppedTraceEventCount(droppedTraceEventCount); + break; + } + + const trace = result[index]; + const startMicros = result[index + 1]; + const endMicros = result[index + 2]; + const threadId = result[index + 3]; + if ( + typeof trace !== 'string' || + trace.length === 0 || + utf8ByteLength(trace, MAX_TRACE_NAME_BYTES) > MAX_TRACE_NAME_BYTES || + typeof startMicros !== 'number' || + !Number.isSafeInteger(startMicros) || + startMicros < 0 || + typeof endMicros !== 'number' || + !Number.isSafeInteger(endMicros) || + endMicros < startMicros || + typeof threadId !== 'number' || + !Number.isSafeInteger(threadId) || + threadId < 0 + ) { + droppedTraceEventCount = incrementDroppedTraceEventCount(droppedTraceEventCount); + continue; + } + + const recordedTrace: RecordedTrace = { trace, startMicros, endMicros, threadId }; + const serializedTrace = JSON.stringify(recordedTrace); + const separatorBytes = traces.length === 0 ? 0 : 1; + const serializedEventBytes = utf8ByteLength(serializedTrace, MAX_SERIALIZED_TRACE_EVENTS_BYTES); + if ( + traces.length >= MAX_RECORDED_TRACE_COUNT || + serializedTraceBytes + separatorBytes + serializedEventBytes > MAX_SERIALIZED_TRACE_EVENTS_BYTES + ) { + droppedTraceEventCount = incrementDroppedTraceEventCount(droppedTraceEventCount); + continue; + } + + traces.push(recordedTrace); + serializedTraceBytes += separatorBytes + serializedEventBytes; + } + + return { traces, droppedTraceEventCount }; +} + +export function decodeLegacyTraceRecordingResult(result: any[]): TraceRecordingResult { + return decodeTraceRecordingResult(result, 0, 0); +} + +export function decodeTraceRecordingResultWithNativeStats(result: any[]): TraceRecordingResult { + return decodeTraceRecordingResult(result, 1, normalizeNativeDroppedTraceEventCount(result[0])); +} + /** * Start recording traces happening in the Valdi Runtime. * It is absolutely essential that this call is eventually followed @@ -26,20 +141,22 @@ export function startTraceRecording(): number { * Returns the captured traces. */ export function stopTraceRecording(id: number): RecordedTrace[] { - const result = runtime.stopTraceRecording(id); - - const out: RecordedTrace[] = []; - - for (let i = 0; i < result.length; ) { - const trace = result[i++]; - const startMicros = result[i++]; - const endMicros = result[i++]; - const threadId = result[i++]; + return stopTraceRecordingWithStats(id).traces; +} - out.push({ trace, startMicros, endMicros, threadId }); +/** + * Stop recording and return both captured traces and the number discarded by native or + * serialization bounds. Older runtimes retain the legacy trace-only method and are bounded here. + */ +export function stopTraceRecordingWithStats(id: number): TraceRecordingResult { + if (runtime.stopTraceRecordingWithStats) { + return decodeTraceRecordingResultWithNativeStats(runtime.stopTraceRecordingWithStats(id)); } + return decodeLegacyTraceRecordingResult(runtime.stopTraceRecording(id)); +} - return out; +export function isTracingSupported(): boolean { + return runtime.trace !== undefined; } /** @@ -58,7 +175,12 @@ export function trace(tag: string, func: () => T): T { const TRACE_PROXY_KEY = '$trace-proxy-target'; function makeProxyFunction(tag: string, fn: (...params: any[]) => any): (...params: any[]) => any { - const proxyFunction = runtime.makeTraceProxy(tag, fn); + const makeTraceProxy = runtime.makeTraceProxy; + if (!makeTraceProxy) { + return fn; + } + + const proxyFunction = makeTraceProxy(tag, fn); Object.defineProperty(proxyFunction, 'name', { value: fn.name }); (proxyFunction as any)[TRACE_PROXY_KEY] = fn; return proxyFunction; diff --git a/src/valdi_modules/src/valdi/valdi_core/test/PerformanceTraceMessageHandler.spec.ts b/src/valdi_modules/src/valdi/valdi_core/test/PerformanceTraceMessageHandler.spec.ts new file mode 100644 index 000000000..704178ec6 --- /dev/null +++ b/src/valdi_modules/src/valdi/valdi_core/test/PerformanceTraceMessageHandler.spec.ts @@ -0,0 +1,494 @@ +import 'jasmine/src/jasmine'; +import { + PERFORMANCE_TRACE_HANDLER_TIMEOUT_MS, + PERFORMANCE_TRACE_RESULT_TTL_MS, + PerformanceTraceMessageHandler, + PerformanceTraceRuntime, +} from '../src/debugging/PerformanceTraceMessageHandler'; +import { + MAX_PERFORMANCE_TRACE_CONTEXT_ID_BYTES, + MAX_PERFORMANCE_TRACE_ERROR_BYTES, + MAX_PERFORMANCE_TRACE_MESSAGE_BYTES, + Messages, + PerformanceTraceEvent, + PerformanceTraceStartRequestBody, + PerformanceTraceStopBody, +} from '../src/debugging/Messages'; +import { + decodeLegacyTraceRecordingResult, + decodeTraceRecordingResultWithNativeStats, + MAX_SERIALIZED_TRACE_EVENTS_BYTES, + TraceRecordingResult, +} from '../src/utils/Trace'; + +class FakeRenderer { + readonly tracingValues: boolean[] = []; + + constructor(private tracingEnabled: boolean) {} + + setTracingEnabled(enabled: boolean): void { + this.tracingEnabled = enabled; + this.tracingValues.push(enabled); + } + + isTracingEnabled(): boolean { + return this.tracingEnabled; + } +} + +interface FakeRuntimeControls { + runtime: PerformanceTraceRuntime; + cancelledTimeoutIds: number[]; + advanceTimeMs(value: number): void; + fireTimeout(): void; + setDroppedTraceEventCount(value: number): void; + setNowMs(value: number): void; + setStartError(error: Error | undefined): void; + setStopError(error: Error | undefined): void; + stopRecordingIds: number[]; + timeoutMs: number | undefined; +} + +function createRuntime(traces: PerformanceTraceEvent[]): FakeRuntimeControls { + let nowMs = 100; + let droppedTraceEventCount = 0; + let startError: Error | undefined; + let stopError: Error | undefined; + let nextTimeoutId = 7; + const scheduledTimeouts = new Map void; deadlineMs: number; timeoutMs: number }>(); + const stopRecordingIds: number[] = []; + const cancelledTimeoutIds: number[] = []; + const runDueTimeouts = (): void => { + for (;;) { + const nextTimeout = Array.from(scheduledTimeouts.entries()) + .filter(([, timeout]) => timeout.deadlineMs <= nowMs) + .sort((left, right) => left[1].deadlineMs - right[1].deadlineMs)[0]; + if (!nextTimeout) return; + scheduledTimeouts.delete(nextTimeout[0]); + nextTimeout[1].callback(); + } + }; + const runtime: PerformanceTraceRuntime = { + cancelTimeout: timeoutId => { + cancelledTimeoutIds.push(timeoutId); + scheduledTimeouts.delete(timeoutId); + }, + isTracingSupported: () => true, + nowMs: () => nowMs, + nowEpochMs: () => 1000, + scheduleTimeout: (callback, delayMs) => { + const timeoutId = nextTimeoutId++; + scheduledTimeouts.set(timeoutId, { callback, deadlineMs: nowMs + delayMs, timeoutMs: delayMs }); + return timeoutId; + }, + startTraceRecording: () => { + if (startError) { + throw startError; + } + return 42; + }, + stopTraceRecording: recordingId => { + stopRecordingIds.push(recordingId); + if (stopError) { + throw stopError; + } + return { traces, droppedTraceEventCount }; + }, + }; + return { + runtime, + cancelledTimeoutIds, + advanceTimeMs: value => { + nowMs += value; + runDueTimeouts(); + }, + fireTimeout: () => { + const nextTimeout = Array.from(scheduledTimeouts.values()).sort( + (left, right) => left.deadlineMs - right.deadlineMs, + )[0]; + if (!nextTimeout) return; + nowMs = Math.max(nowMs, nextTimeout.deadlineMs); + runDueTimeouts(); + }, + setDroppedTraceEventCount: value => { + droppedTraceEventCount = value; + }, + setNowMs: value => { + nowMs = value; + }, + setStartError: error => { + startError = error; + }, + setStopError: error => { + stopError = error; + }, + stopRecordingIds, + get timeoutMs() { + return Array.from(scheduledTimeouts.values()).sort((left, right) => left.deadlineMs - right.deadlineMs)[0] + ?.timeoutMs; + }, + }; +} + +function createHandler(renderer: FakeRenderer, runtime: PerformanceTraceRuntime): PerformanceTraceMessageHandler { + return new PerformanceTraceMessageHandler(contextId => (contextId === 'root' ? renderer : undefined), runtime); +} + +function serializeTraceStopResult(result: TraceRecordingResult): string { + const body: PerformanceTraceStopBody = { + recording: false, + contextId: 'root', + completedRecordingAvailable: false, + completedContextId: undefined, + completionError: undefined, + rendererTracingEnabled: false, + tracingSupported: true, + startedAtEpochMs: 1000, + elapsedMs: 10, + traces: result.traces, + traceEventCount: result.traces.length, + droppedTraceEventCount: result.droppedTraceEventCount, + timedOut: false, + }; + return Messages.performanceTraceStopResponse('trace-request', body); +} + +describe('PerformanceTraceMessageHandler', () => { + it('starts and stops a recording with trace output and active context status', () => { + const traces = [{ trace: 'Renderer.onRender.App', startMicros: 10, endMicros: 25, threadId: 1 }]; + const controls = createRuntime(traces); + const renderer = new FakeRenderer(false); + const handler = createHandler(renderer, controls.runtime); + + const started = handler.startRecording({ contextId: 'root', rendererTracing: true }); + expect(controls.timeoutMs).toBe(PERFORMANCE_TRACE_HANDLER_TIMEOUT_MS); + controls.setNowMs(125); + const stopped = handler.stopRecording({ contextId: 'root' }); + + expect(started.recording).toBeTrue(); + expect(started.contextId).toBe('root'); + expect(stopped.contextId).toBe('root'); + expect(stopped.elapsedMs).toBe(25); + expect(stopped.traces).toEqual(traces); + expect(stopped.traceEventCount).toBe(1); + expect(stopped.droppedTraceEventCount).toBe(0); + expect(stopped.timedOut).toBeFalse(); + expect(controls.stopRecordingIds).toEqual([42]); + expect(controls.cancelledTimeoutIds).toEqual([7]); + expect(handler.getStatus().recording).toBeFalse(); + expect(handler.getStatus().contextId).toBeUndefined(); + }); + + it('rejects overlapping starts without replacing the active context', () => { + const controls = createRuntime([]); + const handler = createHandler(new FakeRenderer(false), controls.runtime); + handler.startRecording({ contextId: 'root' }); + + expect(() => handler.startRecording({ contextId: 'other' })).toThrowError( + Error, + 'A Valdi performance trace recording is already active.', + ); + expect(handler.getStatus().contextId).toBe('root'); + handler.abortRecording(); + }); + + it('rejects a stop when no recording or completed timeout is available', () => { + const controls = createRuntime([]); + const handler = createHandler(new FakeRenderer(false), controls.runtime); + + expect(() => handler.stopRecording({ contextId: 'root' })).toThrowError( + Error, + 'No Valdi performance trace recording is active or waiting to be retrieved.', + ); + }); + + it('allows idempotent stop retries until the bounded result TTL expires', () => { + const traces = [{ trace: 'Renderer.onRender.App', startMicros: 10, endMicros: 25, threadId: 1 }]; + const controls = createRuntime(traces); + const handler = createHandler(new FakeRenderer(false), controls.runtime); + handler.startRecording({ contextId: 'root' }); + + const first = handler.stopRecording({ contextId: 'root' }); + const retry = handler.stopRecording({ contextId: 'root' }); + + expect(retry).toEqual(first); + expect(controls.stopRecordingIds).toEqual([42]); + controls.advanceTimeMs(PERFORMANCE_TRACE_RESULT_TTL_MS - 1); + expect(handler.stopRecording({ contextId: 'root' })).toEqual(first); + controls.advanceTimeMs(1); + expect(() => handler.stopRecording({ contextId: 'root' })).toThrowError( + Error, + 'No Valdi performance trace recording is active or waiting to be retrieved.', + ); + }); + + it('does not let a different context stop or relabel the active recording', () => { + const controls = createRuntime([]); + const handler = createHandler(new FakeRenderer(false), controls.runtime); + handler.startRecording({ contextId: 'root' }); + + expect(() => handler.stopRecording({ contextId: 'other' })).toThrowError( + Error, + 'Valdi performance trace recording belongs to context root, not other.', + ); + expect(handler.getStatus().recording).toBeTrue(); + expect(handler.getStatus().contextId).toBe('root'); + expect(controls.stopRecordingIds).toEqual([]); + handler.stopRecording({ contextId: 'root' }); + }); + + it('cleans up and restores renderer tracing when startTraceRecording fails', () => { + const controls = createRuntime([]); + const renderer = new FakeRenderer(false); + const handler = createHandler(renderer, controls.runtime); + controls.setStartError(new Error('runtime start failed')); + + expect(() => handler.startRecording({ contextId: 'root', rendererTracing: true })).toThrowError( + Error, + 'runtime start failed', + ); + expect(renderer.isTracingEnabled()).toBeFalse(); + expect(handler.getStatus().recording).toBeFalse(); + + controls.setStartError(undefined); + expect(handler.startRecording({ contextId: 'root' }).recording).toBeTrue(); + handler.abortRecording(); + }); + + it('restores the renderer tracing flag that existed before capture', () => { + const controls = createRuntime([]); + const renderer = new FakeRenderer(true); + const handler = createHandler(renderer, controls.runtime); + + handler.startRecording({ contextId: 'root', rendererTracing: false }); + expect(renderer.isTracingEnabled()).toBeFalse(); + handler.stopRecording({ contextId: 'root' }); + + expect(renderer.isTracingEnabled()).toBeTrue(); + expect(renderer.tracingValues).toEqual([false, true]); + }); + + it('aborts the active context during teardown and restores renderer tracing', () => { + const controls = createRuntime([]); + const renderer = new FakeRenderer(false); + const handler = createHandler(renderer, controls.runtime); + handler.startRecording({ contextId: 'root', rendererTracing: true }); + + handler.abortRecordingForContext('other'); + expect(handler.getStatus().recording).toBeTrue(); + handler.abortRecordingForContext('root'); + + expect(handler.getStatus().recording).toBeFalse(); + expect(renderer.isTracingEnabled()).toBeFalse(); + expect(controls.stopRecordingIds).toEqual([42]); + }); + + it('auto-stops before the native leak guard and retains timed-out traces for retrieval', () => { + const traces = [{ trace: 'Renderer.onRender.App', startMicros: 10, endMicros: 25, threadId: 1 }]; + const controls = createRuntime(traces); + const renderer = new FakeRenderer(false); + const handler = createHandler(renderer, controls.runtime); + handler.startRecording({ contextId: 'root', rendererTracing: true }); + controls.setNowMs(20_100); + + controls.fireTimeout(); + + const status = handler.getStatus(); + expect(status.recording).toBeFalse(); + expect(status.completedRecordingAvailable).toBeTrue(); + expect(status.completedContextId).toBe('root'); + expect(renderer.isTracingEnabled()).toBeFalse(); + expect(controls.stopRecordingIds).toEqual([42]); + + const result = handler.stopRecording({ contextId: 'root' }); + expect(result.timedOut).toBeTrue(); + expect(result.traces).toEqual(traces); + expect(result.completedRecordingAvailable).toBeFalse(); + expect(handler.getStatus().completedRecordingAvailable).toBeFalse(); + }); + + it('expires an unretrieved timed-out result after the bounded result TTL', () => { + const controls = createRuntime([]); + const handler = createHandler(new FakeRenderer(false), controls.runtime); + handler.startRecording({ contextId: 'root' }); + controls.fireTimeout(); + + expect(handler.getStatus().completedRecordingAvailable).toBeTrue(); + controls.advanceTimeMs(PERFORMANCE_TRACE_RESULT_TTL_MS - 1); + expect(handler.getStatus().completedRecordingAvailable).toBeTrue(); + controls.advanceTimeMs(1); + expect(handler.getStatus().completedRecordingAvailable).toBeFalse(); + expect(() => handler.stopRecording({ contextId: 'root' })).toThrowError( + Error, + 'No Valdi performance trace recording is active or waiting to be retrieved.', + ); + }); + + it('propagates native dropped trace event counts', () => { + const controls = createRuntime([]); + controls.setDroppedTraceEventCount(3); + const handler = createHandler(new FakeRenderer(false), controls.runtime); + handler.startRecording({ contextId: 'root' }); + + const result = handler.stopRecording({ contextId: 'root' }); + + expect(result.traceEventCount).toBe(0); + expect(result.droppedTraceEventCount).toBe(3); + }); + + it('reports a timed-out native stop failure while still restoring renderer state', () => { + const controls = createRuntime([]); + const renderer = new FakeRenderer(false); + const handler = createHandler(renderer, controls.runtime); + handler.startRecording({ contextId: 'root', rendererTracing: true }); + controls.setStopError(new Error('native stop failed')); + + controls.fireTimeout(); + + expect(handler.getStatus().completionError).toContain('native stop failed'); + expect(renderer.isTracingEnabled()).toBeFalse(); + const result = handler.stopRecording({ contextId: 'root' }); + expect(result.timedOut).toBeTrue(); + expect(result.completionError).toContain('native stop failed'); + }); + + it('rejects a new start until a completed timed-out recording is retrieved', () => { + const controls = createRuntime([]); + const handler = createHandler(new FakeRenderer(false), controls.runtime); + handler.startRecording({ contextId: 'root' }); + controls.fireTimeout(); + + expect(() => handler.startRecording({ contextId: 'root' })).toThrowError( + Error, + 'A completed timed-out Valdi performance trace for context root is waiting to be retrieved.', + ); + handler.stopRecording({ contextId: 'root' }); + expect(handler.startRecording({ contextId: 'root' }).recording).toBeTrue(); + handler.abortRecording(); + }); + + it('rejects a non-boolean rendererTracing value before changing renderer state', () => { + const controls = createRuntime([]); + const renderer = new FakeRenderer(false); + const handler = createHandler(renderer, controls.runtime); + const invalidBody = { contextId: 'root', rendererTracing: 'yes' } as unknown as PerformanceTraceStartRequestBody; + + expect(() => handler.startRecording(invalidBody)).toThrowError( + Error, + 'rendererTracing must be a boolean when provided.', + ); + expect(renderer.tracingValues).toEqual([]); + }); + + it('rejects a context id whose escaped representation exceeds the runtime bound', () => { + const controls = createRuntime([]); + const renderer = new FakeRenderer(false); + const handler = createHandler(renderer, controls.runtime); + + expect(() => + handler.startRecording({ contextId: '\0'.repeat(MAX_PERFORMANCE_TRACE_CONTEXT_ID_BYTES) }), + ).toThrowError( + Error, + `Valdi performance trace contextId exceeds the ${MAX_PERFORMANCE_TRACE_CONTEXT_ID_BYTES}-byte serialized limit.`, + ); + expect(renderer.tracingValues).toEqual([]); + }); + + it('bounds cached completion errors and generic debugger error responses', () => { + const controls = createRuntime([]); + const handler = createHandler(new FakeRenderer(false), controls.runtime); + handler.startRecording({ contextId: 'root' }); + controls.setStopError(new Error('\0'.repeat(MAX_PERFORMANCE_TRACE_ERROR_BYTES))); + + const result = handler.stopRecording({ contextId: 'root' }); + const serializedResult = Messages.performanceTraceStopResponse('trace-request', result); + const error = new Error('\0'.repeat(MAX_PERFORMANCE_TRACE_ERROR_BYTES)); + error.stack = '\0'.repeat(MAX_PERFORMANCE_TRACE_ERROR_BYTES * 4); + const serializedError = Messages.errorResponse('trace-request', error); + + expect(JSON.stringify(result.completionError).length).toBeLessThanOrEqual(MAX_PERFORMANCE_TRACE_ERROR_BYTES); + expect(serializedResult.length).toBeLessThanOrEqual(MAX_PERFORMANCE_TRACE_MESSAGE_BYTES); + expect(serializedError.length).toBeLessThanOrEqual(MAX_PERFORMANCE_TRACE_MESSAGE_BYTES); + }); + + it('bounds the complete runtime trace response with adversarial metadata', () => { + const flatEvents: any[] = []; + for (let index = 0; index < 512; index++) { + flatEvents.push('\0'.repeat(2048), index, index + 1, 1); + } + const traces = decodeLegacyTraceRecordingResult(flatEvents); + const body: PerformanceTraceStopBody = { + recording: false, + contextId: '\0'.repeat(MAX_PERFORMANCE_TRACE_CONTEXT_ID_BYTES), + completedRecordingAvailable: false, + completedContextId: undefined, + completionError: '\0'.repeat(MAX_PERFORMANCE_TRACE_ERROR_BYTES), + rendererTracingEnabled: false, + tracingSupported: true, + startedAtEpochMs: 1000, + elapsedMs: 10, + traces: traces.traces, + traceEventCount: traces.traces.length, + droppedTraceEventCount: traces.droppedTraceEventCount, + timedOut: false, + }; + + const serialized = Messages.performanceTraceStopResponse('trace-request', body); + const parsed = JSON.parse(serialized) as { body: PerformanceTraceStopBody }; + + expect(serialized.length).toBeLessThanOrEqual(MAX_PERFORMANCE_TRACE_MESSAGE_BYTES); + expect(parsed.body.traceEventCount).toBe(parsed.body.traces.length); + expect(parsed.body.droppedTraceEventCount).toBeGreaterThanOrEqual(body.droppedTraceEventCount); + expect(JSON.stringify(parsed.body.contextId).length).toBeLessThanOrEqual(MAX_PERFORMANCE_TRACE_CONTEXT_ID_BYTES); + expect(JSON.stringify(parsed.body.completionError).length).toBeLessThanOrEqual(MAX_PERFORMANCE_TRACE_ERROR_BYTES); + }); + + it('bounds legacy runtime trace results and truthfully counts dropped events', () => { + const legacyResult: any[] = []; + for (let index = 0; index < 10_001; index++) { + legacyResult.push(`trace-${index}`, index, index + 1, 1); + } + + const result = decodeLegacyTraceRecordingResult(legacyResult); + + expect(result.traces.length).toBe(10_000); + expect(result.droppedTraceEventCount).toBe(1); + }); + + it('preserves JavaScript-safe native drop counts and saturates larger integral values', () => { + expect(decodeTraceRecordingResultWithNativeStats([Number.MAX_SAFE_INTEGER]).droppedTraceEventCount).toBe( + Number.MAX_SAFE_INTEGER, + ); + expect(decodeTraceRecordingResultWithNativeStats([Number.MAX_SAFE_INTEGER + 2]).droppedTraceEventCount).toBe( + Number.MAX_SAFE_INTEGER, + ); + expect(decodeTraceRecordingResultWithNativeStats([Number.MAX_VALUE]).droppedTraceEventCount).toBe( + Number.MAX_SAFE_INTEGER, + ); + + for (const invalidCount of [Number.POSITIVE_INFINITY, Number.NaN, -1, 1.5, '3', undefined]) { + expect(decodeTraceRecordingResultWithNativeStats([invalidCount]).droppedTraceEventCount).toBe(0); + } + }); + + it('accounts for JSON escaping before accepting legacy and native trace events', () => { + const eventCount = 512; + const escapedTraceName = '\0'.repeat(2048); + const flatEvents: any[] = []; + for (let index = 0; index < eventCount; index++) { + flatEvents.push(escapedTraceName, index, index + 1, 1); + } + + const legacyResult = decodeLegacyTraceRecordingResult(flatEvents); + const nativeResult = decodeTraceRecordingResultWithNativeStats([3, ...flatEvents]); + + expect(legacyResult.traces.length).toBeLessThan(eventCount); + expect(legacyResult.droppedTraceEventCount).toBe(eventCount - legacyResult.traces.length); + expect(nativeResult.traces.length).toBe(legacyResult.traces.length); + expect(nativeResult.droppedTraceEventCount).toBe(3 + eventCount - nativeResult.traces.length); + expect(JSON.stringify(legacyResult.traces).length).toBeLessThanOrEqual(MAX_SERIALIZED_TRACE_EVENTS_BYTES); + // This payload is ASCII after JSON escaping, so string length is its exact UTF-8 byte length. + expect(serializeTraceStopResult(legacyResult).length).toBeLessThanOrEqual(4 * 1024 * 1024); + expect(serializeTraceStopResult(nativeResult).length).toBeLessThanOrEqual(4 * 1024 * 1024); + }); +}); diff --git a/src/valdi_modules/src/valdi/valdi_core/test/RootComponentsManager.spec.ts b/src/valdi_modules/src/valdi/valdi_core/test/RootComponentsManager.spec.ts index eecb224a3..ef433357e 100644 --- a/src/valdi_modules/src/valdi/valdi_core/test/RootComponentsManager.spec.ts +++ b/src/valdi_modules/src/valdi/valdi_core/test/RootComponentsManager.spec.ts @@ -5,7 +5,13 @@ import { IRenderedVirtualNodeData } from '../src/IRenderedVirtualNodeData'; import { RootComponentHandle, RootComponentsManager } from '../src/RootComponentsManager'; import { RendererFactory } from '../src/RendererFactory'; import { ReceivedDaemonClientMessage } from '../src/debugging/DaemonClientManager'; -import { GetContextTreeBody, Messages } from '../src/debugging/Messages'; +import { + DaemonClientMessage, + DaemonClientMessageType, + GetContextTreeBody, + Messages, + PerformanceTraceStatusBody, +} from '../src/debugging/Messages'; function createComponentNode(): IRenderedVirtualNode { const component = { @@ -27,9 +33,18 @@ function createComponentNode(): IRenderedVirtualNode { function createManager(rootNode: IRenderedVirtualNode): RootComponentsManager { const manager = new RootComponentsManager({} as RendererFactory, undefined, () => {}); + let tracingEnabled = false; manager.rootComponents['context'] = { + contextId: 'context', + componentPath: { filePath: 'test', symbolName: 'TestRoot' }, + disposeFunction: () => {}, renderer: { getRootVirtualNode: () => rootNode, + renderRoot: (render: () => void) => render(), + isTracingEnabled: () => tracingEnabled, + setTracingEnabled: (enabled: boolean) => { + tracingEnabled = enabled; + }, }, } as RootComponentHandle; return manager; @@ -61,6 +76,23 @@ function requestContextTree( return Messages.parse(1, responseJson).body as IRenderedVirtualNodeData; } +function sendDebuggerMessage(manager: RootComponentsManager, requestJson: string): DaemonClientMessage { + const request = Messages.parse(1, requestJson); + let responseJson: string | undefined; + const receivedMessage = { + message: request, + respond: (makeMessage: (requestId: string) => string) => { + responseJson = makeMessage(request.requestId); + }, + } as ReceivedDaemonClientMessage; + + manager.onMessage(receivedMessage); + if (responseJson === undefined) { + throw new Error('RootComponentsManager did not respond to the debugger request.'); + } + return Messages.parse(1, responseJson); +} + describe('RootComponentsManager debugger tree serialization', () => { it('does not expose component data to existing tree clients by default', () => { const data = requestContextTree(createManager(createComponentNode()), undefined); @@ -75,3 +107,62 @@ describe('RootComponentsManager debugger tree serialization', () => { expect(data.component?.state).toContain('sensitive-state'); }); }); + +describe('RootComponentsManager performance tracing', () => { + it('reports an idle trace recorder through the daemon protocol', () => { + const manager = createManager(createComponentNode()); + const response = sendDebuggerMessage(manager, Messages.performanceTraceStatusRequest('trace-status', {})); + const body = response.body as PerformanceTraceStatusBody; + + expect(response.type).toBe(DaemonClientMessageType.PERFORMANCE_TRACE_STATUS_RESPONSE); + expect(body.recording).toBeFalse(); + expect(body.rendererTracingEnabled).toBeFalse(); + }); + + it('returns a protocol error when the requested renderer context does not exist', () => { + const manager = createManager(createComponentNode()); + const response = sendDebuggerMessage( + manager, + Messages.performanceTraceStartRequest('trace-start', { contextId: 'missing' }), + ); + + expect(response.type).toBe(DaemonClientMessageType.ERROR_RESPONSE); + expect((response.body as { message: string }).message).toContain('No Valdi renderer found for context missing'); + }); + + it('binds stop requests to the context that started the recording', () => { + const manager = createManager(createComponentNode()); + const startResponse = sendDebuggerMessage( + manager, + Messages.performanceTraceStartRequest('trace-start', { contextId: 'context' }), + ); + const wrongStopResponse = sendDebuggerMessage( + manager, + Messages.performanceTraceStopRequest('trace-stop-wrong', { contextId: 'other' }), + ); + const statusResponse = sendDebuggerMessage(manager, Messages.performanceTraceStatusRequest('trace-status', {})); + const stopResponse = sendDebuggerMessage( + manager, + Messages.performanceTraceStopRequest('trace-stop', { contextId: 'context' }), + ); + + expect(startResponse.type).toBe(DaemonClientMessageType.PERFORMANCE_TRACE_START_RESPONSE); + expect((startResponse.body as PerformanceTraceStatusBody).contextId).toBe('context'); + expect(wrongStopResponse.type).toBe(DaemonClientMessageType.ERROR_RESPONSE); + expect((wrongStopResponse.body as { message: string }).message).toContain( + 'Valdi performance trace recording belongs to context context, not other', + ); + expect((statusResponse.body as PerformanceTraceStatusBody).contextId).toBe('context'); + expect(stopResponse.type).toBe(DaemonClientMessageType.PERFORMANCE_TRACE_STOP_RESPONSE); + }); + + it('aborts an active recording when its root context is destroyed', () => { + const manager = createManager(createComponentNode()); + sendDebuggerMessage(manager, Messages.performanceTraceStartRequest('trace-start', { contextId: 'context' })); + + manager.destroy('context'); + const statusResponse = sendDebuggerMessage(manager, Messages.performanceTraceStatusRequest('trace-status', {})); + + expect((statusResponse.body as PerformanceTraceStatusBody).recording).toBeFalse(); + }); +}); diff --git a/valdi/src/valdi/runtime/JavaScript/JavaScriptRuntime.cpp b/valdi/src/valdi/runtime/JavaScript/JavaScriptRuntime.cpp index ea479489e..d51ee8029 100644 --- a/valdi/src/valdi/runtime/JavaScript/JavaScriptRuntime.cpp +++ b/valdi/src/valdi/runtime/JavaScript/JavaScriptRuntime.cpp @@ -9,6 +9,7 @@ #include "valdi/runtime/JavaScript/JavaScriptRuntime.hpp" #include +#include #include #include "utils/platform/BuildOptions.hpp" @@ -101,7 +102,19 @@ namespace Valdi { // static const long long kJsGarbageCollectionDelaySeconds = 2; -constexpr int kTraceRecordingTimeoutSeconds = 20; +// Debugger-driven recordings are stopped and retained by the TypeScript handler after 20 seconds. +// Keep a separate native leak guard with enough margin that it cannot discard a handler-owned result. +constexpr int kTraceRecordingTimeoutSeconds = 30; +constexpr uint64_t kMaxJavaScriptSafeInteger = 9007199254740991ULL; + +constexpr uint64_t clampTraceDroppedEventCountForJavaScript(uint64_t value) { + return value > kMaxJavaScriptSafeInteger ? kMaxJavaScriptSafeInteger : value; +} + +static_assert(clampTraceDroppedEventCountForJavaScript(kMaxJavaScriptSafeInteger) == kMaxJavaScriptSafeInteger, + "Exact JavaScript-safe trace drop counts must be preserved"); +static_assert(clampTraceDroppedEventCountForJavaScript(kMaxJavaScriptSafeInteger + 1) == kMaxJavaScriptSafeInteger, + "Oversized trace drop counts must be clamped before double conversion"); constexpr size_t kLoadPropertyName = 0; constexpr size_t kUnloadAllUnusedPropertyName = 1; @@ -1069,19 +1082,30 @@ static double traceTimePointToEpochMicroseconds(const TraceTimePoint& timePoint) return static_cast(asMicroseconds.count()); } -// NOLINTNEXTLINE(readability-convert-member-functions-to-static) -JSValueRef JavaScriptRuntime::runtimeStopTraceRecording(JSFunctionNativeCallContext& callContext) { +static JSValueRef stopTraceRecording(JSFunctionNativeCallContext& callContext, bool includeDroppedTraceEventCount) { auto id = static_cast(callContext.getParameterAsInt(0)); CHECK_CALL_CONTEXT(callContext); - auto traces = Tracer::shared().stopRecording(static_cast(id)); - std::sort(traces.begin(), traces.end(), [](const RecordedTrace& left, const RecordedTrace& right) -> bool { - return left.start < right.start; - }); + TraceRecordingResult result; + if (includeDroppedTraceEventCount) { + result = Tracer::shared().stopRecordingWithStats(static_cast(id)); + } else { + result.traces = Tracer::shared().stopRecording(static_cast(id)); + } + std::sort(result.traces.begin(), + result.traces.end(), + [](const RecordedTrace& left, const RecordedTrace& right) -> bool { + return left.start < right.start; + }); ValueArrayBuilder output; + if (includeDroppedTraceEventCount) { + const auto droppedTraceEventCount = + clampTraceDroppedEventCountForJavaScript(static_cast(result.droppedTraceEventCount)); + output.append(Value(static_cast(droppedTraceEventCount))); + } - for (auto& trace : traces) { + for (auto& trace : result.traces) { output.append(Value(StringCache::getGlobal().makeString(std::move(trace.trace)))); output.append(Value(traceTimePointToEpochMicroseconds(trace.start))); @@ -1096,6 +1120,16 @@ JSValueRef JavaScriptRuntime::runtimeStopTraceRecording(JSFunctionNativeCallCont callContext.getExceptionTracker()); } +// NOLINTNEXTLINE(readability-convert-member-functions-to-static) +JSValueRef JavaScriptRuntime::runtimeStopTraceRecording(JSFunctionNativeCallContext& callContext) { + return stopTraceRecording(callContext, false); +} + +// NOLINTNEXTLINE(readability-convert-member-functions-to-static) +JSValueRef JavaScriptRuntime::runtimeStopTraceRecordingWithStats(JSFunctionNativeCallContext& callContext) { + return stopTraceRecording(callContext, true); +} + JSValueRef JavaScriptRuntime::runtimeSubmitDebugMessage(JSFunctionNativeCallContext& callContext) { auto debugLevel = static_cast(callContext.getParameterAsInt(0)); CHECK_CALL_CONTEXT(callContext); @@ -2566,6 +2600,11 @@ void JavaScriptRuntime::buildContext(Valdi::IJavaScriptContext& context, JS_BIND(context, exceptionTracker, runtimeObject, "startTraceRecording", runtimeStartTraceRecording); JS_BIND(context, exceptionTracker, runtimeObject, "stopTraceRecording", runtimeStopTraceRecording); + JS_BIND(context, + exceptionTracker, + runtimeObject, + "stopTraceRecordingWithStats", + runtimeStopTraceRecordingWithStats); JS_BIND(context, exceptionTracker, runtimeObject, "scheduleWorkItem", runtimeScheduleWorkItem); JS_BIND(context, exceptionTracker, runtimeObject, "unscheduleWorkItem", runtimeUnscheduleWorkItem); diff --git a/valdi/src/valdi/runtime/JavaScript/JavaScriptRuntime.hpp b/valdi/src/valdi/runtime/JavaScript/JavaScriptRuntime.hpp index b7ef388e3..58c95c3ff 100644 --- a/valdi/src/valdi/runtime/JavaScript/JavaScriptRuntime.hpp +++ b/valdi/src/valdi/runtime/JavaScript/JavaScriptRuntime.hpp @@ -541,6 +541,7 @@ class JavaScriptRuntime : public JavaScriptTaskScheduler, JSValueRef runtimeMakeTraceProxy(JSFunctionNativeCallContext& callContext); JSValueRef runtimeStartTraceRecording(JSFunctionNativeCallContext& callContext); JSValueRef runtimeStopTraceRecording(JSFunctionNativeCallContext& callContext); + JSValueRef runtimeStopTraceRecordingWithStats(JSFunctionNativeCallContext& callContext); JSValueRef runtimeScheduleWorkItem(JSFunctionNativeCallContext& callContext); JSValueRef runtimeUnscheduleWorkItem(JSFunctionNativeCallContext& callContext); diff --git a/valdi/test/runtime/Tracer_tests.cpp b/valdi/test/runtime/Tracer_tests.cpp index 6e284b72f..42288bec3 100644 --- a/valdi/test/runtime/Tracer_tests.cpp +++ b/valdi/test/runtime/Tracer_tests.cpp @@ -1,10 +1,27 @@ #include "valdi_core/cpp/Utils/Trace.hpp" #include +#include + using namespace Valdi; namespace ValdiTest { +using LegacyStopRecordingSignature = std::vector (Tracer::*)(size_t); +static_assert(std::is_same::value, + "Tracer::stopRecording must preserve its public source and ABI contract"); + +struct LegacyTracerLayout { + std::mutex mutex; + std::atomic_bool recording = false; + size_t recordingSequence = 0; + std::vector pendingTraces; + std::vector recorders; +}; + +static_assert(sizeof(Tracer) == sizeof(LegacyTracerLayout), "Tracer must preserve its public object size"); +static_assert(alignof(Tracer) == alignof(LegacyTracerLayout), "Tracer must preserve its public object alignment"); + TraceTimePoint appendMs(const TraceTimePoint& start, int ms) { return start + std::chrono::milliseconds(ms); } @@ -118,4 +135,94 @@ TEST(Tracer, onlyReturnsRecordingWhenLastRecorderEnd) { ASSERT_FALSE(tracer.isRecording()); } +TEST(Tracer, boundsRecordedTraceCountBeforeSerialization) { + Tracer tracer; + auto start = std::chrono::steady_clock::now(); + auto id = tracer.startRecording(); + + for (size_t i = 0; i < Tracer::kMaxRecordedTraceCount + 1; i++) { + tracer.append("trace", start, appendMs(start, 1)); + } + + auto result = tracer.stopRecordingWithStats(id); + ASSERT_EQ(Tracer::kMaxRecordedTraceCount, result.traces.size()); + ASSERT_EQ(static_cast(1), result.droppedTraceEventCount); +} + +TEST(Tracer, doesNotReportTruncationAtExactlyTheRecordedTraceLimit) { + Tracer tracer; + auto start = std::chrono::steady_clock::now(); + auto id = tracer.startRecording(); + + for (size_t i = 0; i < Tracer::kMaxRecordedTraceCount; i++) { + tracer.append("trace", start, appendMs(start, 1)); + } + + auto result = tracer.stopRecordingWithStats(id); + ASSERT_EQ(Tracer::kMaxRecordedTraceCount, result.traces.size()); + ASSERT_EQ(static_cast(0), result.droppedTraceEventCount); +} + +TEST(Tracer, dropsOversizedTraceNamesBeforeSerialization) { + Tracer tracer; + auto start = std::chrono::steady_clock::now(); + auto id = tracer.startRecording(); + + tracer.append(std::string(Tracer::kMaxRecordedTraceNameLengthBytes + 1, 'x'), start, appendMs(start, 1)); + tracer.append("valid", start, appendMs(start, 1)); + + auto result = tracer.stopRecordingWithStats(id); + ASSERT_EQ(static_cast(1), result.traces.size()); + ASSERT_EQ(static_cast(1), result.droppedTraceEventCount); + ASSERT_EQ("valid", result.traces[0].trace); +} + +TEST(Tracer, boundsAggregateTraceNameBytesBeforeSerialization) { + Tracer tracer; + auto start = std::chrono::steady_clock::now(); + auto id = tracer.startRecording(); + const auto traceName = std::string(Tracer::kMaxRecordedTraceNameLengthBytes, 'x'); + const auto expectedCount = Tracer::kMaxRecordedTraceNameBytes / traceName.size(); + + for (size_t i = 0; i < expectedCount + 1; i++) { + tracer.append(std::string(traceName), start, appendMs(start, 1)); + } + + auto result = tracer.stopRecordingWithStats(id); + ASSERT_EQ(expectedCount, result.traces.size()); + ASSERT_EQ(static_cast(1), result.droppedTraceEventCount); +} + +TEST(Tracer, reportsDroppedEventsToEachConcurrentRecorderThatObservedThem) { + Tracer tracer; + auto start = std::chrono::steady_clock::now(); + const auto oversizedTraceName = std::string(Tracer::kMaxRecordedTraceNameLengthBytes + 1, 'x'); + auto firstId = tracer.startRecording(); + tracer.append(std::string(oversizedTraceName), start, appendMs(start, 1)); + auto secondId = tracer.startRecording(); + tracer.append(std::string(oversizedTraceName), start, appendMs(start, 1)); + + auto firstResult = tracer.stopRecordingWithStats(firstId); + auto secondResult = tracer.stopRecordingWithStats(secondId); + + ASSERT_EQ(static_cast(2), firstResult.droppedTraceEventCount); + ASSERT_EQ(static_cast(1), secondResult.droppedTraceEventCount); +} + +TEST(Tracer, retainsConcurrentDroppedCountsWhenTheNewestRecorderStopsFirst) { + Tracer tracer; + auto start = std::chrono::steady_clock::now(); + const auto oversizedTraceName = std::string(Tracer::kMaxRecordedTraceNameLengthBytes + 1, 'x'); + auto firstId = tracer.startRecording(); + tracer.append(std::string(oversizedTraceName), start, appendMs(start, 1)); + auto secondId = tracer.startRecording(); + tracer.append(std::string(oversizedTraceName), start, appendMs(start, 1)); + + auto secondResult = tracer.stopRecordingWithStats(secondId); + auto firstResult = tracer.stopRecordingWithStats(firstId); + + ASSERT_EQ(static_cast(1), secondResult.droppedTraceEventCount); + ASSERT_EQ(static_cast(2), firstResult.droppedTraceEventCount); +} + } // namespace ValdiTest diff --git a/valdi_core/src/valdi_core/cpp/Utils/Trace.cpp b/valdi_core/src/valdi_core/cpp/Utils/Trace.cpp index efbd06117..4209c0102 100644 --- a/valdi_core/src/valdi_core/cpp/Utils/Trace.cpp +++ b/valdi_core/src/valdi_core/cpp/Utils/Trace.cpp @@ -8,8 +8,64 @@ #include "valdi_core/cpp/Utils/Trace.hpp" #include "valdi_core/cpp/Utils/StringBox.hpp" +#include +#include + namespace Valdi { +namespace { + +struct DroppedTraceEventCount { + size_t recordingSequence; + size_t count; +}; + +struct TracerRecordingState { + size_t pendingTraceNameBytes = 0; + std::vector pendingDroppedTraceEventCounts; +}; + +struct TracerRecordingStateRegistry { + std::mutex mutex; + std::unordered_map> states; +}; + +TracerRecordingStateRegistry& getTracerRecordingStateRegistry() { + // Tracer::shared() intentionally outlives process teardown. Keeping its auxiliary registry on + // the same lifetime avoids static-destruction ordering hazards while preserving Tracer's public + // object layout for existing native clients. + static auto* registry = new TracerRecordingStateRegistry(); + return *registry; +} + +void registerTracerRecordingState(const Tracer* tracer) { + auto& registry = getTracerRecordingStateRegistry(); + std::lock_guard lock(registry.mutex); + auto [it, inserted] = registry.states.emplace(tracer, std::make_unique()); + if (!inserted) { + it->second = std::make_unique(); + } +} + +TracerRecordingState* getTracerRecordingState(const Tracer* tracer) { + auto& registry = getTracerRecordingStateRegistry(); + std::lock_guard lock(registry.mutex); + auto it = registry.states.find(tracer); + if (it == registry.states.end()) { + auto insertedIt = registry.states.emplace(tracer, std::make_unique()).first; + return insertedIt->second.get(); + } + return it->second.get(); +} + +void unregisterTracerRecordingState(const Tracer* tracer) { + auto& registry = getTracerRecordingStateRegistry(); + std::lock_guard lock(registry.mutex); + registry.states.erase(tracer); +} + +} // namespace + std::string getTraceName(std::string_view prefix, const StringBox& suffix) { return getTraceName(prefix, suffix.toStringView()); } @@ -83,8 +139,13 @@ void ScopedTrace::end() { _osEmitter.end(traceEnd); } -Tracer::Tracer() = default; -Tracer::~Tracer() = default; +Tracer::Tracer() { + registerTracerRecordingState(this); +} + +Tracer::~Tracer() { + unregisterTracerRecordingState(this); +} Tracer& Tracer::shared() { static auto* kInstance = new Tracer(); @@ -97,7 +158,21 @@ void Tracer::append(std::string&& trace, const TraceTimePoint& start, const Trac return; } + auto* recordingState = getTracerRecordingState(this); + const auto traceNameBytes = trace.size(); + if (traceNameBytes > kMaxRecordedTraceNameLengthBytes || _pendingTraces.size() >= kMaxRecordedTraceCount || + traceNameBytes > kMaxRecordedTraceNameBytes - recordingState->pendingTraceNameBytes) { + if (recordingState->pendingDroppedTraceEventCounts.empty() || + recordingState->pendingDroppedTraceEventCounts.back().recordingSequence != _recordingSequence) { + recordingState->pendingDroppedTraceEventCounts.push_back({_recordingSequence, 1}); + } else { + recordingState->pendingDroppedTraceEventCounts.back().count++; + } + return; + } + _pendingTraces.emplace_back(std::move(trace), start, end, getCurrentThreadId(), _recordingSequence); + recordingState->pendingTraceNameBytes += traceNameBytes; } size_t Tracer::startRecording() { @@ -111,6 +186,10 @@ size_t Tracer::startRecording() { } std::vector Tracer::stopRecording(size_t recordingIdentifier) { + return stopRecordingWithStats(recordingIdentifier).traces; +} + +TraceRecordingResult Tracer::stopRecordingWithStats(size_t recordingIdentifier) { std::lock_guard lock(_mutex); auto it = std::find(_recorders.begin(), _recorders.end(), recordingIdentifier); @@ -123,17 +202,34 @@ std::vector Tracer::stopRecording(size_t recordingIdentifier) { // Simple case, we only have one recorder we can return all the recorded traces if (_recorders.empty()) { _recording = false; - return std::move(_pendingTraces); + auto* recordingState = getTracerRecordingState(this); + recordingState->pendingTraceNameBytes = 0; + TraceRecordingResult result; + result.traces = std::move(_pendingTraces); + for (const auto& droppedTraceEventCount : recordingState->pendingDroppedTraceEventCounts) { + if (droppedTraceEventCount.recordingSequence >= recordingIdentifier) { + result.droppedTraceEventCount += droppedTraceEventCount.count; + } + } + _pendingTraces.clear(); + recordingState->pendingDroppedTraceEventCounts.clear(); + return result; } // We still have one active recorder. We collect the traces that ocurreded with or after // this identifier - std::vector outTraces; + TraceRecordingResult result; for (const auto& trace : _pendingTraces) { if (trace.recordingSequence >= recordingIdentifier) { - outTraces.emplace_back(trace); + result.traces.emplace_back(trace); + } + } + auto* recordingState = getTracerRecordingState(this); + for (const auto& droppedTraceEventCount : recordingState->pendingDroppedTraceEventCounts) { + if (droppedTraceEventCount.recordingSequence >= recordingIdentifier) { + result.droppedTraceEventCount += droppedTraceEventCount.count; } } @@ -146,10 +242,21 @@ std::vector Tracer::stopRecording(size_t recordingIdentifier) { while (newStartIt != _pendingTraces.end() && newStartIt->recordingSequence < lowestRecordingIdentifier) { newStartIt++; } + for (auto it = _pendingTraces.begin(); it != newStartIt; ++it) { + recordingState->pendingTraceNameBytes -= it->trace.size(); + } _pendingTraces.erase(_pendingTraces.begin(), newStartIt); + + auto newDroppedStartIt = recordingState->pendingDroppedTraceEventCounts.begin(); + while (newDroppedStartIt != recordingState->pendingDroppedTraceEventCounts.end() && + newDroppedStartIt->recordingSequence < lowestRecordingIdentifier) { + newDroppedStartIt++; + } + recordingState->pendingDroppedTraceEventCounts.erase(recordingState->pendingDroppedTraceEventCounts.begin(), + newDroppedStartIt); } - return outTraces; + return result; } } // namespace Valdi diff --git a/valdi_core/src/valdi_core/cpp/Utils/Trace.hpp b/valdi_core/src/valdi_core/cpp/Utils/Trace.hpp index 18961e35c..7cad16b0a 100644 --- a/valdi_core/src/valdi_core/cpp/Utils/Trace.hpp +++ b/valdi_core/src/valdi_core/cpp/Utils/Trace.hpp @@ -47,8 +47,17 @@ struct RecordedTrace { TraceDuration duration() const; }; +struct TraceRecordingResult { + std::vector traces; + size_t droppedTraceEventCount = 0; +}; + class Tracer { public: + static constexpr size_t kMaxRecordedTraceCount = 10000; + static constexpr size_t kMaxRecordedTraceNameLengthBytes = 2048; + static constexpr size_t kMaxRecordedTraceNameBytes = 1024 * 1024; + Tracer(); ~Tracer(); @@ -58,6 +67,7 @@ class Tracer { size_t startRecording(); std::vector stopRecording(size_t recordingIdentifier); + TraceRecordingResult stopRecordingWithStats(size_t recordingIdentifier); void append(std::string&& trace, const TraceTimePoint& start, const TraceTimePoint& end);