chore(repo): add profiling setup and make some initial perf tweaks - #35186
chore(repo): add profiling setup and make some initial perf tweaks#35186AgentEnder wants to merge 30 commits into
Conversation
✅ Deploy Preview for nx-dev ready!
To edit notification comments on pull requests, go to your Netlify project configuration. |
✅ Deploy Preview for nx-docs ready!
To edit notification comments on pull requests, go to your Netlify project configuration. |
|
View your CI Pipeline Execution ↗ for commit 957c0d9
☁️ Nx Cloud last updated this comment at |
98e07b5 to
6cd77ce
Compare
| if expanded_outputs.is_empty() { | ||
| return Ok(0); | ||
| } |
There was a problem hiding this comment.
Early return bypasses profiler recording. When expanded_outputs is empty, the function returns Ok(0) immediately, but restore_start was already captured at line 316. This means the profiler's record() call at line 364 is never reached, creating inconsistent profiling data.
Fix: Move the profiler recording before the early return:
if expanded_outputs.is_empty() {
crate::native::profiler::record("cache::copy_files_from_cache", restore_start);
return Ok(0);
}| if expanded_outputs.is_empty() { | |
| return Ok(0); | |
| } | |
| if expanded_outputs.is_empty() { | |
| crate::native::profiler::record("cache::copy_files_from_cache", restore_start); | |
| return Ok(0); | |
| } |
Spotted by Graphite
Is this helpful? React 👍 or 👎 to let us know.
db71d60 to
8ca4911
Compare
f89bc4a to
87a07f7
Compare
87a07f7 to
bca182e
Compare
|
Review the following changes in direct dependencies. Learn more about Socket for GitHub.
|
98f9c3e to
9173512
Compare
0a82b95 to
5b832ee
Compare
5b832ee to
ddc78ad
Compare
3012a5a to
dd9d50c
Compare
5b18f2f to
feeb520
Compare
feeb520 to
abab57e
Compare
- cache_restore.rs: benchmark cache restore for varying output counts - file_ops_bench.rs: benchmark copy operations - hashmap_bench.rs: compare std::HashMap vs hashbrown for planning workloads 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude <noreply@anthropic.com>
- perf-logging.ts: accumulate performance.measure() spans, GC stats, and event-loop delay when NX_PROFILE_OUT is set; flush per-process JSON on exit and SIGTERM - perf-report.ts: buildReport/writePidReport for per-process capture; buildSpansSection, buildTotalsSection, buildScenarioIndexMarkdown for markdown report generation - Add markdown-factory as optional peer dependency in packages/nx - Bump markdown-factory to ^1.0.0 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude <noreply@anthropic.com>
Pass plugin path, config, and transpiler flag as argv to the worker at spawn time so it can begin loading the plugin module immediately after server.listen(), before the main process connects and sends the load message. This overlaps plugin loading with the socket-connection phase, eliminating the load round-trip from the critical path. - Workers start in the correct directory via cwd option on spawn rather than calling process.chdir inside the worker - Eager load uses async import() inside setImmediate to keep the event loop free during module resolution so the host can connect mid-load - Suppress unhandledRejection on the eager promise until the load handler attaches; rejection is still propagated when awaited 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude <noreply@anthropic.com>
- Memoize readProjectsConfigurationFromProjectGraph on the ProjectGraph instance via WeakMap; during a single run the graph never changes so repeated callers share the same object without repeating the O(n) node iteration - Cache dotenv file parses in loadAndExpandDotEnvFile keyed by (path, mtime); repeated calls for the same unchanged file skip the file read and re-parse while variable expansion still runs live per-task 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude <noreply@anthropic.com>
- profile-run.mts: orchestrates nx commands across four scenarios (daemon-cold, daemon-warm, nodaemon-cold, nodaemon-warm), collects per-process JSON reports, V8 CPU profiles, and macOS sample output, then renders markdown reports in a timestamped output directory - perf-cpu-profile.mts: parse V8 .cpuprofile files into self-time and call-chain hot spot reports - perf-sample.mts: parse macOS sample command output into self-time hot spot reports with library breakdown - Add profile script and nx target to benchmarks/package.json - Exclude profile-out/ from git 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude <noreply@anthropic.com>
Co-authored-by: AgentEnder <AgentEnder@users.noreply.github.com>
Co-authored-by: AgentEnder <AgentEnder@users.noreply.github.com>
The .env parse cache short-circuited missing files by returning an empty
expand() result with no `error`, but dotenv's config() returns { error }
on a missing file. Callers that inspect result.error (e.g. run-commands'
required `envFile`) stopped throwing. Fall back to the original dotenv
path on stat failure so the error is surfaced.
The worker is now spawned with cwd: root, and node resolves a bare `--require ts-node/register` specifier relative to the child's cwd. A workspace root without a hoisted node_modules/ts-node (temp/virtual test workspaces) failed with 'Cannot find module ts-node/register' and the worker exited before connecting. Resolve to an absolute path so cwd no longer matters.
…Self-Healing CI Rerun]
…Self-Healing CI Rerun]
…Self-Healing CI Rerun]
`dotenv-expand` mutates the `parsed` object it is given in place, so caching
`myEnv.parsed` by reference let the first caller's substitutions be written
back into the cache entry. Every later read of the same file then replayed
that caller's values, and since no `${...}` remained, re-expansion was a no-op.
Two reachable consequences:
- Two tasks reading the same .env with different contexts both got the
first task's expansions.
- `run-commands`' `envFile` option, in a single invocation: `loadEnvVarsFile`
calls `unloadDotEnvFile` first, which expands against a throwaway empty
env, priming the cache with every `${...}` resolved to the empty string.
The very next line hit that cache, so `http://${HOST}:3000` reached the
spawned command as `http://:3000` — silently, with no warning.
Snapshot the parsed pairs before expanding, and hand `expand()` a copy on the
cache-hit path so it can never reach the cached object.
Also include size and inode in the invalidation signature: `mtimeMs` alone
misses a same-millisecond rewrite, and watch-mode processes live long enough
to hit that.
The existing tests structurally could not catch this — both `mkdtempSync` a
fresh directory per test, so every call was a cache miss. The added tests call
twice against the same file with different contexts.
Claude-Session: https://claude.ai/code/session_01LsFgrnFJPfpqf9X7qfAXtW
`profiler::enabled()` had zero call sites, so the "zero overhead when
disabled" claim in the module doc and in the newly published docs row was not
what shipped: `cache.rs`'s `Instant::now()` ran unconditionally, and `record()`
computed `elapsed()` before `record_ms` checked the atomic.
Add `profiler::start()`, which returns `Some(Instant::now())` only when
profiling is on, and take an `Option<Instant>` in `record()`. Disabled
call-sites now cost one relaxed atomic load and never read the clock.
(`hash_planner` keeps using `record_ms` — its durations are already computed
unconditionally for the existing tracing output.)
Also:
- `NX_NATIVE_PROFILE` was a presence test, so `=0` and `=false` both enabled
profiling while the docs declared the type `boolean`. Parse it: only `1`
and `true` enable.
- Drain `EVENTS` in `get_native_timings()`. It was never drained, so a
long-lived daemon grew it without bound and a second call double-reported
every span.
- Recover a poisoned `EVENTS` lock instead of returning `None`, which the
caller cannot tell apart from "profiling was off".
Claude-Session: https://claude.ai/code/session_01LsFgrnFJPfpqf9X7qfAXtW
The eager-load change put `JSON.stringify(plugin)` on the plugin worker's
argv. `PluginConfiguration.options` is arbitrary user JSON from `nx.json`, and
it previously travelled only over the unix socket in the `load` message. On a
command line it is readable by any local user via `ps -ww`, and it was then
persisted verbatim into the profile report, which records
`process.argv.slice(2).join(' ')`. A large options object also risked `E2BIG`
at spawn, which the socket path had no equivalent of.
The configuration is not actually needed to start loading: the expensive half
of `loadResolvedNxPluginAsync` is `importPluginModule(pluginPath)`, and only
the cheap `new LoadedNxPlugin(...)` needs the config. Split the two — export
`importPluginModule` and a new `bindPluginModule` — so the worker imports the
module eagerly from just the path, then binds the configuration when the
`load` message delivers it over the socket. The eager-load win is unchanged;
argv carries only a path and a transpiler flag.
Also fix `shortCommand`, which still assumed the old two-element argv layout
and read the plugin name where it wanted the script path.
Claude-Session: https://claude.ai/code/session_01LsFgrnFJPfpqf9X7qfAXtW
… reports Two problems in `perf-logging`'s flush path, both only when `NX_PROFILE_OUT` is set — which is exactly the mode the benchmark numbers come from. `flushProfile` returned early on `profileEntries.length === 0` and fetched `getNativeTimings()` only after that return, so a process with native timings but no JS measures (a cache-restore-heavy task worker) wrote no report at all, and the missing file was indistinguishable from "that process never ran". Fetch the native timings first and skip only when both are empty. The SIGTERM handler called `process.exit(0)`. Because this module is imported at CLI startup, its listener registers before every other SIGTERM handler in the process, and `process.exit` never returns — so the orchestrator's task cleanup, the daemon's shutdown (socket close, watcher stop, process-cache delete) and the plugin worker's socket unlink were all skipped, and a signalled death reported exit code 0. The benchmark harness triggers this on itself: the daemon inherits `NX_PROFILE_OUT`, and `nx reset` between scenarios SIGTERMs that daemon. It cannot simply be removed — registering any listener suppresses Node's default termination, so with none of them the profile would be lost, and with a listener that just returns the process becomes unkillable by SIGTERM. Instead, defer to any other handler when one exists (they own shutdown, and the 'exit' flush still runs, now also capturing measures emitted during their cleanup), and only flush and re-raise when we are the sole handler. Verified both branches: cleanup runs and exit code 143 is preserved. Guard the flush so the SIGTERM and 'exit' paths cannot both write — relevant now that `getNativeTimings()` drains. Claude-Session: https://claude.ai/code/session_01LsFgrnFJPfpqf9X7qfAXtW
`file_ops_bench.rs` documented itself as modelling the cache-restore hot path, but cache restore goes through `copy_outputs_into_workspace`, which passes `Some(workspace_root)` and so takes the `create_dir_all_within` arm — untouched by this PR. The benchmarked `None` arm is reached only via the public `copy()` NAPI export. Say what it actually justifies. `profile-run.mts` exited with only the last scenario's status, so a run where three of four scenarios failed still exited 0. Fail on any non-zero scenario and name the ones that failed. Claude-Session: https://claude.ai/code/session_01LsFgrnFJPfpqf9X7qfAXtW
…o [Self-Healing CI Rerun]
5f334a2 to
e801ea0
Compare
Every daemon request force-flushes the watcher before serving the graph, and the daemon logs "Client Request for Project Graph Received" just before it does. That log write is a raw FSEvents event that lands inside the flush's grace window; the filter drops it (`.nx/` is ignored), but the loop had already marked a burst in progress, so an idle flush waited the full 50ms FORCE_FLUSH_QUIET instead of the grace. Measured on a warm daemon: every request paid 55-66ms in the flush with count=0, and with a stream of ignored writes the flush ran to the 250ms cap. Two changes. `ingest_event` now reports whether it accumulated anything, and only an accumulated event re-arms the quiet window. The idle grace is a fixed budget from the start of the flush rather than restarting on every received event. The macOS grace drops from 50ms to 25ms: FSEvents delivered a utime to notify in 7-17ms across 10 probes under load, and the previous value was ~20% of a warm `show projects`. A warm daemon flush now measures 27-28ms. `show projects` on the 1110-project benchmark: 269ms -> 200ms. `run-many -t cat`, daemon warm: 927ms -> 629ms (with the task-side changes that follow). Claude-Session: https://claude.ai/code/session_01KHjxSTYyww1TW1MKBCjr19
…umerating disks `get_default_max_cache_size` built a sysinfo `Disks` list to find the one mount the cache path lives on, which on macOS walks every mounted volume: 34.7ms in one call, paid by every task run that constructs the cache. A `statvfs` on the nearest existing ancestor answers the same question in 0.06ms with the same result (92.6 GB = 10% of the 926 GB volume). Claude-Session: https://claude.ai/code/session_01KHjxSTYyww1TW1MKBCjr19
… construction The collector's constructor refreshed every process on the machine to seed a CPU baseline: 11.4ms, paid by any CLI that registers the daemon pid and never collects a metric. The baseline moves to `start_collection`, ahead of the first cycle it exists for. Construction now measures 0.4ms. Claude-Session: https://claude.ai/code/session_01KHjxSTYyww1TW1MKBCjr19
The dotenv parse cache could never hit on the task path. A task's candidate
list (`.env.<target>.local`, `.env.<project>.<target>`, ...) almost always
contains a file that does not exist, one `statSync` throw sent the whole list
to the uncached fallback, and dotenv then threw once more per missing file.
On top of that, `process.env` was spread per task to unload the three root
files, which alone cost 64ms across 1110 tasks.
Absent candidates are now dropped with `throwIfNoEntry: false` (about 1us
each), the files that exist cache by their stat signature, and the root three
are unloaded once per run and re-validated by stat. A single named file that
is missing keeps dotenv's `{ error }` result, which `loadEnvVarsFile`
reports for a required `envFile`.
`getTaskSpecificEnv` over 1000 tasks: 330-373ms -> 57-78ms. The
`hashMultipleTasks` span on the benchmark: 327ms -> 147ms.
Claude-Session: https://claude.ai/code/session_01KHjxSTYyww1TW1MKBCjr19
`TasksSchedule.complete` rewrote every `reverseTaskDeps` entry with a `.filter` on each completion, 1110 x 1110 allocations over a run. A completed task can only appear in the dependents lists of its own dependencies, so those are the only entries touched now; the result is the same by construction. `cleanUpUnneededContinuousTasks` also scanned every task per completion even with nothing continuous running; it returns early when there is nothing to stop. Together with the run-commands change these were ~136ms of a cold-cache run-many on the benchmark. Claude-Session: https://claude.ai/code/session_01KHjxSTYyww1TW1MKBCjr19
`processEnv` spread `process.env` twice per task: once inside npm-run-path's `env()`, then again to layer the result. Each spread is ~58us because `process.env` reads go through the C++ interceptor per key, so this was ~120ms across 1110 spawned tasks. npm-run-path is now asked for the PATH string alone and the result written back under the platform's key. Claude-Session: https://claude.ai/code/session_01KHjxSTYyww1TW1MKBCjr19
…f plugin worker startup Importing a plugin in a worker pulled in the daemon client (via retrieve-workspace-files), ora (via the project-configuration spinner), the catalog YAML parsers and package-manager detection, none of which a worker needs to load a plugin: the host resolves plugins for it. Those imports are now taken at the call sites that use them. Module-namespace imports that the specs spy on stay static. Fresh-process plugin load with the native binding preloaded: project-json 63ms -> 10ms, package-json 65ms -> 44ms, js 71ms -> 60ms. That is on the critical path of every no-daemon graph build and of daemon startup. Claude-Session: https://claude.ai/code/session_01KHjxSTYyww1TW1MKBCjr19
`getProjectType` read `<root>/package.json` for every project without an explicit type and caught the ENOENT. On the 1110-project benchmark that was 65ms of thrown errors during graph construction. An `existsSync` first. Claude-Session: https://claude.ai/code/session_01KHjxSTYyww1TW1MKBCjr19
`show projects` parsed its arguments in affected mode unconditionally, and that mode resolves --base to a merge-base by spawning git: 17ms on every invocation, whether or not --affected was passed. Affected mode is now used only when it is; `run-one` has no mode-specific handling. Claude-Session: https://claude.ai/code/session_01KHjxSTYyww1TW1MKBCjr19
Current Behavior
Nx has no profiling toolchain that captures per-run timings across both the native (Rust) and JS layers, so investigating regressions or validating perf wins relies on ad-hoc instrumentation. Separately, several hot paths — plugin loading, cache restore, hash planning, and per-task env setup — execute work that's redundant within a single invocation.
Expected Behavior
This PR adds a profiling infrastructure (Rust + JS) on top of today's master and applies a handful of targeted perf tweaks. The infrastructure is opt-in:
NX_NATIVE_PROFILE=1enables the Rust timing store, andNX_PROFILE_OUT=<path>enables the JS report (per-PID JSON written underdirname(NX_PROFILE_OUT)on exit). Neither flag adds cost when unset.Profiling infrastructure (new)
getNativeTimingsNAPI export, wired through the logger once-guard; instrumented on cache restore and hash planning hot paths.perf-report.ts) gated byNX_PROFILE_OUT, including GC stats and event-loop-delay monitoring; flushed to<runDir>/<pid>_<role>.jsonon exit.benchmarks/profile-run.mtstoolchain for running profiled workloads.Perf tweaks
create_dir_allin file ops.server.listen()— overlaps the require/transpile work with the host's connect + load-message round-trip. Host spawns the worker withcwd: rootso eager loading runs in the correct directory; the load handler awaits the in-flight promise whenpluginPathmatches.HashPlanner,HashPlanInspector,TaskHasher, andinputsmap types tohashbrown::HashMapfor cheaper hashing in hot paths.readProjectsConfigurationFromProjectGraphon theProjectGraphinstance via aWeakMap; cache dotenv file parses by(path, mtime)so repeated reads of the same unchanged.envskip read + parse (variable expansion still runs live per-task).moduleResolution: nodenext/module: nodenext) so itscustomConditionsresolve cleanly from source — fixes a pre-existingTS5098on the.tsworker path that CI didn't catch (CI runs the built.jsworker).Notes on overlap with master
Several master PRs that landed during this branch's life optimize adjacent areas — #35172 (warm cache for task execution), #35326 (
nx --versionlazy-load), and #35251 (native TS type definitions). The perf-logging fast-path that earlier versions of this branch carried is now master's; the remaining work here layers on top. Benchmark numbers should be re-baselined against current master before being cited.Related Issue(s)
N/A — performance / tooling.