Fix up logging in the profiler

RESOLVED FIXED in Firefox 55

Status

()

enhancement
RESOLVED FIXED
2 years ago
2 years ago

People

(Reporter: njn, Assigned: njn)

Tracking

Trunk
mozilla55
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox55 fixed)

Details

Attachments

(5 attachments, 1 obsolete attachment)

Assignee

Description

2 years ago
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.
Assignee

Comment 1

2 years ago
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.
Attachment #8845787 - Flags: review?(erahm)
Assignee

Updated

2 years ago
Assignee: nobody → n.nethercote
Status: NEW → ASSIGNED

Updated

2 years ago
Attachment #8845787 - Flags: review?(erahm) → review+
Assignee

Comment 2

2 years ago
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.
Attachment #8849753 - Flags: review?(mstange)
Assignee

Comment 3

2 years ago
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.
Attachment #8849754 - Flags: review?(jseward)
Attachment #8849754 - Flags: review?(erahm)
Assignee

Comment 4

2 years ago
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.
Attachment #8849755 - Flags: review?(jseward)
Assignee

Comment 5

2 years ago
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 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.
Attachment #8849754 - Flags: review?(erahm) → review+
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.
Attachment #8849753 - Flags: review?(mstange) → review+
Assignee

Comment 8

2 years ago
> > +  printf(
> 
> This should probably be |printf_stderr|.

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

Comment 9

2 years ago
Updated patch: we can remove one of the profiler_log() variants and a
VARARGS_ASSIGN macro, too.
Attachment #8849789 - Flags: review?(mstange)
Assignee

Updated

2 years ago
Attachment #8849753 - Attachment is obsolete: true
Assignee

Comment 10

2 years ago
It's unused.
Attachment #8849859 - Flags: review?(jseward)
Assignee

Comment 11

2 years ago
(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.
Flags: needinfo?(bugmail)
Kill it with fire!
Flags: needinfo?(bugmail)
Attachment #8849789 - Flags: review?(mstange) → review+
Attachment #8849859 - Flags: review?(jseward) → review+
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?
Attachment #8849755 - Flags: review?(jseward) → review+
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.
Attachment #8849754 - Flags: review?(jseward) → review+
Assignee

Comment 15

2 years ago
> >    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.
You need to log in before you can comment on or make changes to this bug.