1346132 - Fix up logging in the profiler

Status: RESOLVED FIXED

(Core :: Gecko Profiler, enhancement)

Description

[Nicholas Nethercote [inactive]]

The profiler logging has some problems.

- It's a bespoke implementation.

- LUL output is *far* more verbose than other output.

- No PIDs.

- More things could be printed, e.g. profiler_start() params.

Comment 1

[Nicholas Nethercote [inactive]]

Attachment: (part 1) - Initialize Mozilla logging earlier in nsAppRunner.cpp

Preliminary tests indicate this works fine, though I need to do a more
comprehensive try run.

This is a blocker for using MOZ_LOG in the profiler, because without it I can't
call MOZ_LOG in profiler_start(), which is one of the most important places to
have logging, so you can see the start parameters.

Comment 2

[Nicholas Nethercote [inactive]]

Attachment: (part 2) - Remove set_stderr_callback()

It's a very general mechanism for replacing the implementation of
printf_stderr(). But it's only used by the profiler, sparingly, and not in an
important way.

Also, it prevents us from using MOZ_LOG in the profiler, which is something I
want. Because if any code that locks gPSMutex also calls MOZ_LOG, that then
calls printf_stderr(), which calls profiler_log(), which locks gPSMutex, which
deadlocks.

This patch removes set_stderr_callback() altogether.

Comment 3

[Nicholas Nethercote [inactive]]

Attachment: (part 3) - Remove the profiler's bespoke logging system in favour of MOZ_LOG

The profiler will use level 3 (Info) and 4 (Debug) logging, though this patch
only uses level 3. LUL will use level 5 (Verbose) debugging.

The patch also tweaks parts of the the usage message, including adding
MOZ_PROFILER_{STARTUP,SHUTDOWN} to it.

Comment 4

[Nicholas Nethercote [inactive]]

Attachment: (part 4) - Improve the profiler's logging output

This patch adds logging to some important functions that currently lack it.
Thread registration/unregistration is done with DEBUG_LOG because it's
more verbose than the other profiler logging, but less verbose than LUL's
logging.

The patch also scraps the BEGIN/END logging pairs because they bloat the output
for little gain. Now it just logs on function entry.

Comment 5

[Nicholas Nethercote [inactive]]

Here is sample MOZ_LOG="prof:3" output for a single process, for a run that
starts the browser, stops and restarts the profiler, captures a profile, then
quits.

> [Main Thread]: I/prof [22612] profiler_init
> [Main Thread]: I/prof [22612] entries  = 0 (zero means "platform default")
> [Main Thread]: I/prof [22612] interval = 0 ms (zero means "platform default")
> [Main Thread]: I/prof [22612] profiler_start
> [Main Thread]: I/prof [22612] locked_profiler_start
> [Main Thread]: I/prof [22612] - entries  = 1000000
> [Main Thread]: I/prof [22612] - interval = 1.00
> [Main Thread]: I/prof [22612] - feature  = js
> [Main Thread]: I/prof [22612] - feature  = stackwalk
> [Main Thread]: I/prof [22612] - feature  = leaf
> [Main Thread]: I/prof [22612] - feature  = threads
> [Main Thread]: I/prof [22612] - threads  = GeckoMain
> [Main Thread]: I/prof [22612] - threads  = Worker
> [Main Thread]: I/prof [22612] - threads  = Foo
> [Main Thread]: I/prof [22612] profiler_stop
> [Main Thread]: I/prof [22612] locked_profiler_stop
> [Main Thread]: I/prof [22612] profiler_start
> [Main Thread]: I/prof [22612] locked_profiler_start
> [Main Thread]: I/prof [22612] - entries  = 1000000
> [Main Thread]: I/prof [22612] - interval = 1.00
> [Main Thread]: I/prof [22612] - feature  = js
> [Main Thread]: I/prof [22612] - feature  = stackwalk
> [Main Thread]: I/prof [22612] - feature  = leaf
> [Main Thread]: I/prof [22612] - feature  = threads
> [Main Thread]: I/prof [22612] - threads  = GeckoMain
> [Main Thread]: I/prof [22612] - threads  = Worker
> [Main Thread]: I/prof [22612] - threads  = Foo
> [Main Thread]: I/prof [22612] profiler_pause
> [Main Thread]: I/prof [22612] profiler_get_profile_jsobject_async
> [Main Thread]: I/prof [22612] ToJSON
> [Main Thread]: I/prof [22612] StreamJSON
> [Main Thread]: I/prof [22612] profiler_resume
> [Main Thread]: I/prof [22612] profiler_shutdown
> [Main Thread]: I/prof [22612] locked_profiler_stop

Here is sample output for MOZ_LOG="prof:4", which adds thread
registration/unregistration:

> [Unnamed thread 0x7f4c3d86c2c0]: D/prof [20862] profiler_register_thread(Compositor)
> [ImgDecoder #1]: D/prof [20862] profiler_register_thread(ImgDecoder #1)
> [ImgDecoder #2]: D/prof [20862] profiler_register_thread(ImgDecoder #2)
> [ImgDecoder #3]: D/prof [20862] profiler_register_thread(ImgDecoder #3)
> [ImgDecoder #4]: D/prof [20862] profiler_register_thread(ImgDecoder #4)
> [ImageIO]: D/prof [20862] profiler_register_thread(ImageIO)
> ...
> [Socket Thread]: D/prof [20862] profiler_unregister_thread: Socket Thread
> [DNS Resolver #1]: D/prof [20862] profiler_unregister_thread: DNS Resolver #1
> [mozStorage #4]: D/prof [20862] profiler_unregister_thread: mozStorage #4

Comment 6

[Eric Rahm [:erahm]]

Comment on attachment 8849754 [details] [diff] [review]
(part 3) - Remove the profiler's bespoke logging system in favour of MOZ_LOG

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

r=me, just a few minor comments.

::: tools/profiler/core/platform.cpp
@@ +1457,5 @@
>  {
>    MOZ_RELEASE_ASSERT(NS_IsMainThread());
>    MOZ_RELEASE_ASSERT(gPS);
>  
> +  printf(

This should probably be |printf_stderr|.

@@ +1473,5 @@
> +    "  The interval between samples.\n"
> +    "  If unset, platform default is used.\n"
> +    "\n"
> +    "  MOZ_LOG\n"
> +    "  Enables logging. The levels of loggin available are"

nit: logging

@@ +1474,5 @@
> +    "  If unset, platform default is used.\n"
> +    "\n"
> +    "  MOZ_LOG\n"
> +    "  Enables logging. The levels of loggin available are"
> +    "  'prof:3', 'prof:4', 'prof:5'.\n"

Maybe specify that 3 is less verbose, 5 is most verbose.

Comment 7

[Markus Stange [:mstange]]

Comment on attachment 8849753 [details] [diff] [review]
(part 2) - Remove set_stderr_callback()

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

I am sympathetic to the MOZ_LOG problem, and this capability isn't really being used at the moment, so let's remove it for now. We can still add it back (maybe in a different form) once we have a more concrete use case for it.

Comment 8

[Nicholas Nethercote [inactive]]

> > +  printf(
> 
> This should probably be |printf_stderr|.

Usage messages usually go to stdout, which is why I did it this way.

Comment 9

[Nicholas Nethercote [inactive]]

Attachment: (part 2) - Remove set_stderr_callback()

Updated patch: we can remove one of the profiler_log() variants and a
VARARGS_ASSIGN macro, too.

Comment 10

[Nicholas Nethercote [inactive]]

Attachment: (part 5) - Remove ThreadInfo::CanInvokeJS

It's unused.

Comment 11

[Nicholas Nethercote [inactive]]

(In reply to Nicholas Nethercote [:njn] from comment #2)
> Created attachment 8849753 [details] [diff] [review]
> (part 2) - Remove set_stderr_callback()

Argh, I just discovered that set_stderr_callback() is also used by the super-hacky, for-local-debugging-only copy_stderr_to_file() function. kats, you added that in bug 1111407 for B2G -- do you think it's still needed?

If not, I'll remove it. If so, I guess I'll need to keep set_stderr_callback() alive, but not use it from the profiler.

Comment 12

[Kartikaya Gupta (email:[e-mail])]

Kill it with fire!

Comment 13

[Julian Seward [:jseward]]

Comment on attachment 8849755 [details] [diff] [review]
(part 4) - Improve the profiler's logging output

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

Nice cleanup.

::: tools/profiler/core/platform.cpp
@@ +1953,5 @@
>    if (!gPS->IsActive(lock)) {
>      return nullptr;
>    }
>  
> +  UniquePtr<char[]> json = ToJSON(lock, aSinceTime);

What's the reason for removing the straight tailcall here?

Comment 14

[Julian Seward [:jseward]]

Comment on attachment 8849754 [details] [diff] [review]
(part 3) - Remove the profiler's bespoke logging system in favour of MOZ_LOG

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

No comments beyond Eric's.  One place needs s/loggin/logging.

Comment 15

[Nicholas Nethercote [inactive]]

> >    if (!gPS->IsActive(lock)) {
> >      return nullptr;
> >    }
> >  
> > +  UniquePtr<char[]> json = ToJSON(lock, aSinceTime);
> 
> What's the reason for removing the straight tailcall here?

Oh, I originally had a LOG call for the end of the function, but I later removed it. I'll revert this.

Comment 16

[Nicholas Nethercote [inactive]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/13d12cee653291dcbb2e29c32a6a1535fa78a3f6
Bug 1346132 (part 1) - Initialize Mozilla logging earlier in nsAppRunner.cpp. r=erahm.

https://hg.mozilla.org/integration/mozilla-inbound/rev/988b79afb4e31a5ce2cee9a9b5520788f9851a49
Bug 1346132 (part 2) - Remove set_stderr_callback(). r=mstange.

https://hg.mozilla.org/integration/mozilla-inbound/rev/9819cacff56e3ff37759ea19e3999974eb57ce91
Bug 1346132 (part 3) - Remove the profiler's bespoke logging system in favour of MOZ_LOG. r=erahm,jseward.

https://hg.mozilla.org/integration/mozilla-inbound/rev/4d15807711e6013fe7997fe76e10426bec9f3200
Bug 1346132 (part 4) - Improve the profiler's logging output. r=jseward.

https://hg.mozilla.org/integration/mozilla-inbound/rev/627e41422cffcc353003faacd918443bcf2e489c
Bug 1346132 (part 5) - Remove ThreadInfo::CanInvokeJS. r=jseward.

Comment 17

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/13d12cee6532
https://hg.mozilla.org/mozilla-central/rev/988b79afb4e3
https://hg.mozilla.org/mozilla-central/rev/9819cacff56e
https://hg.mozilla.org/mozilla-central/rev/4d15807711e6
https://hg.mozilla.org/mozilla-central/rev/627e41422cff