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

Status: RESOLVED FIXED

(Core :: WebVR, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: dholbert [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=201785029&repo=try

https://queue.taskcluster.net/v1/task/LhPLbqkCSm6-BSYyV40uHg/runs/0/artifacts/public/logs/live_backing.log

https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/LhPLbqkCSm6-BSYyV40uHg/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

The assertion in question is in "VRManager::Run1msTasks" and was just added in bug 1473397:
https://hg.mozilla.org/mozilla-central/annotate/49f48ff493c6/gfx/vr/VRManager.cpp#l402

Comment 1

[Daniel Holbert [:dholbert]]

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

Comment 2

[:kip (Kearwood Gilbert)]

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.

Comment 3

[:kip (Kearwood Gilbert)]

Correction: Will keep the assert in place, but early-exit during shutdown higher up in the stack, at VRManager::RunTasks()

Comment 4

[:kip (Kearwood Gilbert)]

Attachment: Bug 1494490 - Early exit VRManager::RunTasks when not on the VR Listener thread

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 5

[:kip (Kearwood Gilbert)]

Try push:

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

Comment 6

[Daosheng Mu[:daoshengmu]]

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.

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ae0df5bd82ea
Early exit VRManager::RunTasks when not on the VR Listener thread r=daoshengmu

Comment 8

[Arthur Iakab [arthur_iakab]]

https://hg.mozilla.org/mozilla-central/rev/ae0df5bd82ea

Comment 9

[Bogdan Tara[:bogdan_tara | bogdant]]

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]

Comment 11

[Intermittent Failures Robot]

34 failures in 2773 pushes (0.012 failures/push) were associated with this bug in the last 7 days.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. ** 

Repository breakdown:
* autoland: 11
* mozilla-inbound: 8
* try: 6
* mozilla-central: 9

Platform breakdown:
* windows10-64: 1
* linux32: 19
* osx-10-10: 3
* linux64-qr: 4
* linux64: 7

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1494490&startday=2018-09-24&endday=2018-09-30&tree=all

Comment 12

[:kip (Kearwood Gilbert)]

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.

Comment 13

[Intermittent Failures Robot]

20 failures in 485 pushes (0.041 failures/push) were associated with this bug yesterday.

Repository breakdown:
* autoland: 10
* try: 3
* mozilla-inbound: 7

Platform breakdown:
* linux64-qr: 2
* windows10-64: 2
* linux32: 6
* osx-10-10: 2
* linux64: 2
* windows10-64-qr: 1
* windows7-32: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1494490&startday=2018-10-01&endday=2018-10-01&tree=all

Comment 14

[Intermittent Failures Robot]

28 failures in 561 pushes (0.05 failures/push) were associated with this bug yesterday.

Repository breakdown:
* mozilla-inbound: 6
* autoland: 13
* mozilla-central: 4
* try: 5

Platform breakdown:
* windows7-32: 3
* windows7-32-msvc: 1
* linux32: 8
* osx-10-10: 5
* macosx64-qr: 3
* linux64: 3
* linux64-qr: 3
* windows10-64-ccov: 1
* windows10-64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1494490&startday=2018-10-02&endday=2018-10-02&tree=all

Comment 15

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(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

Comment 16

[Intermittent Failures Robot]

50 failures in 2708 pushes (0.018 failures/push) were associated with this bug in the last 7 days.

This is the #39 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. ** 

Repository breakdown:
* autoland: 23
* mozilla-inbound: 14
* try: 8
* mozilla-central: 5

Platform breakdown:
* linux64-qr: 5
* windows10-64: 2
* linux32: 14
* windows7-32: 8
* linux64: 7
* windows7-32-msvc: 1
* windows10-64-ccov: 1
* macosx64-qr: 3
* windows10-64-qr: 2
* osx-10-10: 7

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1494490&startday=2018-10-01&endday=2018-10-07&tree=all

Comment 17

[:kip (Kearwood Gilbert)]

This should now be fixed, due to Bug 1494556 removing the VR listener thread.

Comment 18

[:kip (Kearwood Gilbert)]

Resolving fixed, as the affected code no longer exists.