Make the profiler env vars MOZ_PROFILER_ENTRIES and MOZ_PROFILER_INTERVAL specific to startup

RESOLVED FIXED in Firefox 55

Status

()

Core
Gecko Profiler
RESOLVED FIXED
2 months ago
2 months ago

People

(Reporter: mstange, Assigned: njn)

Tracking

(Blocks: 1 bug)

Trunk
mozilla55
Points:
---

Firefox Tracking Flags

(firefox55 fixed)

Details

Attachments

(1 attachment, 1 obsolete attachment)

(Reporter)

Description

2 months ago
Currently, these environment variables apply every time the profiler is started throughout the lifetime of the process, and they overwrite any value that was supplied to the arguments of nsIProfiler::StartProfiler / profiler_start.

However, these environment variables are only really needed for startup profiling. So I think we should rename them to MOZ_PROFILER_STARTUP_ENTRIES / MOZ_PROFILER_STARTUP_INTERVAL and only respect them if we start the profiler in profiler_init.
(Assignee)

Comment 1

2 months ago
By "startup profiling" do you mean setting MOZ_PROFILER_STARTUP? I don't understand the various ways the profile can start up. When is startup profiling used? Does the profiler add-on use it?
Flags: needinfo?(mstange)
(Reporter)

Comment 2

2 months ago
(In reply to Nicholas Nethercote [:njn] from comment #1)
> By "startup profiling" do you mean setting MOZ_PROFILER_STARTUP?

Yes, exactly.

> I don't understand the various ways the profile can start up. When is startup
> profiling used? Does the profiler add-on use it?

At the moment, startup profiling is only used when you manually set the MOZ_PROFILER_STARTUP environment variable when you launch Firefox from the command line. This was last done successfully in bug 1312373 comment 11.

The old add-on had a button that would restart Firefox with MOZ_PROFILER_STARTUP set, but the new add-on doesn't have such a button yet, see https://github.com/devtools-html/Gecko-Profiler-Addon/issues/31 .

When the add-on initializes, it also starts the profiler: https://github.com/devtools-html/Gecko-Profiler-Addon/blob/a23ac75241af1f1f06c0b625e199da6f4721e3fa/index.js#L224
It just calls nsIProfiler.startProfiler as usual. Add-on initialization happens much later during startup than profiler_init, though, so this automatic starting of the profiler is not very useful when you want to know what happens during early startup - you'll have to use MOZ_PROFILER_STARTUP for that.
Flags: needinfo?(mstange)
(Assignee)

Comment 3

2 months ago
Created attachment 8849811 [details] [diff] [review]
Make the env vars MOZ_PROFILER_{ENTRIES,INTERVAL} specific to startup

The patch also renames profiler_usage() as PrintUsageThenExit().
Attachment #8849811 - Flags: review?(mstange)
(Assignee)

Updated

2 months ago
Assignee: nobody → n.nethercote
Status: NEW → ASSIGNED
(Assignee)

Comment 4

2 months ago
With this patch applied and the following env vars:

> MOZ_LOG="prof:3" MOZ_PROFILER_STARTUP= MOZ_PROFILER_STARTUP_INTERVAL=2 MOZ_PROFILER_STARTUP_ENTRIES=999999

Here's the output I get when I simply start the browser with the profiler
add-on installed.

> [Main Thread]: I/prof [12430] profiler_init
> [Main Thread]: I/prof [12430] - MOZ_PROFILER_STARTUP is set
> [Main Thread]: I/prof [12430] - MOZ_PROFILER_STARTUP_ENTRIES = 999999
> [Main Thread]: I/prof [12430] - MOZ_PROFILER_STARTUP_INTERVAL = 2
> [Main Thread]: I/prof [12430] locked_profiler_start
> [Main Thread]: I/prof [12430] - entries  = 999999
> [Main Thread]: I/prof [12430] - interval = 2.00
> [Main Thread]: I/prof [12430] - feature  = js
> [Main Thread]: I/prof [12430] - feature  = leaf
> [Main Thread]: I/prof [12430] - feature  = stackwalk
> [Main Thread]: I/prof [12430] - feature  = threads
> [Main Thread]: I/prof [12430] - threads  = GeckoMain
> [Main Thread]: I/prof [12430] - threads  = Compositor
> [Main Thread]: I/prof [12481] profiler_init
> [Main Thread]: I/prof [12481] - MOZ_PROFILER_STARTUP is set
> [Main Thread]: I/prof [12481] - MOZ_PROFILER_STARTUP_ENTRIES = 999999
> [Main Thread]: I/prof [12481] - MOZ_PROFILER_STARTUP_INTERVAL = 2
> [Main Thread]: I/prof [12481] locked_profiler_start
> [Main Thread]: I/prof [12481] - entries  = 999999
> [Main Thread]: I/prof [12481] - interval = 2.00
> [Main Thread]: I/prof [12481] - feature  = js
> [Main Thread]: I/prof [12481] - feature  = leaf
> [Main Thread]: I/prof [12481] - feature  = stackwalk
> [Main Thread]: I/prof [12481] - feature  = threads
> [Main Thread]: I/prof [12481] - threads  = GeckoMain
> [Main Thread]: I/prof [12481] - threads  = Compositor
> [Main Thread]: I/prof [12481] profiler_start            <-- ???
> [Main Thread]: I/prof [12481] locked_profiler_stop
> [Main Thread]: I/prof [12481] locked_profiler_start
> [Main Thread]: I/prof [12481] - entries  = 999999
> [Main Thread]: I/prof [12481] - interval = 2.00
> [Main Thread]: I/prof [12481] - feature  = js
> [Main Thread]: I/prof [12481] - feature  = leaf
> [Main Thread]: I/prof [12481] - feature  = stackwalk
> [Main Thread]: I/prof [12481] - feature  = threads
> [Main Thread]: I/prof [12481] - threads  = GeckoMain
> [Main Thread]: I/prof [12481] - threads  = Compositor

It looks reasonable to start with -- two profiler_init() calls, one for the
parent (12430), one for the child (12481). Both of them use the entries and
interval values from the env vars as expected.

But then the child process calls profiler_start() again, which is surprising,
and doesn't happen when MOZ_PROFILER_STARTUP is undefined. This makes the
profiler stop and restart.

Furthermore, entries and interval are 999999 and 2.00 on this restart, but
profiler_init() is not involved, so they can't have been read from the env
vars. This suggests that the profiler add-on obtained the prior start
parameters and restarted with them.

mstange, does this look like you'd expect?
Flags: needinfo?(mstange)
(Assignee)

Comment 5

2 months ago
Comment on attachment 8849811 [details] [diff] [review]
Make the env vars MOZ_PROFILER_{ENTRIES,INTERVAL} specific to startup

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

Hmm, I need to fix up some Android and Talos stuff.
Attachment #8849811 - Flags: review?(mstange)
(Reporter)

Comment 6

2 months ago
The unexpected profiler_start call is triggered by this: http://searchfox.org/mozilla-central/source/dom/ipc/ContentParent.cpp#1329

We're launching a child process while the parent process is being profiled, so we tell the new process that it should also profile itself.
Not sure what to do about the unfortunate clearing of the buffer.
Flags: needinfo?(mstange)
(Reporter)

Comment 7

2 months ago
Hmm, so we have two ways to start the profiler at the beginning of a content process, and they conflict with each other. Maybe we can unify them. For example, instead of using SendStartProfiler, we could do the following: When launching a child process, if the profiler is running in the parent, launch the child process with the appropriate MOZ_PROFILER_STARTUP* env variables. And if the profiler is not running in the parent, unset any MOZ_PROFILER_STARTUP* env vars for the new child process.

Blindly inheriting the env vars into child processes is not a good idea anyway. If you use startup profiling, you usually wait for startup to finish, grab a profile, and stop the profiler. But if a new child process is launched after this point, with the current setup, it will enable startup profiling for itself even though Firefox startup is already over.
(Assignee)

Comment 8

2 months ago
Thank you for the explanation. This is clearly a pre-existing problem with MOZ_PROFILER_STARTUP and can be fixed in a follow-up.
(Reporter)

Comment 9

2 months ago
Absolutely.
(Assignee)

Comment 10

2 months ago
Created attachment 8850290 [details] [diff] [review]
Make the env vars MOZ_PROFILER_{ENTRIES,INTERVAL} specific to startup

The patch also renames profiler_usage() as PrintUsageThenExit().
Attachment #8850290 - Flags: review?(mstange)
(Assignee)

Updated

2 months ago
Attachment #8849811 - Attachment is obsolete: true
(Reporter)

Comment 11

2 months ago
Comment on attachment 8850290 [details] [diff] [review]
Make the env vars MOZ_PROFILER_{ENTRIES,INTERVAL} specific to startup

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

Thanks! Sorry for the delay.

::: tools/profiler/core/platform-linux-android.cpp
@@ +556,5 @@
>    // So we free them later, but we don't want to change the const char**
>    // declaration in profiler_start. Annoying but ok for now.
>    const char* threadNames[10];
>    const char* features[10];
>    const char* profilerConfigFile = "/data/local/tmp/profiler.options";

Thanks for putting this code under my nose again. It's not needed, I've filed bug 1351946.
Attachment #8850290 - Flags: review?(mstange) → review+
(Assignee)

Comment 12

2 months ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/c3653faaac8aad50623a0ed57bcc77d8a5bdc7f7
Bug 1348024 - Make the env vars MOZ_PROFILER_{ENTRIES,INTERVAL} specific to startup. r=mstange.

Comment 13

2 months ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/c3653faaac8a
Status: ASSIGNED → RESOLVED
Last Resolved: 2 months ago
status-firefox55: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
You need to log in before you can comment on or make changes to this bug.