1172138 - mozilla_sampler causes 5 instances of "XPCOM objects created/destroyed from static ctor/dtor" on startup

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect)

Description

[Eric Rahm [:erahm]]

Attachment: Call stacks

At least on linux I'm seeing various mozilla_sampler related things causing the message: "XPCOM objects created/destroyed from static ctor/dtor" to be printed when starting firefox on debug builds.

I've attached stack traces at each point. The message is a bit misleading, these don't seem to be static ctor related, rather it's the GeckoProfiler poking xpcom things before xpcom has called NS_LogInit.

I'm not sure what the proper thing to do here is, possibly we need to delay starting the profiler until after xpcom init?

Comment 1

[Andrew McCreight [:mccr8]]

I think this is a dupe of bug 1067547.

Comment 2

[Eric Rahm [:erahm]]

This might be slightly different, these errors are only in the content process.

Comment 3

[Eric Rahm [:erahm]]

Attachment: Call PR_LogInit before profiler_init

Comment 4

[Eric Rahm [:erahm]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=3dd05bc3f05a

Comment 5

[Nathan Froyd [:froydnj]]

Comment on attachment 8616242 [details] [diff] [review]
Call PR_LogInit before profiler_init

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

Your try run looks busted.

Also, it's not clear to me what the XPCOM objects here are.  The stack traces suggest something around mutexes/deadlock detector bits, but I can't see anything calling NS_Log* after several minutes of poking around in that area.  Can you figure out what exactly is triggering that (GDB?) ?

Comment 6

[Eric Rahm [:erahm]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=b62b50ff1b88

Comment 7

[Eric Rahm [:erahm]]

(In reply to Nathan Froyd [:froydnj] [:nfroyd] from comment #5)
> Comment on attachment 8616242 [details] [diff] [review]
> Call PR_LogInit before profiler_init
> 
> Review of attachment 8616242 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Your try run looks busted.

Yes, unfortunately I had another patch that turned on (unrelated) assertions applied from a previous try run.

> Also, it's not clear to me what the XPCOM objects here are.  The stack
> traces suggest something around mutexes/deadlock detector bits, but I can't
> see anything calling NS_Log* after several minutes of poking around in that
> area.  Can you figure out what exactly is triggering that (GDB?) ?

I'll do a GDB run w/o the patch to see what's up.

Comment 8

[Eric Rahm [:erahm]]

This is a bit of a pain to debug, the messages are coming from the child process (this doesn't repro on non-e10s). I managed to get slightly better stacks:

#0  AssertActivityIsLegal () at /home/erahm/dev/mozilla-central/xpcom/base/nsTraceRefcnt.cpp:155
#1  0x00007f6e81a9e186 in NS_LogCtor (aPtr=0x7f6e77d52820, aType=0x7f6e848914e0 "nsTArray_base", aInstanceSize=8)
    at /home/erahm/dev/mozilla-central/xpcom/base/nsTraceRefcnt.cpp:1106
#2  0x00007f6e81b08299 in nsTArray_Impl (this=0x7f6e77d52820) at /home/erahm/dev/mozilla-central/xpcom/build/../glue/nsTArray.h:833
#3  nsTArray (this=0x7f6e77d52820) at /home/erahm/dev/mozilla-central/xpcom/build/../glue/nsTArray.h:1976
#4  OrderingEntry (aResource=0x7f6e77d52800, this=0x7f6e77d52820) at ../../dist/include/mozilla/DeadlockDetector.h:89
#5  mozilla::DeadlockDetector<mozilla::BlockingResourceBase>::Add (this=0x7f6e77d07300, aResource=0x7f6e77d52800)
    at ../../dist/include/mozilla/DeadlockDetector.h:182
#6  0x00007f6e839ab3ac in OffTheBooksMutex (aName=0x7f6e84bf72fd "sRegisteredThreads mutex", this=0x7f6e77d52800)
    at ../../dist/include/mozilla/Mutex.h:47
#7  Mutex (aName=0x7f6e84bf72fd "sRegisteredThreads mutex", this=0x7f6e77d52800) at ../../dist/include/mozilla/Mutex.h:124
#8  Sampler::Startup () at /home/erahm/dev/mozilla-central/tools/profiler/platform.cpp:89
#9  0x00007f6e839ad5e2 in mozilla_sampler_init (stackTop=stackTop@entry=0x7fff1be131c7)
    at /home/erahm/dev/mozilla-central/tools/profiler/platform.cpp:471
#10 0x00007f6e83b62f35 in profiler_init (stackTop=0x7fff1be131c7) at ../../dist/include/GeckoProfilerImpl.h:66
#11 XRE_InitChildProcess (aArgc=5, aArgv=0x7fff1be14758, aGMPLoader=0x0)
    at /home/erahm/dev/mozilla-central/toolkit/xre/nsEmbedFunctions.cpp:354
#12 0x0000000000408173 in content_process_main (argc=5, argv=0x7fff1be14758)
    at /home/erahm/dev/mozilla-central/ipc/app/../contentproc/plugin-container.cpp:236
#13 0x00007f6e80409ec5 in __libc_start_main (main=0x407cf1 <main(int, char**)>, argc=6, argv=0x7fff1be14758, init=<optimized out>, 
    fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fff1be14748) at libc-start.c:287
#14 0x0000000000407dcc in _start ()

So sampler creates a mutex, which gets added to the deadlock detector's list of entries, entry has an nsTArray which I guess does some LogCtor magic. Entry has two arrays so there's a second identical stack trace.

Then a stack trace for the Mutex:

#0  AssertActivityIsLegal () at /home/erahm/dev/mozilla-central/xpcom/base/nsTraceRefcnt.cpp:155
#1  0x00007f6e81a9e186 in NS_LogCtor (aPtr=0x7f6e77d52800, aType=0x7f6e848900d4 "Mutex", aInstanceSize=32)
    at /home/erahm/dev/mozilla-central/xpcom/base/nsTraceRefcnt.cpp:1106
#2  0x00007f6e839ab3ee in Mutex (aName=0x7f6e84bf72fd "sRegisteredThreads mutex", this=0x7f6e77d52800)
    at ../../dist/include/mozilla/Mutex.h:126
#3  Sampler::Startup () at /home/erahm/dev/mozilla-central/tools/profiler/platform.cpp:89
#4  0x00007f6e839ad5e2 in mozilla_sampler_init (stackTop=stackTop@entry=0x7fff1be131c7)
    at /home/erahm/dev/mozilla-central/tools/profiler/platform.cpp:471
#5  0x00007f6e83b62f35 in profiler_init (stackTop=0x7fff1be131c7) at ../../dist/include/GeckoProfilerImpl.h:66
#6  XRE_InitChildProcess (aArgc=5, aArgv=0x7fff1be14758, aGMPLoader=0x0)
    at /home/erahm/dev/mozilla-central/toolkit/xre/nsEmbedFunctions.cpp:354
#7  0x0000000000408173 in content_process_main (argc=5, argv=0x7fff1be14758)
    at /home/erahm/dev/mozilla-central/ipc/app/../contentproc/plugin-container.cpp:236
#8  0x00007f6e80409ec5 in __libc_start_main (main=0x407cf1 <main(int, char**)>, argc=6, argv=0x7fff1be14758, init=<optimized out>, 
    fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fff1be14748) at libc-start.c:287
#9  0x0000000000407dcc in _start ()

Then the sampler pokes the nsThreadManager, it has an OffTheBooksMutex, which causes another deadlock detector entry, which has 2 arrays that produce this stack trace:

#0  AssertActivityIsLegal () at /home/erahm/dev/mozilla-central/xpcom/base/nsTraceRefcnt.cpp:155
#1  0x00007f6e81a9e186 in NS_LogCtor (aPtr=0x7f6e77d52860, aType=0x7f6e848914e0 "nsTArray_base", aInstanceSize=8)
    at /home/erahm/dev/mozilla-central/xpcom/base/nsTraceRefcnt.cpp:1106
#2  0x00007f6e81b08299 in nsTArray_Impl (this=0x7f6e77d52860) at /home/erahm/dev/mozilla-central/xpcom/build/../glue/nsTArray.h:833
#3  nsTArray (this=0x7f6e77d52860) at /home/erahm/dev/mozilla-central/xpcom/build/../glue/nsTArray.h:1976
#4  OrderingEntry (aResource=0x7f6e86c73d90 <nsThreadManager::get()::sInstance+96>, this=0x7f6e77d52860)
    at ../../dist/include/mozilla/DeadlockDetector.h:89
#5  mozilla::DeadlockDetector<mozilla::BlockingResourceBase>::Add (this=0x7f6e77d07300, 
    aResource=0x7f6e86c73d90 <nsThreadManager::get()::sInstance+96>) at ../../dist/include/mozilla/DeadlockDetector.h:182
#6  0x00007f6e81a55595 in mozilla::OffTheBooksMutex::OffTheBooksMutex (this=0x7f6e86c73d90 <nsThreadManager::get()::sInstance+96>, 
    aName=<optimized out>) at ../../dist/include/mozilla/Mutex.h:47
#7  0x00007f6e81aead26 in nsThreadManager (this=0x7f6e86c73d30 <nsThreadManager::get()::sInstance>)
    at /home/erahm/dev/mozilla-central/xpcom/threads/nsThreadManager.h:64
#8  nsThreadManager::get () at /home/erahm/dev/mozilla-central/xpcom/threads/nsThreadManager.h:25
#9  0x00007f6e81b0e726 in NS_GetCurrentThread () at /home/erahm/dev/mozilla-central/xpcom/glue/nsThreadUtils.cpp:322
#10 0x00007f6e839acc69 in ThreadInfo::ThreadInfo (this=this@entry=0x7f6e77d51d80, aName=<optimized out>, aThreadId=22949, 
    aIsMainThread=<optimized out>, aPseudoStack=aPseudoStack@entry=0x7f6e77d6e000, aStackTop=0x7fff1be131c7)
    at /home/erahm/dev/mozilla-central/tools/profiler/platform.cpp:134
#11 0x00007f6e839acd21 in StackOwningThreadInfo::StackOwningThreadInfo (this=0x7f6e77d51d80, aName=<optimized out>, 
    aThreadId=<optimized out>, aIsMainThread=<optimized out>, aPseudoStack=0x7f6e77d6e000, aStackTop=<optimized out>)
    at /home/erahm/dev/mozilla-central/tools/profiler/platform.cpp:161
#12 0x00007f6e83998aaa in Sampler::RegisterCurrentThread (aName=aName@entry=0x7f6e84bf775f "GeckoMain", 
    aPseudoStack=aPseudoStack@entry=0x7f6e77d6e000, aIsMainThread=aIsMainThread@entry=true, stackTop=stackTop@entry=0x7fff1be131c7)
    at /home/erahm/dev/mozilla-central/tools/profiler/platform-linux.cc:532
#13 0x00007f6e839ad67d in mozilla_sampler_init (stackTop=stackTop@entry=0x7fff1be131c7)
    at /home/erahm/dev/mozilla-central/tools/profiler/platform.cpp:479
#14 0x00007f6e83b62f35 in profiler_init (stackTop=0x7fff1be131c7) at ../../dist/include/GeckoProfilerImpl.h:66
#15 XRE_InitChildProcess (aArgc=5, aArgv=0x7fff1be14758, aGMPLoader=0x0)
    at /home/erahm/dev/mozilla-central/toolkit/xre/nsEmbedFunctions.cpp:354
#16 0x0000000000408173 in content_process_main (argc=5, argv=0x7fff1be14758)
    at /home/erahm/dev/mozilla-central/ipc/app/../contentproc/plugin-container.cpp:236
#17 0x00007f6e80409ec5 in __libc_start_main (main=0x407cf1 <main(int, char**)>, argc=6, argv=0x7fff1be14758, init=<optimized out>, 
    fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fff1be14748) at libc-start.c:287
#18 0x0000000000407dcc in _start ()

Comment 9

[Nathan Froyd [:froydnj]]

Comment on attachment 8616242 [details] [diff] [review]
Call PR_LogInit before profiler_init

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

r+'ing this after discussing with Eric.  Since infra is hosed right now, we can't get a good clean try run, but ideally we'll get a green debug run before this lands.

Comment 10

[Eric Rahm [:erahm]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=44bec852bf30

Comment 11

[Eric Rahm [:erahm]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/17c8c58041f4

Comment 12

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/17c8c58041f4