Closed Bug 1356694 Opened 7 years ago Closed 7 years ago

Profile capture fails with MOZ_PROFILER_STARTUP=1


(Core :: Gecko Profiler, defect)

Not set



Performance Impact high
Tracking Status
firefox-esr52 --- unaffected
firefox53 --- unaffected
firefox54 --- unaffected
firefox55 --- fixed


(Reporter: eoger, Assigned: n.nethercote)



(Keywords: regression)


(1 file, 1 obsolete file)

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, 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

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.
Thanks for debugging this! I think I can take it from here.
Assignee: nobody → 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.
Blocks: 1350967
Flags: needinfo?(n.nethercote)
Keywords: regression
OS: Unspecified → All
Hardware: Unspecified → All
Version: unspecified → Trunk
I wish we had a test for MOZ_PROFILER_STARTUP, but I'm struggling to think how
to do it.
Attachment #8859864 - Flags: review?(mstange)
Assignee: mstange → n.nethercote
Flags: needinfo?(n.nethercote)
Summary: Cannot get profile data → Profile capture fails with MOZ_PROFILER_STARTUP=1
Whiteboard: [qf]
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.
Whiteboard: [qf] → [qf:p1]
Attachment #8859864 - Attachment is obsolete: true
Attachment #8859864 - Flags: review?(mstange)
Attachment #8860213 - Flags: review?(mstange) → review+
Bug 1356694 - Create a ProfileGatherer in nsProfiler() if the profiler is active. r=mstange.
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Performance Impact: --- → P1
Whiteboard: [qf:p1]
You need to log in before you can comment on or make changes to this bug.