Closed Bug 1067547 Opened 6 years ago Closed 4 years ago

XRE_InitChildProcess calls profiler_init() before NS_LogInit()

Categories

(Core :: XPCOM, defect)

Product:
Core
Component:
XPCOM
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla52
Tracking Flags:
Tracking Status
firefox52 --- fixed

People

(Reporter: mccr8, Assigned: tromey)

Details

Attachments

(2 files, 3 obsolete files)

Bug 1067547 - add more uses of MOZ_COUNT_CTOR to tools/profiler;
58 bytes, text/x-review-board-request
benjamin
: review+
Details
Bug 1067547 - unify ScopedLogging implementations and use in nsEmbedFunctions;
58 bytes, text/x-review-board-request
benjamin
: review+
Details 
I was looking into what is causing this:
  WARNING: XPCOM objects created/destroyed from static ctor/dtor

It looks like that in a child process starting up the profiler before we do NS_LogInit(), this causes the deadlock detector to start doing XPCOM stuff, which makes the XPCOM logging sad.  I don't see a similar problem in the parent process for whatever reason, even though it also sets up the profiler before NS_LogInit().  I don't know if this is worth investigating or fixing but I figured I'd at least file a bug.
XPCOM-using processes call profiler_init from within NS_InitXPCOM, which is well after we've initialized logging/leak detection: http://mxr.mozilla.org/mozilla-central/source/xpcom/build/nsXPComInit.cpp#485

We seem to be *also* initializing profiling much earlier in various startup paths, with blame leading back to bug 872496. In Firefox, NS_InitLogging is already called before XRE_main for various things like local files, but we shouldn't rely on that.  We should either make profiling imply another logging Init/Finish pair, or we should change the various places touched by http://hg.mozilla.org/mozilla-central/rev/383bed640c7b to move the NS_LogInit call before we start the profiler.
I tripped across this problem while working on bug 1047124.

In that bug, I tried adding MOZ_COUNT_* calls to various profiler-related
classes, e.g., PseudoStack.  This lead to more apparent leaks being reported,
because the profiler is initialized before logging.
See https://bugzilla.mozilla.org/show_bug.cgi?id=1047124#c31

I have a patch that I'll attach shortly. It went through "try"
(it was part of the patch in https://bugzilla.mozilla.org/show_bug.cgi?id=1047124#c33).
This patch arranges for NS_LogInit to be called before profiler_init.
This makes it possible to track possible memory leaks coming from the
profiler.  It also adds some MOZ_COUNT_* markup to various profiler
objects; these were sanity checks from bug 1047124.

I believe I tracked down all the NS_LogInit calls that matter.

For XRE_InitChildProcess I introduced a new ScopedLogging.  This class
already appears in several places in the source.  I think it would be
better to have a single definition of it, but I did not know where to
put it.

Also in XRE_InitChildProcess, the use of the RAII style means that
XRE_DeinitCommandLine will be called in a different order relative to
profiler_shutdown and NS_LogTerm.  This did not seem to cause problems
on "try" and seemed safe to me, but if it is not ok, it is readily
solved by introducing a new scope.
Attachment #8518980 - Flags: review?(benjamin)
Comment on attachment 8518980 [details] [diff] [review]
call NS_LogInit before profiler_init

You could probably put ScopedLogging in nsXPCOM.h.
Attachment #8518980 - Flags: review?(benjamin) → review+
Assignee: nobody → ttromey
Here's an updated version that unifies the various copies of
ScopedLogging into nsXPCOM.h.
Attachment #8518980 - Attachment is obsolete: true
Rebased for changes to bug 1047124; and moved one MOZ_COUNT_DTOR call
from that patch into this one.
Attachment #8526304 - Attachment is obsolete: true
Comment on attachment 8535079 [details] [diff] [review]
call NS_LogInit before profiler_init

I wasn't sure if the r+ carried over, since I've moved ScopedLogging
into nsXPCOM.h; so I'm requesting another review to be on the safe side.
Thanks!
Attachment #8535079 - Flags: review?(benjamin)
Attachment #8535079 - Flags: review?(benjamin) → review+
Keywords: checkin-needed
What about all the B2G debug leaks on the Try run?
Keywords: checkin-needed
(In reply to Ryan VanderMeulen [:RyanVM UTC-5] from comment #11)
> What about all the B2G debug leaks on the Try run?

I will look.
I had thought those were pre-existing but I was wrong about that.
Consider this successful try build:
https://tbpl.mozilla.org/?tree=Mozilla-Inbound&rev=78d01e271d8a

The B2G ICS Emulator Debug M(1) full log is here:
https://tbpl.mozilla.org/php/getParsedLog.php?id=54852690&tree=Mozilla-Inbound&full=1

If you search for leakcheck you will see a bunch of existing leak reports:

23:44:25     INFO -  TEST-INFO | leakcheck | default process: leaked 1 CameraPreferences (12 bytes)
23:44:25     INFO -  TEST-INFO | leakcheck | default process: leaked 1 Composer2D (8 bytes)
23:44:25     INFO -  TEST-INFO | leakcheck | default process: leaked 3 CondVar (72 bytes)
[...]

Something must be different in my run; I didn't look yet, but I thought
I'd note this in the bug to make it simpler to find again.
The difference (of course) is from the patch; the failing run mentions:

13:57:38     INFO -  TEST-INFO | leakcheck | default process: leaked 2 PseudoStack (32896 bytes)
I dug some more and the issue is that this patch changes the leak total
to 38048 bytes leaked, but the default leak threshold is 5180 bytes.

I'm reluctant to bump the leak threshold for this patch.  This patch is
a cleanup and a safety measure, but doesn't catch any actual leaks (they
were fixed as a prerequisite to this).  On the other hand, bumping
the leak threshold might result in new leaks going unnoticed.

I think this is related to bug 1038943 and its dependencies.

My inclination is to mark this bug as blocked by some other bug, pending
a fix, I think, to b2g leak-checking.  I'm not sure which bug this
might be.  Maybe bug 1070068?
I finally got back to rebasing this patch.

The main reason for this patch was landed in bug 1172138.
So, one possible solution here would be to mark this as a dup.

However, I think the remaining bits -- adding more uses of MOZ_COUNT_CTOR to the
profiler, and unifying the ScopedLogging implementations -- are reasonable cleanups.

Do reviews ever expire?  I don't know, so I'll re-request review.
Attachment #8535079 - Attachment is obsolete: true
Comment on attachment 8794914 [details]
Bug 1067547 - add more uses of MOZ_COUNT_CTOR to tools/profiler;

https://reviewboard.mozilla.org/r/81138/#review80336
Attachment #8794914 - Flags: review?(benjamin) → review+
Comment on attachment 8794915 [details]
Bug 1067547 - unify ScopedLogging implementations and use in nsEmbedFunctions;

https://reviewboard.mozilla.org/r/81140/#review80338
Attachment #8794915 - Flags: review?(benjamin) → review+
Pushed by ttromey@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/326e6c945c37
add more uses of MOZ_COUNT_CTOR to tools/profiler; r=bsmedberg
https://hg.mozilla.org/integration/autoland/rev/e8f4dc9c44cc
unify ScopedLogging implementations and use in nsEmbedFunctions; r=bsmedberg
https://hg.mozilla.org/mozilla-central/rev/326e6c945c37
https://hg.mozilla.org/mozilla-central/rev/e8f4dc9c44cc
Status: NEW → RESOLVED
Closed: 4 years ago
status-firefox52: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla52
You need to log in before you can comment on or make changes to this bug.