1774848 - Missing JS frames in the profiler stack around AsyncFunctionResume

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect, P1)

Description

[Markus Stange [:mstange]]

Example profile: https://share.firefox.dev/3xBWKk5

When async functions are resumed, the profiler often doesn't show which function is being resumed. It often only shows AsyncFunctionNext and InterpretGeneratorResume and no other JS frames.

For example, in this stack, there's a JS function that's calling JSON.parse(), but I don't know where that call to JSON.parse() is:

mozilla::PromiseJobRunnable::Run(mozilla::AutoSlowOperation&)
mozilla::dom::PromiseJobCallback::Call(char const*)
mozilla::dom::PromiseJobCallback::Call(mozilla::ErrorResult&, char const*, mozilla::dom::CallbackObject::ExceptionHandling, JS::Realm*)
mozilla::dom::MozJSActorCallback::Call(mozilla::dom::BindingCallContext&, JS::Handle<JS::Value>, mozilla::ErrorResult&)
JS::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>)
js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason)
InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason)
js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason)
CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&)
PromiseReactionJob(JSContext*, unsigned int, JS::Value*)
AsyncFunctionPromiseReactionJob(JSContext*, JS::Handle<PromiseReactionRecord *>)
AsyncFunctionResume(JSContext*, JS::Handle<js::AsyncFunctionGeneratorObject *>, ResumeKind, JS::Handle<JS::Value>)
js::CallSelfHostedFunction(JSContext*, JS::Handle<js::PropertyName *>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>)
js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason)
InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason)
js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason)
js::RunScript
js::RunScript(JSContext*, js::RunState&)
AsyncFunctionNext
js::RunScript
InterpretGeneratorResume
0x105bf0a3b10
js::jit::InterpretResume(JSContext*, JS::Handle<JSObject *>, JS::Value*, JS::MutableHandle<JS::Value>)
js::CallSelfHostedFunction(JSContext*, JS::Handle<js::PropertyName *>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>)
js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason)
InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason)
js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason)
js::RunScript(JSContext*, js::RunState&)
Interpret(JSContext*, js::RunState&)
js::CallFromStack(JSContext*, JS::CallArgs const&)
InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason)
js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason)
CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&)
json_parse(JSContext*, unsigned int, JS::Value*)

There's one unsymbolicated frame in that stack: 0x105bf0a3b10.
The InterpretGeneratorResume frame has category "JavaScript: Interpreter".
The AsyncFunctionNext frame has category "JavaScript: JIT (baseline)".

(This profile was captured on Windows, so the native stack might be missing some frames around JIT code because I think on Windows, the profiler's native stack doesn't take advantage of the new frame pointers yet, and still uses the stack-stitching from bug 1635987.)

Comment 1

[Jan de Mooij [:jandem]]

@Markus: those js::RunScript and InterpretGeneratorResume frames are from the profiler stack I assume. I'd expect those to be inserted after js::jit::InterpretResume, somewhere around the last js::RunScript(JSContext*, js::RunState&).

As for the missing frame, it looks like the C++ interpreter is not pushing a profiler entry for JSOp::Resume. In GeckoProfilerThread::exit we check the stack is balanced, but we only call that if frame->hasPushedGeckoProfilerFrame() so if we don't push an entry when resuming, we don't catch it there.

Good find! I'll take a closer look on Monday...

Comment 2

[Jan de Mooij [:jandem]]

Attachment: Bug 1774848 part 1 - Improve assertion in EnterScript. r?iain!

We push a new InterpreterFrame for generators/async nowadays, so the flag should
never be set.

Comment 3

[Jan de Mooij [:jandem]]

Attachment: Bug 1774848 part 2 - Add testing function and tests for reading the interpreter profiling stack. r?iain!

readGeckoProfilingStack only reads the JIT frames. This adds a similar function
for C++ interpreter frames.

Depends on D149862

Comment 4

[Jan de Mooij [:jandem]]

Attachment: Bug 1774848 part 3 - Push a profiler entry when resuming generators and async functions in the C++ interpreter. r?iain!

Depends on D149863

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/3460120a401e
part 1 - Improve assertion in EnterScript. r=iain
https://hg.mozilla.org/integration/autoland/rev/9e08bd7c3b86
part 2 - Add testing function and tests for reading the interpreter profiling stack. r=iain
https://hg.mozilla.org/integration/autoland/rev/f56ce7a6e251
part 3 - Push a profiler entry when resuming generators and async functions in the C++ interpreter. r=iain

Comment 6

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/3460120a401e
https://hg.mozilla.org/mozilla-central/rev/9e08bd7c3b86
https://hg.mozilla.org/mozilla-central/rev/f56ce7a6e251