Intermittent Assertion failure: gcMax > TimeDuration::Zero(), at /builds/worker/checkouts/gecko/js/src/gc/Statistics.cpp:1580
Categories
(Core :: JavaScript: GC, defect, P5)
Tracking
()
Tracking | Status | |
---|---|---|
firefox-esr102 | --- | unaffected |
firefox-esr115 | --- | unaffected |
firefox115 | --- | unaffected |
firefox116 | --- | unaffected |
firefox117 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: jonco)
References
(Regression)
Details
(Keywords: assertion, intermittent-failure, regression, Whiteboard: [stockwell needswork:owner])
Attachments
(2 files)
Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=421416000&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/TARGQgf5RV28MWw_uxGjIg/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/TARGQgf5RV28MWw_uxGjIg/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1
[task 2023-07-04T11:53:14.633Z] 11:53:14 INFO - REFTEST TEST-START | layout/reftests/invalidation/scroll-inactive-layers-2.html != about:blank
[task 2023-07-04T11:53:14.634Z] 11:53:14 INFO - REFTEST TEST-LOAD | file:///Z:/task_168846770134897/build/tests/reftest/tests/layout/reftests/invalidation/scroll-inactive-layers-2.html | 46 / 101 (45%)
[task 2023-07-04T11:53:14.824Z] 11:53:14 INFO - Assertion failure: gcMax > TimeDuration::Zero(), at /builds/worker/checkouts/gecko/js/src/gc/Statistics.cpp:1580
[task 2023-07-04T11:53:14.921Z] 11:53:14 INFO - #01: js::gcstats::Statistics::computeMMU(mozilla::BaseTimeDuration<mozilla::TimeDurationValueCalculator>) const [js/src/gc/Statistics.cpp:1580]
[task 2023-07-04T11:53:14.922Z] 11:53:14 INFO - #02: js::gcstats::Statistics::sendGCTelemetry() [js/src/gc/Statistics.cpp:1082]
[task 2023-07-04T11:53:14.922Z] 11:53:14 INFO - #03: js::gcstats::Statistics::endSlice() [js/src/gc/Statistics.cpp:1246]
[task 2023-07-04T11:53:14.923Z] 11:53:14 INFO - #04: js::gc::GCRuntime::gcCycle(bool, js::SliceBudget const&, JS::GCReason) [js/src/gc/GC.cpp:4179]
[task 2023-07-04T11:53:14.924Z] 11:53:14 INFO - #05: js::gc::GCRuntime::collect(bool, js::SliceBudget const&, JS::GCReason) [js/src/gc/GC.cpp:4363]
[task 2023-07-04T11:53:14.924Z] 11:53:14 INFO - #06: js::gc::GCRuntime::gcSlice(JS::GCReason, js::SliceBudget const&) [js/src/gc/GC.cpp:4465]
[task 2023-07-04T11:53:14.925Z] 11:53:14 INFO - #07: JS::IncrementalGCSlice(JSContext*, JS::GCReason, js::SliceBudget const&) [js/src/gc/GCAPI.cpp:319]
[task 2023-07-04T11:53:14.926Z] 11:53:14 INFO - #08: GarbageCollectImpl(JS::GCReason, nsJSContext::IsShrinking, js::SliceBudget const&) [dom/base/nsJSEnvironment.cpp:1053]
[task 2023-07-04T11:53:14.927Z] 11:53:14 INFO - #09: nsJSContext::RunIncrementalGCSlice(JS::GCReason, nsJSContext::IsShrinking, js::SliceBudget&) [dom/base/nsJSEnvironment.cpp:1090]
[task 2023-07-04T11:53:14.928Z] 11:53:14 INFO - #10: mozilla::CCGCScheduler::GCRunnerFiredDoGC(mozilla::TimeStamp, mozilla::GCRunnerStep const&) [dom/base/CCGCScheduler.cpp:427]
[task 2023-07-04T11:53:14.929Z] 11:53:14 INFO - #11: mozilla::CCGCScheduler::GCRunnerFired(mozilla::TimeStamp) [dom/base/CCGCScheduler.cpp:386]
[task 2023-07-04T11:53:14.930Z] 11:53:14 INFO - #12: std::_Func_impl_no_alloc<`lambda at /builds/worker/checkouts/gecko/dom/base/CCGCScheduler.cpp:617:7',bool,mozilla::TimeStamp>::_Do_call(mozilla::TimeStamp&&) [/builds/worker/fetches/vs/VC/Tools/MSVC/14.29.30133/include/functional:822]
[task 2023-07-04T11:53:14.930Z] 11:53:14 INFO - #13: mozilla::IdleTaskRunner::Run() [xpcom/threads/IdleTaskRunner.cpp:134]
[task 2023-07-04T11:53:14.931Z] 11:53:14 INFO - #14: mozilla::TimedOut(nsITimer*, void*) [xpcom/threads/IdleTaskRunner.cpp:144]
[task 2023-07-04T11:53:14.932Z] 11:53:14 INFO - #15: nsTimerImpl::Fire(int) [xpcom/threads/nsTimerImpl.cpp:673]
[task 2023-07-04T11:53:14.932Z] 11:53:14 INFO - #16: nsTimerEvent::Run() [xpcom/threads/TimerThread.cpp:476]
[task 2023-07-04T11:53:14.933Z] 11:53:14 INFO - #17: mozilla::RunnableTask::Run() [xpcom/threads/TaskController.cpp:556]
[task 2023-07-04T11:53:14.934Z] 11:53:14 INFO - #18: mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex &> const&) [xpcom/threads/TaskController.cpp:880]
[task 2023-07-04T11:53:14.934Z] 11:53:14 INFO - #19: mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex &> const&) [xpcom/threads/TaskController.cpp:704]
[task 2023-07-04T11:53:14.935Z] 11:53:14 INFO - #20: mozilla::TaskController::ProcessPendingMTTask(bool) [xpcom/threads/TaskController.cpp:491]
[task 2023-07-04T11:53:14.936Z] 11:53:14 INFO - #21: mozilla::detail::RunnableFunction<`lambda at /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:221:7'>::Run() [xpcom/threads/nsThreadUtils.h:549]
[task 2023-07-04T11:53:14.937Z] 11:53:14 INFO - #22: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1203]
[task 2023-07-04T11:53:14.937Z] 11:53:14 INFO - #23: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:480]
[task 2023-07-04T11:53:14.938Z] 11:53:14 INFO - #24: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:107]
[task 2023-07-04T11:53:14.938Z] 11:53:14 INFO - #25: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:370]
[task 2023-07-04T11:53:14.939Z] 11:53:14 INFO - #26: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:364]
[task 2023-07-04T11:53:14.939Z] 11:53:14 INFO - #27: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:346]
[task 2023-07-04T11:53:14.940Z] 11:53:14 INFO - #28: nsBaseAppShell::Run() [widget/nsBaseAppShell.cpp:150]
[task 2023-07-04T11:53:14.941Z] 11:53:14 INFO - #29: nsAppShell::Run() [widget/windows/nsAppShell.cpp:615]
[task 2023-07-04T11:53:14.941Z] 11:53:14 INFO - #30: XRE_RunAppShell() [toolkit/xre/nsEmbedFunctions.cpp:717]
[task 2023-07-04T11:53:14.942Z] 11:53:14 INFO - #31: mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:235]
[task 2023-07-04T11:53:14.942Z] 11:53:14 INFO - #32: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:370]
[task 2023-07-04T11:53:14.943Z] 11:53:14 INFO - #33: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:364]
[task 2023-07-04T11:53:14.943Z] 11:53:14 INFO - #34: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:346]
[task 2023-07-04T11:53:14.945Z] 11:53:14 INFO - #35: XRE_InitChildProcess(int, char**, XREChildData const*) [toolkit/xre/nsEmbedFunctions.cpp:656]
[task 2023-07-04T11:53:14.945Z] 11:53:14 INFO - #36: mozilla::BootstrapImpl::XRE_InitChildProcess(int, char**, XREChildData const*) [toolkit/xre/Bootstrap.cpp:67]
[task 2023-07-04T11:53:14.946Z] 11:53:14 INFO - #37: NS_internal_main(int, char**, char**) [browser/app/nsBrowserApp.cpp:375]
[task 2023-07-04T11:53:14.947Z] 11:53:14 INFO - #38: wmain(int, wchar_t**) [toolkit/xre/nsWindowsWMain.cpp:167]
[task 2023-07-04T11:53:14.947Z] 11:53:14 INFO - #39: __scrt_common_main_seh() [/builds/worker/workspace/obj-build/browser/app/D:/a/_work/1/s/src/vctools/crt/vcstartup/src/startup/exe_common.inl:288]
[task 2023-07-04T11:53:14.948Z] 11:53:14 INFO - #40: BaseThreadInitThunk [C:\Windows\System32\KERNEL32.DLL + 0x17d49]
[task 2023-07-04T11:53:14.948Z] 11:53:14 INFO - #41: RtlInitializeExceptionChain [C:\Windows\SYSTEM32\ntdll.dll + 0x6b74b]
[task 2023-07-04T11:53:14.948Z] 11:53:14 INFO - #42: RtlClearBits [C:\Windows\SYSTEM32\ntdll.dll + 0x6b6cf]
[task 2023-07-04T11:53:15.098Z] 11:53:15 INFO - [Parent 9088, IPC I/O Parent] WARNING: DuplicateHandle failed for handle 0 in TransferHandles: file /builds/worker/checkouts/gecko/ipc/chromium/src/chrome/common/ipc_channel_win.cc:621
[task 2023-07-04T11:53:15.098Z] 11:53:15 INFO - [Parent 9088, IPC I/O Parent] WARNING: Call to Send() failed: file /builds/worker/checkouts/gecko/ipc/glue/NodeChannel.cpp:196
[task 2023-07-04T11:53:15.099Z] 11:53:15 INFO - [Parent 9088, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 8C0D2E43FFE4E6A8.7B79B0F34C30C785: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:344
[task 2023-07-04T11:53:15.100Z] 11:53:15 INFO - [Parent 9088, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 8C0D2E43FFE4E6A8.7B79B0F34C30C785: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:344
[task 2023-07-04T11:53:15.101Z] 11:53:15 INFO - [Parent 9088, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 8C0D2E43FFE4E6A8.7B79B0F34C30C785: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:344
[task 2023-07-04T11:53:15.101Z] 11:53:15 INFO - [Parent 9088, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 8C0D2E43FFE4E6A8.7B79B0F34C30C785: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:344
[task 2023-07-04T11:53:15.101Z] 11:53:15 INFO - [Parent 9088, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 8C0D2E43FFE4E6A8.7B79B0F34C30C785: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:344
[task 2023-07-04T11:53:15.102Z] 11:53:15 INFO - [Parent 9088, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 8C0D2E43FFE4E6A8.7B79B0F34C30C785: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:344
[task 2023-07-04T11:53:15.102Z] 11:53:15 INFO - [Parent 9088, IPC I/O Parent] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 8C0D2E43FFE4E6A8.7B79B0F34C30C785: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:344
[task 2023-07-04T11:53:15.103Z] 11:53:15 INFO - [GPU 10128, IPC I/O Child] WARNING: pipe error: 232: file /builds/worker/checkouts/gecko/ipc/chromium/src/chrome/common/ipc_channel_win.cc:443
[task 2023-07-04T11:53:15.103Z] 11:53:15 INFO - [Parent 9088, ProcessHangMon] WARNING: IPC message 'PProcessHangMonitor::Msg_RequestContentJSInterrupt' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:508
[task 2023-07-04T11:53:15.104Z] 11:53:15 INFO - [Parent 9088, Main Thread] WARNING: IPC message 'PBrowser::Msg_UpdateNativeWindowHandle' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:508
[task 2023-07-04T11:53:15.104Z] 11:53:15 INFO - [Parent 9088, Main Thread] WARNING: IPC message 'PBrowser::Msg_Destroy' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:508
[task 2023-07-04T11:53:15.104Z] 11:53:15 INFO - [Parent 9088, Main Thread] WARNING: No build ID mismatch: file /builds/worker/checkouts/gecko/dom/base/nsFrameLoader.cpp:3777
[task 2023-07-04T11:53:15.106Z] 11:53:15 ERROR - A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-07-04T11:53:15.107Z] 11:53:15 INFO - [Parent 9088, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorParent.cpp:42
[task 2023-07-04T11:53:15.665Z] 11:53:15 INFO - [Child 1180, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:61
[task 2023-07-04T11:53:15.666Z] 11:53:15 INFO - [Child 1180, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:61
[task 2023-07-04T11:53:15.677Z] 11:53:15 INFO - [Child 1180, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:61
[task 2023-07-04T11:53:15.680Z] 11:53:15 INFO - [Child 1180, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:61
[task 2023-07-04T11:53:15.680Z] 11:53:15 INFO - [Child 1180, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:61
[task 2023-07-04T11:53:15.681Z] 11:53:15 INFO - [Child 1180, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:61
[task 2023-07-04T11:53:15.683Z] 11:53:15 INFO - [Child 1180, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:61
[task 2023-07-04T11:53:15.683Z] 11:53:15 INFO - [Child 1180, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:61
[task 2023-07-04T11:53:15.687Z] 11:53:15 INFO - [Child 1180, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:61
[task 2023-07-04T11:53:15.703Z] 11:53:15 INFO - 1688471595703 Marionette TRACE Received observer notification quit-application
[task 2023-07-04T11:53:15.704Z] 11:53:15 INFO - 1688471595703 Marionette INFO Stopped listening on port 2828
[task 2023-07-04T11:53:15.705Z] 11:53:15 INFO - 1688471595704 Marionette DEBUG Marionette stopped listening
[task 2023-07-04T11:53:15.778Z] 11:53:15 INFO - [GPU 10128, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/checkouts/gecko/gfx/layers/apz/src/APZUpdater.cpp:371
[task 2023-07-04T11:53:15.784Z] 11:53:15 INFO - [GPU 10128, Compositor] WARNING: bad Shmem: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:450
[task 2023-07-04T11:53:15.784Z] 11:53:15 INFO - [GPU 10128, Compositor] WARNING: bad Shmem: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:450
[task 2023-07-04T11:53:15.798Z] 11:53:15 INFO - [GPU 10128, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/checkouts/gecko/gfx/layers/apz/src/APZUpdater.cpp:371
[task 2023-07-04T11:53:15.862Z] 11:53:15 INFO - [Parent 9088, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:232
[task 2023-07-04T11:53:15.863Z] 11:53:15 INFO - [Parent 9088, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:232
[task 2023-07-04T11:53:15.864Z] 11:53:15 INFO - !!! error running onStopped callback: TypeError: callback is not a function
[task 2023-07-04T11:53:15.873Z] 11:53:15 INFO - [Parent 9088, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x8046001E (NS_ERROR_ILLEGAL_DURING_SHUTDOWN): file /builds/worker/checkouts/gecko/toolkit/components/credentialmanagement/IdentityCredentialStorageService.cpp:55
[task 2023-07-04T11:53:15.873Z] 11:53:15 INFO - [Parent 9088, Main Thread] WARNING: NS_ENSURE_TRUE(inst) failed: file StaticComponents.cpp:10800
[task 2023-07-04T11:53:15.880Z] 11:53:15 INFO - console.error: ({})
[task 2023-07-04T11:53:16.165Z] 11:53:16 INFO - [Parent 9088, IPDL Background] WARNING: quota manager shutdown step: '0.000000s: startCrashBrowserTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3266
[task 2023-07-04T11:53:16.165Z] 11:53:16 INFO - [Parent 9088, IPDL Background] WARNING: quota manager shutdown step: '0.000000s: initiateShutdownWorkThreads', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3266
Updated•2 years ago
|
Comment 1•2 years ago
|
||
:jonco, since you are the author of the regressor, bug 1840744, could you take a look?
For more information, please visit BugBot documentation.
Comment 2•2 years ago
|
||
There have been 40 total failures in the last 7 days.
There are:
- 19 failures on windows11-64-2009-qr debug
- 4 failures on windows11-64-2009-mingwclang-qr debug
- 15 failures. on windows11-32-2009-qr debug
- 1 failure on windows11-32-2009-mingwclang-qr debug
- 1 failure on windows10-64-2009-qr debug
Recent failure log.
Daniel, as the owner of this component, can you help us assign the bug to someone? Thank you.
Updated•2 years ago
|
Comment 3•2 years ago
|
||
Looks like the assertion failure is in JS garbage collection code. Reclassifying to that component. Seems like jonco needs to take a look, as the author of the regressor.
Comment 4•2 years ago
|
||
(The failing assertion here was added in bug 1840744, the identified regressor, FWIW.)
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Updated•2 years ago
|
Assignee | ||
Comment 6•2 years ago
|
||
This seems to be failing on Windows only. The code to calculate MMU looks
correct and I don't see how it can result in something less than zero. We know
we can get non-monotonic timestamps sometimes, so let's try to work around this
on Windows.
The patch replaces everywhere in the statistics code where we calculate the
duration between two timestamps with a function that clamps the minimum to
zero, but only on Windows. Other platforms get an assert to make sure we don't
mess up.
Comment 8•2 years ago
|
||
bugherder |
Updated•2 years ago
|
Comment 9•2 years ago
•
|
||
Updated•2 years ago
|
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Updated•2 years ago
|
Assignee | ||
Comment 11•2 years ago
|
||
Looking at this again I realise that it's possible for this value to be zero.
Comment 12•2 years ago
|
||
Comment 13•2 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 15•1 year ago
|
||
This particular assertion failure seems to have stopped happening.
Updated•1 year ago
|
Updated•1 year ago
|
Description
•