Closed
Bug 1346132
Opened 8 years ago
Closed 8 years ago
Fix up logging in the profiler
Categories
(Core :: Gecko Profiler, enhancement)
Core
Gecko Profiler
Tracking
()
RESOLVED
FIXED
mozilla55
Tracking | Status | |
---|---|---|
firefox55 | --- | fixed |
People
(Reporter: n.nethercote, Assigned: n.nethercote)
References
Details
Attachments
(5 files, 1 obsolete file)
(deleted),
patch
|
erahm
:
review+
|
Details | Diff | Splinter Review |
(deleted),
patch
|
erahm
:
review+
jseward
:
review+
|
Details | Diff | Splinter Review |
(deleted),
patch
|
jseward
:
review+
|
Details | Diff | Splinter Review |
(deleted),
patch
|
mstange
:
review+
|
Details | Diff | Splinter Review |
(deleted),
patch
|
jseward
:
review+
|
Details | Diff | Splinter Review |
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•8 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•8 years ago
|
Assignee: nobody → n.nethercote
Status: NEW → ASSIGNED
Updated•8 years ago
|
Attachment #8845787 -
Flags: review?(erahm) → review+
Assignee | ||
Comment 2•8 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•8 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•8 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•8 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 6•8 years ago
|
||
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 7•8 years ago
|
||
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•8 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•8 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•8 years ago
|
Attachment #8849753 -
Attachment is obsolete: true
Assignee | ||
Comment 11•8 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)
Updated•8 years ago
|
Attachment #8849789 -
Flags: review?(mstange) → review+
Updated•8 years ago
|
Attachment #8849859 -
Flags: review?(jseward) → review+
Comment 13•8 years ago
|
||
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 14•8 years ago
|
||
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•8 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.
Assignee | ||
Comment 16•8 years ago
|
||
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•8 years ago
|
||
bugherder |
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
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
You need to log in
before you can comment on or make changes to this bug.
Description
•