Closed Bug 1494490 Opened 1 year ago Closed 1 year ago

Intermittent Assertion failure: VRListenerThreadHolder::IsInVRListenerThread(), at /builds/worker/workspace/build/src/gfx/vr/VRManager.cpp:402

Categories

(Core :: WebVR, defect, P5)

defect

Tracking

()

RESOLVED FIXED
mozilla64
Tracking Status
firefox-esr60 --- unaffected
firefox62 --- unaffected
firefox63 --- unaffected
firefox64 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: kip)

References

(Blocks 1 open bug)

Details

(Keywords: assertion, intermittent-failure)

Attachments

(1 file)

I ran into this assertion on a Try run based off of this morning's mozilla-central.  The patches I added for the try run were minimal & wholly unrelated to VR, so they wouldn't have been responsible for causing the failure.

This seems to be a shutdown assertion-failure -- it happened just after "Received observer notification xpcom-will-shutdown".


Here's the assertion backtrace from the log:
Assertion failure: VRListenerThreadHolder::IsInVRListenerThread(), at /builds/worker/workspace/build/src/gfx/vr/VRManager.cpp:402
#01: mozilla::gfx::VRManager::Run1msTasks(double) [gfx/vr/VRManager.cpp:402]
#02: mozilla::gfx::VRManager::RunTasks() [gfx/vr/VRManager.cpp:353]
#03: mozilla::gfx::VRManager::TaskTimerCallback(nsITimer*, void*) [gfx/vr/VRManager.cpp:327]
#04: nsTimerImpl::Fire(int) [xpcom/threads/nsTimerImpl.cpp:701]
#05: nsTimerEvent::Run() [xpcom/threads/TimerThread.cpp:299]
#06: MessageLoop::RunTask(already_AddRefed<nsIRunnable>) [xpcom/base/nsCOMPtr.h:396]
#07: MessageLoop::DeferOrRunPendingTask(MessageLoop::PendingTask&&) [ipc/chromium/src/base/message_loop.cc:459]
#08: MessageLoop::DoWork() [ipc/chromium/src/base/message_loop.cc:534]
#09: base::MessagePumpDefault::Run(base::MessagePump::Delegate*) [ipc/chromium/src/base/message_pump_default.cc:39]
#10: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:326]
#11: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:598]
#12: base::Thread::ThreadMain() [ipc/chromium/src/base/thread.cc:184]
#13: ThreadFunc(void*) [ipc/chromium/src/base/platform_thread_posix.cc:45]
#14: libpthread.so.0 + 0x6295
Flags: needinfo?(kgilbert)
Thanks, I'll take this and investigate.

I suspect we'll just need to change the assert into a check for the in-progress shutdown VRManager::RunTasks that early-exits before calling the runxxmstasks functions.
Assignee: nobody → kgilbert
Flags: needinfo?(kgilbert)
Correction: Will keep the assert in place, but early-exit during shutdown higher up in the stack, at VRManager::RunTasks()
During shutdown, VRManager::RunTasks may be run outside
of the VR Listener thread due to residual nsTimer events.
This results in intermittent assertions during shutdown
when the assert is hit.
We do not need to run these periodic tasks during shutdown
so we can simply early-exit here.
Comment on attachment 9012411 [details]
Bug 1494490 - Early exit VRManager::RunTasks when not on the VR Listener thread

Daosheng Mu[:daoshengmu] has approved the revision.
Attachment #9012411 - Flags: review+
Pushed by kgilbert@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ae0df5bd82ea
Early exit VRManager::RunTasks when not on the VR Listener thread r=daoshengmu
https://hg.mozilla.org/mozilla-central/rev/ae0df5bd82ea
Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla64
This is still happening, or at least something very similar.

Recent failure: https://treeherder.mozilla.org/logviewer.html#?job_id=202418384&repo=mozilla-central&lineNumber=8664

[task 2018-09-29T23:00:26.941Z] 23:00:26     INFO - REFTEST TEST-START | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/css-ui-invalid/textarea/textarea-novalidate.html == file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/css-ui-invalid/textarea/textarea-ref.html
[task 2018-09-29T23:00:26.942Z] 23:00:26     INFO - REFTEST TEST-LOAD | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/css-ui-invalid/textarea/textarea-novalidate.html | 14 / 15 (93%)
[task 2018-09-29T23:00:26.964Z] 23:00:26     INFO - ++DOMWINDOW == 68 (0xdf739800) [pid = 2401] [serial = 68] [outer = 0xd9546940]
[task 2018-09-29T23:00:27.002Z] 23:00:27     INFO - [2401, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/workspace/build/src/dom/base/nsContentUtils.cpp, line 4021
[task 2018-09-29T23:00:27.123Z] 23:00:27     INFO - REFTEST TEST-PASS | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/css-ui-invalid/textarea/textarea-novalidate.html == file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/css-ui-invalid/textarea/textarea-ref.html | image comparison, max difference: 0, number of differing pixels: 0
[task 2018-09-29T23:00:27.128Z] 23:00:27     INFO - REFTEST TEST-END | file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/css-ui-invalid/textarea/textarea-novalidate.html == file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/css-ui-invalid/textarea/textarea-ref.html
[task 2018-09-29T23:00:27.129Z] 23:00:27     INFO - ++DOMWINDOW == 69 (0xdf733800) [pid = 2401] [serial = 69] [outer = 0xd9546940]
[task 2018-09-29T23:00:27.155Z] 23:00:27     INFO - REFTEST INFO | Slowest test took 520ms (file:///builds/worker/workspace/build/tests/reftest/tests/layout/reftests/css-ui-invalid/textarea/textarea-valid.html)
[task 2018-09-29T23:00:27.157Z] 23:00:27     INFO - REFTEST INFO | Total canvas count = 3
[task 2018-09-29T23:00:27.523Z] 23:00:27     INFO - [2401, Main Thread] WARNING: NS_ENSURE_TRUE(service) failed: file /builds/worker/workspace/build/src/netwerk/cache2/CacheObserver.cpp, line 347
[task 2018-09-29T23:00:27.524Z] 23:00:27     INFO - [2401, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/workspace/build/src/netwerk/cache2/CacheObserver.cpp, line 370
[task 2018-09-29T23:00:27.526Z] 23:00:27     INFO - [2401, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/workspace/build/src/netwerk/cache2/CacheObserver.cpp, line 487
[task 2018-09-29T23:00:28.556Z] 23:00:28     INFO - 1538262028551	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
[task 2018-09-29T23:00:28.556Z] 23:00:28     INFO - 1538262028552	Marionette	INFO	Stopped listening on port 2828
[task 2018-09-29T23:00:28.557Z] 23:00:28     INFO - 1538262028553	Marionette	DEBUG	Remote service is inactive
[task 2018-09-29T23:00:28.565Z] 23:00:28     INFO - [2401, Main Thread] WARNING: NS_ENSURE_TRUE(mDB) failed: file /builds/worker/workspace/build/src/netwerk/cache/nsDiskCacheDeviceSQL.cpp, line 1422
[task 2018-09-29T23:00:28.607Z] 23:00:28     INFO - Assertion failure: VRListenerThreadHolder::IsInVRListenerThread(), at /builds/worker/workspace/build/src/gfx/vr/VRManager.cpp:407
[task 2018-09-29T23:01:16.336Z] 23:01:16     INFO - #01: mozilla::gfx::VRManager::Run1msTasks(double) [gfx/vr/VRManager.cpp:407]
[task 2018-09-29T23:01:16.337Z] 23:01:16     INFO - 
[task 2018-09-29T23:01:16.338Z] 23:01:16     INFO - #02: mozilla::gfx::VRManager::RunTasks() [gfx/vr/VRManager.cpp:358]
[task 2018-09-29T23:01:16.338Z] 23:01:16     INFO - 
[task 2018-09-29T23:01:16.339Z] 23:01:16     INFO - #03: mozilla::gfx::VRManager::TaskTimerCallback(nsITimer*, void*) [gfx/vr/VRManager.cpp:327]
[task 2018-09-29T23:01:16.340Z] 23:01:16     INFO - 
[task 2018-09-29T23:01:16.341Z] 23:01:16     INFO - #04: nsTimerImpl::Fire(int) [xpcom/threads/nsTimerImpl.cpp:701]
[task 2018-09-29T23:01:16.341Z] 23:01:16     INFO - 
[task 2018-09-29T23:01:16.342Z] 23:01:16     INFO - #05: nsTimerEvent::Run() [xpcom/threads/TimerThread.cpp:299]
[task 2018-09-29T23:01:16.343Z] 23:01:16     INFO - 
[task 2018-09-29T23:01:16.343Z] 23:01:16     INFO - #06: MessageLoop::RunTask(already_AddRefed<nsIRunnable>) [xpcom/base/nsCOMPtr.h:396]
[task 2018-09-29T23:01:16.343Z] 23:01:16     INFO - 
[task 2018-09-29T23:01:16.344Z] 23:01:16     INFO - #07: MessageLoop::DeferOrRunPendingTask(MessageLoop::PendingTask&&) [ipc/chromium/src/base/message_loop.cc:459]
[task 2018-09-29T23:01:16.344Z] 23:01:16     INFO - 
[task 2018-09-29T23:01:16.345Z] 23:01:16     INFO - #08: MessageLoop::DoWork() [ipc/chromium/src/base/message_loop.cc:534]
[task 2018-09-29T23:01:16.346Z] 23:01:16     INFO - 
[task 2018-09-29T23:01:16.347Z] 23:01:16     INFO - #09: base::MessagePumpDefault::Run(base::MessagePump::Delegate*) [ipc/chromium/src/base/message_pump_default.cc:39]
[task 2018-09-29T23:01:16.347Z] 23:01:16     INFO - 
[task 2018-09-29T23:01:16.348Z] 23:01:16     INFO - #10: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:326]
[task 2018-09-29T23:01:16.349Z] 23:01:16     INFO - 
[task 2018-09-29T23:01:16.349Z] 23:01:16     INFO - #11: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:598]
Status: RESOLVED → REOPENED
Flags: needinfo?(kgilbert)
Resolution: FIXED → ---
Duplicate of this bug: 1494444
To fix another bug (Bug 1494556), I am removing the VRListener thread entirely.  

Hopefully, this will also resolve this one.

I'll keep the bug open until we can confirm that the crashes no longer occur.
Flags: needinfo?(kgilbert)
Depends on: 1494556
(In reply to :kip (Kearwood Gilbert) from comment #12)
> I'll keep the bug open until we can confirm that the crashes no longer occur.

Might this failure which happened earlier today be still related?

https://treeherder.mozilla.org/logviewer.html#?job_id=203281020&repo=mozilla-inbound&lineNumber=51760

Also there is one more occurrence from yesterday here:
https://treeherder.mozilla.org/logviewer.html#?job_id=203019692&repo=mozilla-inbound&lineNumber=45294
Flags: needinfo?(kgilbert)
This should now be fixed, due to Bug 1494556 removing the VR listener thread.
Flags: needinfo?(kgilbert)
Resolving fixed, as the affected code no longer exists.
Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.