fix(time-profiler): serialize before clearing the source mapper in stop()#342
fix(time-profiler): serialize before clearing the source mapper in stop()#342mcollina wants to merge 2 commits into
Conversation
…op() The legacy time profiler stop() called handleStopRestart()/ handleStopNoRestart() before serializing the profile. handleStopNoRestart() clears gSourceMapper (and disposes the profiler), so serialization ran with an undefined source mapper: transpiled frames (e.g. TypeScript) were left pointing at the generated .js files instead of being mapped back to their original sources. Move serialization ahead of the teardown so the source mapper is still set, matching stopV2(), which serializes inside the stopAndCollect callback while gSourceMapper is still defined. This restores the behaviour of 5.14.1, whose stop() serialized via stopAndCollect before teardown. Add a regression test asserting stop() passes the source mapper to serializeTimeProfile. Assisted-by: Claude Code:claude-opus-4-8 Signed-off-by: Matteo Collina <hello@matteocollina.com>
szegedi
left a comment
There was a problem hiding this comment.
Thanks for finding this!
FWIW, we're switching back to "legacy" stop because with stopV2 we had a larger overlap between two profiling sessions being active which triggered crashes due to a race condition in V8 (see my report and also it was fixed since, but since it's been present for forever, we can't use stopV2 until all non-EOL Node.js versions have the fix.)
Anyhow, I have a nit about this – in the restart case, I still want the profiler to perform the restart early; aside from that, looks good!
|
|
||
| const profile = gProfiler.stop(restart); | ||
| if (restart) { | ||
| handleStopRestart(); |
There was a problem hiding this comment.
We definitely want to – at least for the restart case – to stop/start the profiler before we serialize, as then the serialization work itself is captured in the next profile; we like to be honest like that and let the users observe its cost :-) Arguably, for the plain stop case it doesn't matter. I guess maybe we'll need to blow up this nice encapsulation of handleStop[No]Restart() here and have an early stop-start for the restart case (which should not dispose of source maps, right?) and a late stop for for no-restart case.
Per review feedback, the profiler restart should still happen before serialization so the cost of serialization is captured in the next profile. Only handleStopNoRestart() clears gSourceMapper, so only that path needs to run after serialization; handleStopRestart() stays early and does not touch the source mapper. Extend the regression test to also assert the source mapper is preserved on the restart (stop(true)) path. Assisted-by: Claude Code:claude-opus-4-8 Signed-off-by: Matteo Collina <hello@matteocollina.com>
|
Should be fixed, lmk |
Summary
The legacy time-profiler
stop()serializes the profile after tearing down the profiler state, so source maps are silently dropped. CPU profiles taken viastart()+stop()with asourceMapperno longer map transpiled frames (e.g. TypeScript) back to their original sources — they point at the generated.jsfiles instead. This is a regression introduced between5.14.1and5.14.3/5.14.4.Root cause
In
ts/src/time-profiler.ts,stop()runshandleStopNoRestart()(which setsgSourceMapper = undefinedand disposes the profiler) before callingserializeTimeProfile(profile, gIntervalMicros, gSourceMapper, …):Because
gSourceMapperisundefinedat serialization time,serializeTimeProfilenever callssourceMapper.mappingInfo(...), and frames keep their generated-file locations.stopV2()is unaffected: it serializes inside thestopAndCollectcallback, which runs whilegSourceMapperis still set. In5.14.1,stop()itself used thestopAndCollectpath, so the mapper was still set at serialization time — hence this is a regression.Fix
Move serialization ahead of the teardown so the source mapper is still set, matching
stopV2()(and the currentmainbranch, which already serializes before clearing). Theprofileobject returned by the nativestop()does not depend on the profiler still being alive, so this reordering is safe.Reproduction
With
5.14.4:sourceMapper.mappingInfois called 0 times on5.14.4vs 26 times on5.14.1for the same workload. Usingtime.stopV2()instead oftime.stop()produces the correctly mapped profile, confirming the diagnosis.Test
Added a deterministic regression test in
test-time-profiler.ts(underprofile (w/ stubs)): it stubsserializeTimeProfileand assertsstop()passes the source mapper through. It fails on the current code (undefined !== {}) and passes with this fix.Notes
Issues are disabled on this repository, so I'm opening this as a PR with the fix. Happy to adjust the approach or test as preferred.