1348024 - Make the profiler env vars MOZ_PROFILER_ENTRIES and MOZ_PROFILER_INTERVAL specific to startup

Status: RESOLVED FIXED

(Core :: Gecko Profiler, enhancement)

Description

[Markus Stange [:mstange]]

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.

Comment 1

[Nicholas Nethercote [inactive]]

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?

Comment 2

[Markus Stange [:mstange]]

(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.

Comment 3

[Nicholas Nethercote [inactive]]

Attachment: Make the env vars MOZ_PROFILER_{ENTRIES,INTERVAL} specific to startup

The patch also renames profiler_usage() as PrintUsageThenExit().

Comment 4

[Nicholas Nethercote [inactive]]

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?

Comment 5

[Nicholas Nethercote [inactive]]

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.

Comment 6

[Markus Stange [:mstange]]

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.

Comment 7

[Markus Stange [:mstange]]

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.

Comment 8

[Nicholas Nethercote [inactive]]

Thank you for the explanation. This is clearly a pre-existing problem with MOZ_PROFILER_STARTUP and can be fixed in a follow-up.

Comment 9

[Markus Stange [:mstange]]

Absolutely.

Comment 10

[Nicholas Nethercote [inactive]]

Attachment: Make the env vars MOZ_PROFILER_{ENTRIES,INTERVAL} specific to startup

The patch also renames profiler_usage() as PrintUsageThenExit().

Comment 11

[Markus Stange [:mstange]]

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.

Comment 12

[Nicholas Nethercote [inactive]]

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

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/c3653faaac8a