Closed Bug 1239794 Opened 8 years ago Closed 6 years ago

intermittent assertion failure: NS_GetCurrentThread() == mOwningThread (Wrong thread!) / mOwningEventTarget->IsOnCurrentThread() caused by storage::Service::minimizeMemory()

Categories

(Toolkit :: Storage, defect, P3)

Product:
Toolkit
Component:
Storage
Type:
defect

Tracking

()

Status:
RESOLVED WONTFIX

People

(Reporter: ehsan.akhgari, Unassigned)

References

Details

(Keywords: intermittent-failure)

Crash Data

<http://archive.mozilla.org/pub/firefox/try-builds/eakhgari@mozilla.com-12fb5862dfc8110cae035ac55c32231fb4cb893f/try-linux64-debug/try_ubuntu64_vm-debug_test-mochitest-e10s-browser-chrome-2-bm114-tests1-linux64-build658.txt.gz>

00:31:38     INFO -  Assertion failure: NS_GetCurrentThread() == mOwningThread (Wrong thread!), at /builds/slave/try-l64-d-00000000000000000000/build/src/xpcom/threads/LazyIdleThread.cpp:530
00:32:06     INFO -  #01: nsThread::PutEvent(already_AddRefed<nsIRunnable>&&, nsThread::nsNestedEventTarget*) [xpcom/threads/nsThread.cpp:594]
00:32:06     INFO -  #02: nsThread::DispatchInternal(already_AddRefed<nsIRunnable>&&, unsigned int, nsThread::nsNestedEventTarget*) [xpcom/threads/nsThread.cpp:652]
00:32:06     INFO -  #03: nsIEventTarget::Dispatch(nsIRunnable*, unsigned int) [mfbt/AlreadyAddRefed.h:101]
00:32:06     INFO -  #04: mozilla::storage::Service::minimizeMemory() [storage/mozStorageService.cpp:389]
00:32:06     INFO -  #05: mozilla::storage::Service::Observe(nsISupports*, char const*, char16_t const*) [storage/mozStorageService.cpp:936]
00:32:06     INFO -  #06: nsObserverList::NotifyObservers(nsISupports*, char const*, char16_t const*) [xpcom/glue/nsTArray.h:367]
00:32:06     INFO -  #07: nsObserverService::NotifyObservers(nsISupports*, char const*, char16_t const*) [xpcom/glue/nsTHashtable.h:134]
00:32:06     INFO -  #08: NS_InvokeByIndex [xpcom/reflect/xptcall/md/unix/xptcinvoke_x86_64_unix.cpp:176]
00:32:06     INFO -  #09: CallMethodHelper::Call() [js/xpconnect/src/xpcprivate.h:857]
00:32:06     INFO -  #10: XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) [js/xpconnect/src/XPCWrappedNative.cpp:1381]
00:32:06     INFO -  #11: XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) [js/xpconnect/src/XPCWrappedNativeJSOps.cpp:1115]
00:32:06     INFO -  #12: js::CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), JS::CallArgs const&) [js/src/jscntxtinlines.h:236]
00:32:06     INFO -  #13: js::Invoke(JSContext*, JS::CallArgs const&, js::MaybeConstruct) [js/src/vm/Interpreter.cpp:479]
00:32:06     INFO -  #14: Interpret [js/src/vm/Interpreter.cpp:2803]
00:32:06     INFO -  #15: js::RunScript(JSContext*, js::RunState&) [js/src/vm/Interpreter.cpp:426]
00:32:06     INFO -  #16: js::Invoke(JSContext*, JS::CallArgs const&, js::MaybeConstruct) [js/src/vm/Interpreter.cpp:497]
00:32:06     INFO -  #17: js::Invoke(JSContext*, JS::Value const&, JS::Value const&, unsigned int, JS::Value const*, JS::MutableHandle<JS::Value>) [js/src/vm/Interpreter.cpp:531]
00:32:06     INFO -  #18: js::DirectProxyHandler::call(JSContext*, JS::Handle<JSObject*>, JS::CallArgs const&) const [js/public/RootingAPI.h:719]
00:32:06     INFO -  #19: js::CrossCompartmentWrapper::call(JSContext*, JS::Handle<JSObject*>, JS::CallArgs const&) const [js/src/proxy/CrossCompartmentWrapper.cpp:289]
00:32:06     INFO -  #20: js::Proxy::call(JSContext*, JS::Handle<JSObject*>, JS::CallArgs const&) [js/src/proxy/Proxy.cpp:391]
00:32:06     INFO -  #21: js::proxy_Call(JSContext*, unsigned int, JS::Value*) [js/public/RootingAPI.h:719]
00:32:06     INFO -  #22: js::CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), JS::CallArgs const&) [js/src/jscntxtinlines.h:236]
00:32:06     INFO -  #23: js::Invoke(JSContext*, JS::CallArgs const&, js::MaybeConstruct) [js/src/vm/Interpreter.cpp:467]
00:32:06     INFO -  #24: js::Invoke(JSContext*, JS::Value const&, JS::Value const&, unsigned int, JS::Value const*, JS::MutableHandle<JS::Value>) [js/src/vm/Interpreter.cpp:531]
00:32:06     INFO -  #25: JS::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) [js/src/jsapi.cpp:2864]
00:32:06     INFO -  #26: mozilla::dom::AnyCallback::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>, mozilla::ErrorResult&) [obj-firefox/dom/bindings/PromiseBinding.cpp:78]
00:32:06     INFO -  #27: mozilla::dom::AnyCallback::Call(JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>, mozilla::ErrorResult&, char const*, mozilla::dom::CallbackObject::ExceptionHandling, JSCompartment*) [obj-firefox/dist/include/mozilla/dom/PromiseBinding.h:149]
00:32:06     INFO -  #28: mozilla::dom::WrapperPromiseCallback::Call(JSContext*, JS::Handle<JS::Value>) [dom/promise/PromiseCallback.cpp:341]
00:32:06     INFO -  #29: mozilla::dom::PromiseReactionJob::Run() [mfbt/Maybe.h:372]
00:32:06     INFO -  #30: mozilla::dom::Promise::PerformMicroTaskCheckpoint() [xpcom/glue/nsDebug.h:40]
00:32:06     INFO -  #31: mozilla::CycleCollectedJSRuntime::AfterProcessTask(unsigned int) [xpcom/base/CycleCollectedJSRuntime.cpp:1161]
00:32:06     INFO -  #32: XPCJSRuntime::AfterProcessTask(unsigned int) [js/xpconnect/src/XPCJSRuntime.cpp:3651]
00:32:06     INFO -  #33: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1007]
00:32:06     INFO -  #34: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/glue/nsThreadUtils.cpp:297]
00:32:06     INFO -  #35: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:96]
00:32:06     INFO -  #36: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:235]
00:32:06     INFO -  #37: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:520]
00:32:06     INFO -  #38: nsBaseAppShell::Run() [widget/nsBaseAppShell.cpp:158]
00:32:06     INFO -  #39: nsAppStartup::Run() [toolkit/components/startup/nsAppStartup.cpp:282]
00:32:06     INFO -  #40: XREMain::XRE_mainRun() [toolkit/xre/nsAppRunner.cpp:4327]
00:32:06     INFO -  #41: XREMain::XRE_main(int, char**, nsXREAppData const*) [toolkit/xre/nsAppRunner.cpp:4423]
00:32:06     INFO -  #42: XRE_main [toolkit/xre/nsAppRunner.cpp:4526]
00:32:06     INFO -  #43: do_main [browser/app/nsBrowserApp.cpp:212]
00:32:06     INFO -  #44: main [browser/app/nsBrowserApp.cpp:354]
00:32:06     INFO -  #45: libc.so.6 + 0x2176d
00:32:06     INFO -  #46: _start
00:32:06     INFO -  Assertion failure: mPendingEventCount (Mismatched calls to observer methods!), at /builds/slave/try-l64-d-00000000000000000000/build/src/xpcom/threads/LazyIdleThread.cpp:550
00:32:06     INFO -  #01: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1003]
00:32:06     INFO -  #02: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/glue/nsThreadUtils.cpp:297]
00:32:06     INFO -  #03: mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:327]
00:32:06     INFO -  #04: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:235]
00:32:06     INFO -  #05: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:520]
00:32:06     INFO -  #06: nsThread::ThreadFunc(void*) [xpcom/threads/nsThread.cpp:403]
00:32:06     INFO -  #07: _pt_root [nsprpub/pr/src/pthreads/ptthread.c:215]
00:32:06     INFO -  #08: libpthread.so.0 + 0x7e9a
00:32:06     INFO -  #09: libc.so.6 + 0xf42ed
00:32:06     INFO -  [Child 3065] ###!!! ABORT: Aborting on channel error.: file /builds/slave/try-l64-d-00000000000000000000/build/src/ipc/glue/MessageChannel.cpp, line 1762
00:32:06     INFO -  #01: mozilla::ipc::ProcessLink::OnChannelError() [ipc/glue/MessageLink.cpp:429]
00:32:06     INFO -  #02: IPC::Channel::ChannelImpl::OnFileCanReadWithoutBlocking(int) [ipc/chromium/src/chrome/common/ipc_channel_posix.cc:881]
00:32:06     INFO -  #03: event_base_loop [ipc/chromium/src/third_party/libevent/event.c:1355]
00:32:06     INFO -  #04: base::MessagePumpLibevent::Run(base::MessagePump::Delegate*) [ipc/chromium/src/base/message_pump_libevent.cc:370]
00:32:06     INFO -  #05: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:235]
00:32:06     INFO -  #06: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:520]
00:32:06     INFO -  #07: base::Thread::ThreadMain() [ipc/chromium/src/base/thread.cc:175]
00:32:06     INFO -  #08: ThreadFunc [ipc/chromium/src/base/platform_thread_posix.cc:38]
00:32:06     INFO -  #09: libpthread.so.0 + 0x7e9a
00:32:06     INFO -  #10: libc.so.6 + 0xf42ed
00:32:06     INFO -  [Child 3065] ###!!! ABORT: Aborting on channel error.: file /builds/slave/try-l64-d-00000000000000000000/build/src/ipc/glue/MessageChannel.cpp, line 1762
00:32:06     INFO -  Hit MOZ_CRASH() at /builds/slave/try-l64-d-00000000000000000000/build/src/memory/mozalloc/mozalloc_abort.cpp:33
Blocks: 998330
This looks like a serious LazyIdleThread semantics problem.  Whatever we are dispatching to is a LazyIdleThread that demands that only its owner dispatches to it.

So I think the scenario is this:
- Someone is a LazyIdleThread
- The LazyIdleThread opens a synchronous mozStorage connection
- DOOM! DOOM DOOM DOOM!

This seems like mozStorage can either blame the consumer or LazyIdleThread for having dubious semantics.  LazyIdleThread.h for one doesn't seem to justify why only its creator can use it.
Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
Looking into this more (because of bug 1357554 showing this is still a thing that happens and can waste the valuable time of those who file bugs on assertions they encounter), it seems:
- It's QuotaManager's IOThread that is a LazyIdleThread and the root cause.
- The connections in question aren't QuotaManager's, but its clients dom/indexedDB, dom/cache, and dom/asmjscache.  (QuotaManager does use a SQLite database for tracking the status of <profile>/storage, but that's new and is a very short-lived connection.  The usage did not exist when this intermittent was first reported.)
- mozStorage's use of do_GetCurrentThread() is indeed not seeing the LazyIdleThread (as touched on in bug 722181), but instead the underlying backing thread that can go away.  The assertion is happening because LazyIdleThread registers itself as an observer for the underlying nsThread and enforces its assertion in the OnDispatched notification.

Looking at https://bugzilla.mozilla.org/buglist.cgi?quicksearch=lazyidlethread I see a number of other intermittent failures involving LazyIdleThread.  The only other LazyIdleThread consumers seem to be nsHttpNegotiateAuth and ipc/glue/CrashReporterHost.

Given how important QuotaManager is to the system and that arguably adding thread startup overhead to our latency for ServiceWorkers' use of dom/cache is bad, maybe it would be a good short-term fix to just have QuotaManager use a permanent thread.  :janv, what are your thoughts on that?

We could maintain the balance by addressing bug 722181 and having mozStorage's async threads not be dedicated threads.  (There's also some new possibilities for addressing that that I'll post there.)
Flags: needinfo?(jvarga)
Crash Signature: [@ mozilla::LazyIdleThread::OnDispatchedEvent(nsIThreadInternal *) ]
Summary: intermittent assertion failure: NS_GetCurrentThread() == mOwningThread (Wrong thread!) caused by storage::Service::minimizeMemory() → intermittent assertion failure: NS_GetCurrentThread() == mOwningThread (Wrong thread!) / mOwningEventTarget->IsOnCurrentThread() caused by storage::Service::minimizeMemory()
(In reply to Andrew Sutherland [:asuth] from comment #5)
> Given how important QuotaManager is to the system and that arguably adding
> thread startup overhead to our latency for ServiceWorkers' use of dom/cache
> is bad, maybe it would be a good short-term fix to just have QuotaManager
> use a permanent thread.  :janv, what are your thoughts on that?

This was done in bug 1392755.
Flags: needinfo?(jvarga)
Closing because no crash reported since 12 weeks.
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.