1829433 - GeckoProfilerEntryMarker takes time in js::RunScript even when Firefox profiler isn't running

Status: NEW

(Core :: Gecko Profiler, defect, P2)

Description

[Olli Pettay [:smaug][[e-mail]]]

I wouldn't expect to see Firefox profiler stuff in profiles generated using other profilers
https://share.firefox.dev/3N4yArP

Comment 1

[Nazım Can Altınova [:canova][:canaltinova on phabricator]]

Hey Adam, could you take a look at this too? We can also look at it together.

Comment 2

[Olli Pettay [:smaug][[e-mail]]]

Shows up quite a bit on Mac too, TodoMVC-Angular
https://profiler.firefox.com/public/ezvnmmr6ethwy6xpvj85cbbwhr42947stqwk46r/flame-graph/?globalTrackOrder=0wf&hiddenGlobalTracks=0w79wf&profileName=Firefox%20TodoMVC-Angular-BrowserMacM1-Jun5-FxWithSortedListeners&symbolServer=http%3A%2F%2F127.0.0.1%3A3001%2F0nax7lx48s0cfz9wk7a9mjdf89iilbwn5xjlih5&thread=8&transforms=fs-m--async%2C-sync~df-3123~df-3122~df-3709~df-8928~df-15788~df-1286~df-37717~df-9590~df-5938~df-22113~df-890~df-8768~df-24016~df-24359~df-23596~df-911~df-2021~df-3118~df-2985~df-8566~df-8866~df-8865~df-10928~df-13206~df-4327~df-2228~df-2274~df-1703~df-1727~df-1728~df-11220~df-2721~df-8373~df-18402~df-9668~df-46658~df-46481~df-12148~df-2781~df-18201~df-8350~df-44963~df-14950~df-19791~df-34494~df-35701~ff-4998~rec-4998~df-6481~df-5000~df-7790&v=9

Comment 3

[Adam Brouwers-Harries [:aabh] [he/him] ⌚GMT]

So the issue here is that the GeckoProfilingEntryMarker needs to run while the profiler isn't running, as it keeps track (for the profiler) of certain aspects of the state of the JS interpreter - specifically the label stack, and interpreter stack. (more info at js/public/ProfilingStack.h)

This would be fine if it was a lightweight operation, but as the js + label frames need to be in a consistent state while the profiler is running, it uses a lot of atomic operations.

For example, pushLabelFrame here does a number of atomic operations to manipulate the stack, and while modifying the stack pointer: https://searchfox.org/mozilla-central/rev/3b707c8fd7e978eebf24279ee51ccf07895cfbcb/js/public/ProfilingStack.h#411

I'm investigating whether or not we can do something different when the profiler isn't running. From what I understand, the concurrency is required while the profiler is sampling, but I don't see why we would need the "protection" before/after a profiling session. I think it was Markus who originally wrote this code, so he might have some ideas as to how (or whether!) we could do this.

Comment 4

[Markus Stange [:mstange]]

Rather than reducing the time spent in GeckoProfilingEntryMarker, I think it would be better to reduce the number of calls to it. Most of that work is already happening, in bug 1829411: We're only ending up in this code because we have frequent JIT -> C++ -> JIT calls, and bug 1829411 will turn those into JIT -> JIT calls.

What I'm curious about is why we need an "interpreter" profiling stack frame in these cases where we end up calling into JIT code - I'd have expected the JS frame of the called function to be filled in via JIT stack walking and not via the interpreter stack. js::RunScript is used for calls into both interpreted JS functions and JITted JS functions, so I wonder why we're pushing the profiling stack frame here and not in interpreter-specific code.

Also, I'm not sure if avoiding atomic operations here will actually improve anything. The atomic ordering we're using is ReleaseAcquire, which is what you get on x86 by default anyway.

Comment 5

[Adam Brouwers-Harries [:aabh] [he/him] ⌚GMT]

I think it would be better to reduce the number of calls to it

Ah, I wasn't aware of this effort, thanks for looping me in! I'll hold off on major changes then, as it may not end up being that much of a performance improvement if this code cools down.

so I wonder why we're pushing the profiling stack frame here and not in interpreter-specific code.

I'm unfamiliar with how we merge stack walking and the profiling stack, so I'm not sure about that. I could imagine that it's non-trivial, and so having a stack entry might help even if we can get info via stack walking.

The atomic ordering we're using is ReleaseAcquire, which is what you get on x86 by default anyway.

We seem to be using SequentiallyConsistent for the actual stack frames, which may be slower on x86 (there's an interesting comment at the top of the file regarding this). Additionally, this could be slow on ARM architecture or more relaxed memory architectures.

Comment 6

[Nazım Can Altınova [:canova][:canaltinova on phabricator]]

Thanks for the investigation Adam and thanks Markus for the additinal information about the current work happening in bug 1829411. It looks like that work has recently landed. Deprioritising this one until we can measure the new impact again.

Comment 7

[Adam Brouwers-Harries [:aabh] [he/him] ⌚GMT]

:smaug, are you still seeing this taking time during profiles? Based on the previous discussion, it looks like the underlying cause might have been addressed in another bug.

Comment 8

[Olli Pettay [:smaug][[e-mail]]]

Looks like it is still there a tiny bit https://share.firefox.dev/4f75xOP