|
| 1 | +# profiler |
| 2 | + |
| 3 | +## Overview {/* #overview */} |
| 4 | + |
| 5 | +The built-in profiler explains where a Testplane run spent wall time and CPU, highlights likely bottlenecks, and suggests changes to try. Measurements and recommendations are kept separate: every recommendation includes evidence and a `high`, `medium`, or `low` confidence level. |
| 6 | + |
| 7 | +Profiling works for CLI runs and the programmatic `run` and `readTests` APIs. |
| 8 | + |
| 9 | +## Setup {/* #setup */} |
| 10 | + |
| 11 | +```javascript title="testplane.config.js" |
| 12 | +module.exports = { |
| 13 | + profiler: { |
| 14 | + level: 2, |
| 15 | + output: "profiler-result.json", |
| 16 | + }, |
| 17 | +}; |
| 18 | +``` |
| 19 | + |
| 20 | +| Parameter | Type | Default | Description | |
| 21 | +| ------------------- | ------------------ | ------- | ------------------------------------------------------------------------------------ | |
| 22 | +| [`level`](#level) | `0 \| 1 \| 2 \| 3` | `0` | Selects cumulative collection detail. `0` disables the profiler. | |
| 23 | +| [`output`](#output) | `string \| null` | `null` | Optional path to an atomic JSON report, resolved from the current working directory. | |
| 24 | + |
| 25 | +### level {/* #level */} |
| 26 | + |
| 27 | +The levels are cumulative: |
| 28 | + |
| 29 | +- `0` collects nothing and produces no profiler console output, event, or file; |
| 30 | +- `1` records the full run and major lifecycle phases, process CPU, event-loop metrics, memory, and host CPU samples; |
| 31 | +- `2` adds event listeners, test-file loading and cache behavior, tests and grouped hooks, worker utilization, browser-pool queues, and session reuse; |
| 32 | +- `3` adds individual hooks, browser commands, CommonJS/ESM load boundaries, scoped async active/waiting time, and partial browser-runtime telemetry. |
| 33 | + |
| 34 | +Use level 1 to locate a slow phase, level 2 for normal investigation, and level 3 only when the additional detail is needed. `level` must be an integer from 0 through 3. |
| 35 | + |
| 36 | +### output {/* #output */} |
| 37 | + |
| 38 | +When set, `output` must be a non-empty path ending in `.json`. Testplane writes the report through a temporary file and atomically renames it. Without `output`, the console summary and [`PROFILER_RESULT`](../../testplane-events#profiler_result) event remain available. |
| 39 | + |
| 40 | +TypeScript users can import the public result type from the package root: |
| 41 | + |
| 42 | +```typescript |
| 43 | +import type { ProfilerResultV1 } from "testplane"; |
| 44 | +``` |
| 45 | + |
| 46 | +## Reading the result {/* #reading_the_result */} |
| 47 | + |
| 48 | +The report has these top-level sections: |
| 49 | + |
| 50 | +- `run`: operation, outcome, total duration, and partial-result reasons; |
| 51 | +- `environment` and `capabilities`: runtime details and which measurements were available; |
| 52 | +- `timeline`: retained operations with process and correlation context; |
| 53 | +- `aggregates`: full streaming statistics, even when detailed operations were truncated; |
| 54 | +- `findings`: evidence-backed observations and suggested experiments; |
| 55 | +- `dataQuality`: collector coverage, clock uncertainty, and warnings; |
| 56 | +- `profiler`: bounded collection errors, truncation information, and measured in-run profiler overhead. |
| 57 | + |
| 58 | +A console result is formatted as a readable report with the execution breakdown, detailed findings, and suggested actions: |
| 59 | + |
| 60 | +```text |
| 61 | +[profiler] Test run profile |
| 62 | +________________________________________________________________________________________ |
| 63 | +
|
| 64 | +Total time: 452ms |
| 65 | +
|
| 66 | +Execution breakdown |
| 67 | +
|
| 68 | + Phase Time Time % Bar |
| 69 | + ____________________________ _____ ______ __________ |
| 70 | + Initialize Testplane 351ms 77.8% ██████████ |
| 71 | + Discover and load test files 85ms 18.7% ██ |
| 72 | + Load configuration 7ms 1.5% |
| 73 | + Unattributed 7ms 1.5% |
| 74 | + Load plugins 2ms 0.4% |
| 75 | + Set up transforms 0ms <0.1% |
| 76 | +
|
| 77 | +Performance findings |
| 78 | +
|
| 79 | +1. MEDIUM • Slow event listener • init:acceptanceSlowInit |
| 80 | +
|
| 81 | + init:acceptanceSlowInit used 351ms across 1 call(s). Slowest retained call at |
| 82 | + /path/to/project/.profiler-acceptance/acceptance-plugin.cjs |
| 83 | + (.profiler-acceptance/acceptance-plugin.cjs:5:19) took 351ms. |
| 84 | +
|
| 85 | + Slowest call breakdown |
| 86 | + Activity Time Call % Bar |
| 87 | + _________ _____ ______ _____________ |
| 88 | + Active JS 0ms <0.1% |
| 89 | + Waiting 350ms 99.9% █████████████ |
| 90 | +
|
| 91 | + Suggested action: |
| 92 | + init:acceptanceSlowInit (acceptance-plugin.cjs:5:19): waiting dominates the slowest |
| 93 | + retained call; inspect awaited I/O or timers and remove avoidable serial waits. |
| 94 | +
|
| 95 | +________________________________________________________________________________________ |
| 96 | +[profiler] 1 finding: 1 medium |
| 97 | +``` |
| 98 | + |
| 99 | +The JSON keeps measurements and advice separate: |
| 100 | + |
| 101 | +```json |
| 102 | +{ |
| 103 | + "schemaVersion": 1, |
| 104 | + "run": { |
| 105 | + "level": 2, |
| 106 | + "profileStatus": "complete", |
| 107 | + "runOutcome": "passed", |
| 108 | + "durationMs": 133000 |
| 109 | + }, |
| 110 | + "timeline": [], |
| 111 | + "aggregates": {}, |
| 112 | + "findings": [ |
| 113 | + { |
| 114 | + "category": "event-listener", |
| 115 | + "confidence": "high", |
| 116 | + "evidence": [{ "metric": "wall", "value": 30000, "unit": "ms" }], |
| 117 | + "action": "Inspect this listener's source and reduce synchronous work." |
| 118 | + } |
| 119 | + ] |
| 120 | +} |
| 121 | +``` |
| 122 | + |
| 123 | +The example is abbreviated. Use the public `ProfilerResultV1` type and `schemaVersion` when consuming the complete payload. |
| 124 | + |
| 125 | +Each timeline operation distinguishes wall time from cumulative work, overlap, critical-path impact, and the available CPU estimate. Parallel operations can have cumulative work greater than the run wall time; this is expected and must not be read as elapsed run duration. |
| 126 | + |
| 127 | +`processCpuMs` is a process-window measurement and is not exclusive when operations overlap. Level 3 may additionally provide thread CPU and estimates of synchronous JS activity versus asynchronous waiting. Event-loop delay is process-wide. Browser CPU attribution is not available in v1; consult `capabilities` and `dataQuality.coverage` before relying on any optional field. |
| 128 | + |
| 129 | +Entity details are retained with deterministic top-K and serialized-size limits. `profiler.truncation` states what was seen and retained; aggregates still include all observations. Internal collector failures make the result `partial` but do not change the test outcome. |
| 130 | + |
| 131 | +Paths are project-relative when possible, URLs have credentials/query/hash removed, and known secret-like values are redacted. Raw browser session IDs and raw browser-command arguments are not included. |
| 132 | + |
| 133 | +## Lifecycle boundary {/* #lifecycle_boundary */} |
| 134 | + |
| 135 | +The profile starts at CLI/API entry, includes configuration, plugins, initialization, test discovery and loading, master/worker startup, sessions, test execution, reporters, and normal teardown. Stages that a command does not execute are absent rather than reported with zero duration. Uncovered time is represented as `unattributed`. |
| 136 | + |
| 137 | +The final snapshot is frozen after teardown and then delivered to the console, the event, and the optional JSON file. Snapshot creation, serialization, and event delivery are profiler overhead, but cannot recursively appear inside the already frozen payload. Output or event-handler failures are reported as warnings and do not change the test result. |
| 138 | + |
| 139 | +```text |
| 140 | +END → RUNNER_END → worker flush/shutdown → afterAll and cleanup |
| 141 | + → freeze ProfilerResultV1 → console + PROFILER_RESULT + optional JSON |
| 142 | +``` |
| 143 | + |
| 144 | +On graceful termination, Testplane requests a bounded worker flush and emits a partial profile with the abort reason. A second termination signal keeps the existing force-exit behavior, so delivery cannot be guaranteed in that case. |
| 145 | + |
| 146 | +## Consuming the event {/* #consuming_the_event */} |
| 147 | + |
| 148 | +```javascript |
| 149 | +module.exports = testplane => { |
| 150 | + testplane.on(testplane.events.PROFILER_RESULT, async result => { |
| 151 | + await sendToTelemetry(result); |
| 152 | + }); |
| 153 | +}; |
| 154 | +``` |
| 155 | + |
| 156 | +The async event receives the same immutable object used for the console and JSON outputs. Its own handlers are outside the frozen profile and cannot recursively add spans to it. |
0 commit comments