1356694 - Profile capture fails with MOZ_PROFILER_STARTUP=1

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect)

Description

[Edouard Oger [:eoger]]

I'm trying to measure what happens during the startup of the first window.
The profiler front-end I'm using is the one at perf-html.io, on a firefox artifact build on macos.
Per [0], it seems like I need to set MOZ_PROFILER_STARTUP to 1, which I did.
When this option is set and I when I press ctrl+shift+2, I'm getting an error:

> console.error: geckoprofiler:
>   Message: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIProfiler.getProfileDataAsync]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource://jid0-edalmuivkozlouyij0lpdx548bc-at-jetpack/lib/profiler.js :: getProfile :: line 76"  data: no]
>   Stack:
>     getProfile@resource://gre/modules/commonjs/toolkit/loader.js -> resource://jid0-edalmuivkozlouyij0lpdx548bc-at-jetpack/lib/profiler.js:76:12
> collectProfile@resource://gre/modules/commonjs/toolkit/loader.js -> resource://jid0-edalmuivkozlouyij0lpdx548bc-at-jetpack/lib/ui-controller.js:95:26
> onPress@resource://gre/modules/commonjs/toolkit/loader.js -> resource://jid0-edalmuivkozlouyij0lpdx548bc-at-jetpack/index.js:60:18
> onKeypress@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/keyboard/hotkeys.js:102:7
> emitOnObject@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/event/core.js:110:7
> emit@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/event/core.js:86:38
> handleEvent@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/commonjs/sdk/keyboard/observer.js:53:5

[0]: https://developer.mozilla.org/en-US/docs/Mozilla/Performance/Profiling_with_the_Built-in_Profiler#Profiling_Firefox_Startup

Comment 1

[Edouard Oger [:eoger]]

In platform.cpp, profiler_init() calls NotifyProfilerStarted().
I found 2 problems:
- NotifyProfilerStarted() calls GetObserverService() whichs returns null so we bail.
- CrossProcessProfilerController (who should start the profiler) starts listening after we should be sending that notification.

I may be completely wrong of course, I don't usually fiddle with the platform.

Comment 2

[Markus Stange [:mstange]]

Thanks for debugging this! I think I can take it from here.

Comment 3

[Markus Stange [:mstange]]

This is a regression from bug 1350967.

nsProfiler::GetProfileDataAsync returns NS_ERROR_FAILURE because it doesn't have an mGatherer.

nsProfiler::ProfilerStart() is the only place where we create mGatherer. I think we also need to do it in the nsProfiler constructor, if the profiler is already running.

Nick, I'm going to head out, feel free to take this bug.

Comment 4

[Nicholas Nethercote [inactive]]

Attachment: Create a ProfileGatherer in nsProfiler() if MOZ_PROFILER_STARTUP is set

I wish we had a test for MOZ_PROFILER_STARTUP, but I'm struggling to think how
to do it.

Comment 7

[Markus Stange [:mstange]]

Comment on attachment 8859864 [details] [diff] [review]
Create a ProfileGatherer in nsProfiler() if MOZ_PROFILER_STARTUP is set

Review of attachment 8859864 [details] [diff] [review]:
-----------------------------------------------------------------

::: tools/profiler/gecko/nsProfiler.cpp
@@ +39,5 @@
>  {
> +  // If MOZ_PROFILER_STARTUP is set, the profiler will already be running. We
> +  // need to create a ProfileGatherer in that case.
> +  if (getenv("MOZ_PROFILER_STARTUP")) {
> +    MOZ_RELEASE_ASSERT(profiler_is_active());

I think the assertion can fail if the following happens:
 - MOZ_PROFILER_STARTUP was set when launching the main process and got inherited down to the content process
 - nobody has created an nsIProfiler instance in the content process yet
 - The profiler is stopped in the parent process, which triggers calls to ContentParent::SendStopProfiler
 - profiler_stop is called in the content process from ContentChild::RecvStopProfiler
 - the user opens the performance devtools which will create an nsIProfiler instance in the content process

I think this illustrates a problem with our current responsibility split between nsProfiler and the profiler_* functions. nsProfiler thinks it's in charge, but it's really not, because it can be bypassed.

I think we should teach nsProfiler that it's not in control of the profiler state, and make it listen for the "profiler-started" and "profiler-stopped" notifications and create + destroy mGatherer from those. Or maybe having mGatherer should not be tied to profiler activeness and nsProfiler should have a ProfileGatherer at all times.

Comment 8

[Nicholas Nethercote [inactive]]

Attachment: Create a ProfileGatherer in nsProfiler() if the profiler is active

Updated version.

Comment 9

[Nicholas Nethercote [inactive]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/7952b06fc0d0735e1ebb360cbf557ef704482ca1
Bug 1356694 - Create a ProfileGatherer in nsProfiler() if the profiler is active. r=mstange.

Comment 10

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/7952b06fc0d0