Closed Bug 1172138 Opened 9 years ago Closed 9 years ago

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

Categories

(Core :: Gecko Profiler, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla41
Tracking Status
firefox41 --- fixed

People

(Reporter: erahm, Assigned: erahm)

References

(Blocks 1 open bug)

Details

Attachments

(2 files)

Attached file Call stacks (deleted) —
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?
Blocks: logspam
I think this is a dupe of bug 1067547.
This might be slightly different, these errors are only in the content process.
Attachment #8616242 - Flags: review?(nfroyd)
Assignee: nobody → erahm
Status: NEW → ASSIGNED
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?) ?
Attachment #8616242 - Flags: review?(nfroyd)
(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.
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 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.
Attachment #8616242 - Flags: review+
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla41
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: