Intermittent Assertion failure: firstTimeStamp == mTimers[0]->Timeout(), at /builds/worker/checkouts/gecko/xpcom/threads/TimerThread.cpp:674
Categories
(Core :: XPCOM, defect, P5)
Tracking
()
People
(Reporter: intermittent-bug-filer, Unassigned)
References
Details
(Keywords: assertion, intermittent-failure)
Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=380410703&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Vh2buHBoSISgcUE9ufBCSg/runs/0/artifacts/public/logs/live_backing.log
[task 2022-06-07T00:41:30.843Z] 00:41:30 INFO - PID 1084 | [GPU 3872, Renderer] WARNING: framebuffer_multisample marked as unsupported: file /builds/worker/checkouts/gecko/gfx/gl/GLContextFeatures.cpp:632
[task 2022-06-07T00:41:30.843Z] 00:41:30 INFO - PID 1084 | [Parent 8828, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp:1234
[task 2022-06-07T00:41:30.844Z] 00:41:30 INFO - PID 1084 | [Parent 8828, GMPThread] WARNING: Failed to delete GMP storage directory: file /builds/worker/checkouts/gecko/dom/media/gmp/GMPServiceParent.cpp:1754
[task 2022-06-07T00:41:30.845Z] 00:41:30 INFO - PID 1084 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to C:\Users\task_165455439432018\AppData\Local\Temp\tmpthlgfuk1\runtests_leaks_8060_tab_pid7204.log
[task 2022-06-07T00:41:30.845Z] 00:41:30 INFO - PID 1084 | [7204, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:339
[task 2022-06-07T00:41:30.846Z] 00:41:30 INFO - PID 1084 | [Parent 8828, Main Thread] WARNING: '!scrollbar', file /builds/worker/checkouts/gecko/widget/Theme.cpp:1075
[task 2022-06-07T00:41:30.847Z] 00:41:30 INFO - PID 1084 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to C:\Users\task_165455439432018\AppData\Local\Temp\tmpthlgfuk1\runtests_leaks_8060_tab_pid8880.log
[task 2022-06-07T00:41:30.847Z] 00:41:30 INFO - PID 1084 | [8880, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:339
[task 2022-06-07T00:41:30.848Z] 00:41:30 INFO - PID 1084 | [Child 8880, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2817
[task 2022-06-07T00:41:30.849Z] 00:41:30 INFO - PID 1084 | [Child 8880, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2817
[task 2022-06-07T00:41:30.849Z] 00:41:30 INFO - PID 1084 | [Child 8880, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2817
[task 2022-06-07T00:41:30.850Z] 00:41:30 INFO - PID 1084 | [Child 8880, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2817
[task 2022-06-07T00:41:30.850Z] 00:41:30 INFO - PID 1084 | [Child 8880, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2817
[task 2022-06-07T00:41:30.851Z] 00:41:30 INFO - PID 1084 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to C:\Users\task_165455439432018\AppData\Local\Temp\tmpthlgfuk1\runtests_leaks_8060_tab_pid3856.log
[task 2022-06-07T00:41:30.852Z] 00:41:30 INFO - PID 1084 | [3856, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:339
[task 2022-06-07T00:41:30.852Z] 00:41:30 INFO - PID 1084 | [Parent 8828, Main Thread] WARNING: '!scrollbar', file /builds/worker/checkouts/gecko/widget/Theme.cpp:1075
[task 2022-06-07T00:41:30.853Z] 00:41:30 INFO - PID 1084 | [GPU 3872, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/checkouts/gecko/gfx/layers/apz/src/APZUpdater.cpp:365
[task 2022-06-07T00:41:30.854Z] 00:41:30 INFO - PID 1084 | [GPU 3872, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/checkouts/gecko/gfx/layers/apz/src/APZUpdater.cpp:365
[task 2022-06-07T00:41:30.855Z] 00:41:30 INFO - PID 1084 | [Child 7204, Main Thread] WARNING: IPC message 'PIdleScheduler::Msg_StartedGC' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:509
[task 2022-06-07T00:41:30.855Z] 00:41:30 INFO - PID 1084 | [Parent 8828, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1601
[task 2022-06-07T00:41:30.856Z] 00:41:30 INFO - PID 1084 | [Child 7204, Main Thread] WARNING: IPC message 'PIdleScheduler::Msg_DoneGC' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:509
[task 2022-06-07T00:41:30.857Z] 00:41:30 INFO - PID 1084 | [Child 7204, Main Thread] WARNING: IPC message 'PIdleScheduler::Msg_StartedGC' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:509
[task 2022-06-07T00:41:30.857Z] 00:41:30 INFO - PID 1084 | [Child 7204, Main Thread] WARNING: IPC message 'PIdleScheduler::Msg_DoneGC' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:509
[task 2022-06-07T00:41:30.858Z] 00:41:30 INFO - PID 1084 | [Child 7204, Main Thread] WARNING: IPC message 'PIdleScheduler::Msg_StartedGC' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:509
[task 2022-06-07T00:41:30.859Z] 00:41:30 INFO - PID 1084 | [Child 7204, Main Thread] WARNING: IPC message 'PIdleScheduler::Msg_DoneGC' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:509
[task 2022-06-07T00:41:30.859Z] 00:41:30 INFO - PID 1084 | [Child 7204, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3359
[task 2022-06-07T00:41:30.860Z] 00:41:30 INFO - PID 1084 | [2022-06-07T00:41:27Z WARN audioipc2::ipccore] AudioIPC Server RPC: EventLoop drop - closing connection for Token(0) failed: Custom { kind: NotFound, error: "I/O source not registered with `Registry`" }
[task 2022-06-07T00:41:30.861Z] 00:41:30 INFO - PID 1084 | [Child 7204, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-06-07T00:41:30.862Z] 00:41:30 INFO - PID 1084 | [Child 7204, Main Thread] WARNING: IPC message 'PIdleScheduler::Msg_StartedGC' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:509
[task 2022-06-07T00:41:30.862Z] 00:41:30 INFO - PID 1084 | [Child 7204, Main Thread] WARNING: IPC message 'PIdleScheduler::Msg_DoneGC' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:509
[task 2022-06-07T00:41:30.863Z] 00:41:30 INFO - PID 1084 | [Child 7204, Main Thread] WARNING: IPC message 'PIdleScheduler::Msg_StartedGC' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:509
[task 2022-06-07T00:41:30.864Z] 00:41:30 INFO - PID 1084 | [Child 7204, Main Thread] WARNING: IPC message 'PIdleScheduler::Msg_DoneGC' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:509
[task 2022-06-07T00:41:30.864Z] 00:41:30 INFO - PID 1084 | [Child 7204, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4571
[task 2022-06-07T00:41:30.865Z] 00:41:30 INFO - PID 1084 | firstTimeStamp -746.000000, mTimers[0]->Timeout() -746.000000, initialFirstTimer 0000013511A69040, current first 00000135114D7B20
[task 2022-06-07T00:41:30.866Z] 00:41:30 INFO - PID 1084 | Assertion failure: firstTimeStamp == mTimers[0]->Timeout(), at /builds/worker/checkouts/gecko/xpcom/threads/TimerThread.cpp:674
[task 2022-06-07T00:41:30.866Z] 00:41:30 INFO - STDOUT: Initializing stack-fixing for the first stack frame, this may take a while...
[task 2022-06-07T00:41:31.136Z] 00:41:31 INFO - PID 1084 | [Parent 8828, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3359
[task 2022-06-07T00:41:31.158Z] 00:41:31 INFO - PID 1084 | [Parent 8828, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-06-07T00:41:31.181Z] 00:41:31 INFO - PID 1084 | Assertion failure: !mInitialized (UnloadModules() was not explicitly called before cleaning up mozJSComponentLoader), at /builds/worker/checkouts/gecko/js/xpconnect/loader/mozJSComponentLoader.cpp:359
[task 2022-06-07T00:41:41.578Z] 00:41:41 INFO - PID 1084 | #01: TimerThread::FindNextFireTimeForCurrentThread(mozilla::TimeStamp, unsigned int) [xpcom/threads/TimerThread.cpp:674]
[task 2022-06-07T00:41:41.579Z] 00:41:41 INFO - PID 1084 | #01: mozJSComponentLoader::~mozJSComponentLoader() [js/xpconnect/loader/mozJSComponentLoader.cpp:357]
[task 2022-06-07T00:41:41.580Z] 00:41:41 INFO - PID 1084 | #02: NS_GetTimerDeadlineHintOnCurrentThread(mozilla::TimeStamp, unsigned int) [xpcom/threads/nsTimerImpl.cpp:136]
[task 2022-06-07T00:41:41.580Z] 00:41:41 INFO - PID 1084 | #02: mozJSComponentLoader::Release() [js/xpconnect/loader/mozJSComponentLoader.cpp:232]
[task 2022-06-07T00:41:41.581Z] 00:41:41 INFO - PID 1084 | #03: mozilla::MainThreadIdlePeriod::GetIdlePeriodHint(mozilla::TimeStamp*) [xpcom/threads/MainThreadIdlePeriod.cpp:46]
[task 2022-06-07T00:41:41.581Z] 00:41:41 INFO - PID 1084 | #03: nsComponentManagerImpl::Shutdown() [xpcom/components/nsComponentManager.cpp:862]
[task 2022-06-07T00:41:41.582Z] 00:41:41 INFO - PID 1084 | #04: mozilla::IdlePeriodState::GetLocalIdleDeadline(bool&, mozilla::detail::BaseAutoUnlock<mozilla::Mutex &> const&) [xpcom/threads/IdlePeriodState.cpp:133]
[task 2022-06-07T00:41:41.582Z] 00:41:41 INFO - PID 1084 | #04: mozilla::ShutdownXPCOM(nsIServiceManager*) [xpcom/build/XPCOMInit.cpp:721]
[task 2022-06-07T00:41:41.583Z] 00:41:41 INFO - PID 1084 | #05: mozilla::IdlePeriodState::GetIdleDeadlineInternal(bool, mozilla::detail::BaseAutoUnlock<mozilla::Mutex &> const&) [xpcom/threads/IdlePeriodState.cpp:69]
[task 2022-06-07T00:41:41.584Z] 00:41:41 INFO - PID 1084 | #05: ScopedXPCOMStartup::~ScopedXPCOMStartup() [toolkit/xre/nsAppRunner.cpp:2047]
[task 2022-06-07T00:41:41.584Z] 00:41:41 INFO - PID 1084 | #06: mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex &> const&) [xpcom/threads/TaskController.cpp:639]
[task 2022-06-07T00:41:41.585Z] 00:41:41 INFO - PID 1084 | #06: XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) [toolkit/xre/nsAppRunner.cpp:5956]
[task 2022-06-07T00:41:41.585Z] 00:41:41 INFO - PID 1084 | #07: mozilla::TaskController::ProcessPendingMTTask(bool) [xpcom/threads/TaskController.cpp:398]
[task 2022-06-07T00:41:41.586Z] 00:41:41 INFO - PID 1084 | #07: XRE_main(int, char**, mozilla::BootstrapConfig const&) [toolkit/xre/nsAppRunner.cpp:5991]
[task 2022-06-07T00:41:41.586Z] 00:41:41 INFO - PID 1084 | #08: mozilla::detail::RunnableFunction<`lambda at /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:127:7'>::Run() [xpcom/threads/nsThreadUtils.h:532]
[task 2022-06-07T00:41:41.629Z] 00:41:41 INFO - PID 1084 | #08: NS_internal_main(int, char**, char**) [browser/app/nsBrowserApp.cpp:406]
[task 2022-06-07T00:41:41.635Z] 00:41:41 INFO - PID 1084 | #09: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1184]
[task 2022-06-07T00:41:41.636Z] 00:41:41 INFO - PID 1084 | #09: wmain(int, wchar_t**) [toolkit/xre/nsWindowsWMain.cpp:167]
[task 2022-06-07T00:41:41.636Z] 00:41:41 INFO - PID 1084 | #10: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:465]
[task 2022-06-07T00:41:41.637Z] 00:41:41 INFO - PID 1084 | #10: __scrt_common_main_seh() [/builds/worker/workspace/obj-build/browser/app/d:/agent/_work/2/s/src/vctools/crt/vcstartup/src/startup/exe_common.inl:288]
[task 2022-06-07T00:41:41.637Z] 00:41:41 INFO - PID 1084 | #11: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:107]
[task 2022-06-07T00:41:41.719Z] 00:41:41 INFO - PID 1084 |
[task 2022-06-07T00:41:41.721Z] 00:41:41 INFO - PID 1084 |
[task 2022-06-07T00:41:41.723Z] 00:41:41 INFO - STDERR: Traceback (most recent call last):
Comment 1•3 years ago
|
||
There's also this assertion in the log:
Assertion failure: !mInitialized (UnloadModules() was not explicitly called before cleaning up mozJSComponentLoader), at /builds/worker/checkouts/gecko/js/xpconnect/loader/mozJSComponentLoader.cpp:359
That one happened simultaneously enough with the other one that the frames are interleaved.
In the log, the printf before the assertion shows "firstTimeStamp -746.000000, mTimers[0]->Timeout() -746.000000", so the compared timestamps do look equal at first glance!
This function FindNextFireTimeForCurrentThread
does a few std::pop_heap
s to extract the next few timers, followed by the same number of std::push_heap
s to put the timers back.
I suppose it's possible that pops&pushes are not stable, i.e., equal items could end up in different positions, as long as the heap invariants are respected.
And the printf seems to indicate as much: "initialFirstTimer 0000013511A69040, current first 00000135114D7B20", so the timers are not the same even though their timestamps look equal.
The heap is sorted using <
(to bring the lowest value to the front), and the failing assertion uses ==
. Could there be some subtle precision issues in Windows timestamps, such that the two operators could disagree when two timestamps are super close? Maybe something to do with high and low precision timers? (But that seems unlikely, there is common code for all comparisons.)
I'm not sure I can help further with this one, except suggesting printing the low-level timestamp values if possible, to better understand if they're equal or not.
Note that in upcoming work I'm hoping to get done in the next few weeks/months, I would get rid of all this popping&pushing, so the problem would go away. (No bug# yet, but it would be a follow-up to bug 1767396.)
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 6•3 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Reporter | ||
Comment 7•2 years ago
|
||
treeherder |
New failure instance: https://treeherder.mozilla.org/logviewer?job_id=389490995&repo=autoland
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
(In reply to Gerald Squelart (he/him) from comment #2)
Note that in upcoming work I'm hoping to get done in the next few weeks/months, I would get rid of all this popping&pushing, so the problem would go away. (No bug# yet, but it would be a follow-up to bug 1767396.)
That work should be handled in bug 1787974 (but not by me anymore).
Comment 11•2 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Reporter | ||
Comment 12•2 years ago
|
||
treeherder |
New failure instance: https://treeherder.mozilla.org/logviewer?job_id=392738944&repo=mozilla-central
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 15•2 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Reporter | ||
Comment 16•2 years ago
|
||
treeherder |
New failure instance: https://treeherder.mozilla.org/logviewer?job_id=397880658&repo=autoland
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 25•2 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Description
•