1843532 - Intermittent Assertion failure: gcMax <= window, at /builds/worker/checkouts/gecko/js/src/gc/Statistics.cpp:1605

Status: RESOLVED WORKSFORME

(Core :: JavaScript: GC, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=422645012&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/G8kzgoskT5KcsBo-IoDTJw/runs/0/artifacts/public/logs/live_backing.log

---

[task 2023-07-14T10:29:46.886Z] 10:29:46     INFO - TEST-START | toolkit/content/tests/chrome/test_popup_keys.xhtml
[task 2023-07-14T10:29:46.889Z] 10:29:46     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/chrome/nsChromeRegistry.cpp:182
[task 2023-07-14T10:29:46.889Z] 10:29:46     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/chrome/nsChromeProtocolHandler.cpp:73
[task 2023-07-14T10:29:46.913Z] 10:29:46     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:46.992Z] 10:29:46     INFO - GECKO(1632) | [WARN  webrender::renderer::init] asking to enable_gpu_markers but no supporting extension was found
[task 2023-07-14T10:29:47.003Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: Could not get window class style: file /builds/worker/checkouts/gecko/widget/windows/nsWindow.cpp:7553
[task 2023-07-14T10:29:47.086Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.118Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.118Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.196Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.212Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.212Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.228Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.255Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.259Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.259Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.259Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.259Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.259Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.259Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.259Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.259Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.386Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.395Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.416Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.427Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.429Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.447Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.458Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.478Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.490Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.495Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.505Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.520Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.540Z] 10:29:47     INFO - GECKO(1632) | [Parent 9364, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:198
[task 2023-07-14T10:29:47.556Z] 10:29:47     INFO - GECKO(1632) | Assertion failure: gcMax <= window, at /builds/worker/checkouts/gecko/js/src/gc/Statistics.cpp:1605
[task 2023-07-14T10:29:47.917Z] 10:29:47     INFO -  Initializing stack-fixing for the first stack frame, this may take a while...
[task 2023-07-14T10:30:09.207Z] 10:30:09     INFO - GECKO(1632) | #01: js::gcstats::Statistics::computeMMU(mozilla::BaseTimeDuration<mozilla::TimeDurationValueCalculator>) const [js/src/gc/Statistics.cpp:1605]
[task 2023-07-14T10:30:09.207Z] 10:30:09     INFO - GECKO(1632) | #02: js::gcstats::Statistics::sendGCTelemetry() [js/src/gc/Statistics.cpp:1096]
[task 2023-07-14T10:30:09.208Z] 10:30:09     INFO - GECKO(1632) | #03: js::gcstats::Statistics::endSlice() [js/src/gc/Statistics.cpp:1265]
[task 2023-07-14T10:30:09.209Z] 10:30:09     INFO - GECKO(1632) | #04: js::gc::GCRuntime::gcCycle(bool, js::SliceBudget const&, JS::GCReason) [js/src/gc/GC.cpp:4181]
[task 2023-07-14T10:30:09.209Z] 10:30:09     INFO - GECKO(1632) | #05: js::gc::GCRuntime::collect(bool, js::SliceBudget const&, JS::GCReason) [js/src/gc/GC.cpp:4365]
[task 2023-07-14T10:30:09.209Z] 10:30:09     INFO - GECKO(1632) | #06: js::gc::GCRuntime::gcSlice(JS::GCReason, js::SliceBudget const&) [js/src/gc/GC.cpp:4467]
[task 2023-07-14T10:30:09.210Z] 10:30:09     INFO - GECKO(1632) | #07: JS::IncrementalGCSlice(JSContext*, JS::GCReason, js::SliceBudget const&) [js/src/gc/GCAPI.cpp:319]
[task 2023-07-14T10:30:09.210Z] 10:30:09     INFO - GECKO(1632) | #08: GarbageCollectImpl(JS::GCReason, nsJSContext::IsShrinking, js::SliceBudget const&) [dom/base/nsJSEnvironment.cpp:1053]
[task 2023-07-14T10:30:09.211Z] 10:30:09     INFO - GECKO(1632) | #09: nsJSContext::RunIncrementalGCSlice(JS::GCReason, nsJSContext::IsShrinking, js::SliceBudget&) [dom/base/nsJSEnvironment.cpp:1090]
[task 2023-07-14T10:30:09.211Z] 10:30:09     INFO - GECKO(1632) | #10: mozilla::CCGCScheduler::GCRunnerFiredDoGC(mozilla::TimeStamp, mozilla::GCRunnerStep const&) [dom/base/CCGCScheduler.cpp:427]
[task 2023-07-14T10:30:09.211Z] 10:30:09     INFO - GECKO(1632) | #11: mozilla::CCGCScheduler::GCRunnerFired(mozilla::TimeStamp) [dom/base/CCGCScheduler.cpp:386]
[task 2023-07-14T10:30:09.212Z] 10:30:09     INFO - GECKO(1632) | #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-14T10:30:09.212Z] 10:30:09     INFO - GECKO(1632) | #13: mozilla::IdleTaskRunner::Run() [xpcom/threads/IdleTaskRunner.cpp:134]
[task 2023-07-14T10:30:09.212Z] 10:30:09     INFO - GECKO(1632) | #14: mozilla::IdleTaskRunnerTask::Run() [xpcom/threads/IdleTaskRunner.cpp:47]
[task 2023-07-14T10:30:09.213Z] 10:30:09     INFO - GECKO(1632) | #15: mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex &> const&) [xpcom/threads/TaskController.cpp:880]
[task 2023-07-14T10:30:09.213Z] 10:30:09     INFO - GECKO(1632) | #16: mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex &> const&) [xpcom/threads/TaskController.cpp:746]
[task 2023-07-14T10:30:09.213Z] 10:30:09     INFO - GECKO(1632) | #17: mozilla::TaskController::ProcessPendingMTTask(bool) [xpcom/threads/TaskController.cpp:491]
[task 2023-07-14T10:30:09.214Z] 10:30:09     INFO - GECKO(1632) | #18: mozilla::detail::RunnableFunction<`lambda at /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:218:7'>::Run() [xpcom/threads/nsThreadUtils.h:549]
[task 2023-07-14T10:30:09.214Z] 10:30:09     INFO - GECKO(1632) | #19: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:1203]
[task 2023-07-14T10:30:09.214Z] 10:30:09     INFO - GECKO(1632) | #20: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:480]
[task 2023-07-14T10:30:09.215Z] 10:30:09     INFO - GECKO(1632) | #21: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:85]
[task 2023-07-14T10:30:09.215Z] 10:30:09     INFO - GECKO(1632) | #22: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:370]
[task 2023-07-14T10:30:09.215Z] 10:30:09     INFO - GECKO(1632) | #23: MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:364]
[task 2023-07-14T10:30:09.216Z] 10:30:09     INFO - GECKO(1632) | #24: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:346]
[task 2023-07-14T10:30:09.216Z] 10:30:09     INFO - GECKO(1632) | #25: nsBaseAppShell::Run() [widget/nsBaseAppShell.cpp:150]
[task 2023-07-14T10:30:09.217Z] 10:30:09     INFO - GECKO(1632) | #26: nsAppShell::Run() [widget/windows/nsAppShell.cpp:520]
[task 2023-07-14T10:30:09.217Z] 10:30:09     INFO - GECKO(1632) | #27: nsAppStartup::Run() [toolkit/components/startup/nsAppStartup.cpp:296]
[task 2023-07-14T10:30:09.217Z] 10:30:09     INFO - GECKO(1632) | #28: XREMain::XRE_mainRun() [toolkit/xre/nsAppRunner.cpp:5661]
[task 2023-07-14T10:30:09.218Z] 10:30:09     INFO - GECKO(1632) | #29: XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) [toolkit/xre/nsAppRunner.cpp:5862]
[task 2023-07-14T10:30:09.218Z] 10:30:09     INFO - GECKO(1632) | #30: XRE_main(int, char**, mozilla::BootstrapConfig const&) [toolkit/xre/nsAppRunner.cpp:5918]
[task 2023-07-14T10:30:09.219Z] 10:30:09     INFO - GECKO(1632) | #31: mozilla::BootstrapImpl::XRE_main(int, char**, mozilla::BootstrapConfig const&) [toolkit/xre/Bootstrap.cpp:45]
[task 2023-07-14T10:30:09.269Z] 10:30:09     INFO - GECKO(1632) | #32: NS_internal_main(int, char**, char**) [browser/app/nsBrowserApp.cpp:445]
[task 2023-07-14T10:30:09.282Z] 10:30:09     INFO - GECKO(1632) | #33: wmain(int, wchar_t**) [toolkit/xre/nsWindowsWMain.cpp:167]
[task 2023-07-14T10:30:09.282Z] 10:30:09     INFO - GECKO(1632) | #34: __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-14T10:30:09.284Z] 10:30:09     INFO -  fix-stacks: error: failed to read debug info file `wkernel32.pdb` for `C:\Windows\System32\KERNEL32.DLL`
[task 2023-07-14T10:30:09.284Z] 10:30:09     INFO -  fix-stacks: note: this is expected and harmless for all PDB files on opt automation runs
[task 2023-07-14T10:30:09.284Z] 10:30:09     INFO -  fix-stacks: The system cannot find the file specified. (os error 2)
[task 2023-07-14T10:30:09.284Z] 10:30:09     INFO - GECKO(1632) | #35: BaseThreadInitThunk [C:\Windows\System32\KERNEL32.DLL + 0x17d49]
[task 2023-07-14T10:30:09.287Z] 10:30:09     INFO -  fix-stacks: error: failed to read debug info file `wntdll.pdb` for `C:\Windows\SYSTEM32\ntdll.dll`
[task 2023-07-14T10:30:09.287Z] 10:30:09     INFO -  fix-stacks: note: this is expected and harmless for all PDB files on opt automation runs
[task 2023-07-14T10:30:09.287Z] 10:30:09     INFO -  fix-stacks: The system cannot find the file specified. (os error 2)
[task 2023-07-14T10:30:09.288Z] 10:30:09     INFO - GECKO(1632) | #36: RtlInitializeExceptionChain [C:\Windows\SYSTEM32\ntdll.dll + 0x6b74b]
[task 2023-07-14T10:30:09.288Z] 10:30:09     INFO - GECKO(1632) | #37: RtlClearBits [C:\Windows\SYSTEM32\ntdll.dll + 0x6b6cf]
[task 2023-07-14T10:30:09.289Z] 10:30:09     INFO - GECKO(1632) | [Child 6700, IPC I/O Child] WARNING: [A030BB53C3F0A98C.72273F41A7BE4FD4]: Ignoring message 'EVENT_MESSAGE' to peer 1.1 due to a missing broker: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:352
[task 2023-07-14T10:30:09.289Z] 10:30:09     INFO - GECKO(1632) | Exiting due to channel error.
[task 2023-07-14T10:30:09.289Z] 10:30:09     INFO - TEST-INFO | Main app process: exit 1
[task 2023-07-14T10:30:09.290Z] 10:30:09     INFO - Buffered messages logged at 10:29:46
[task 2023-07-14T10:30:09.290Z] 10:30:09     INFO - TEST-PASS | toolkit/content/tests/chrome/test_popup_keys.xhtml | keys enabled 

Comment 1

[Intermittent Failures Robot]

1 failures in 3309 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows11-32-2009-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1843532&startday=2023-07-10&endday=2023-07-16&tree=all

Comment 2

[Intermittent Failures Robot]

2 failures in 3520 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• mozilla-central: 1

Platform and build breakdown:

• windows11-64-2009-qr: 1
  • debug: 1
• windows11-64-2009-mingwclang-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1843532&startday=2023-07-17&endday=2023-07-23&tree=all

Comment 3

[Jon Coppeard (:jonco)]

Attachment: Bug 1843532 - Refactor Statistics::computeMMU to make it easier to understand r?sfink

Not a fix.

This method is pretty cryptic. I renamed the variables and added comments to
make it clearer what's happening here. Also I added a few assertions.

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/14f7f1a60e27
Refactor Statistics::computeMMU to make it easier to understand r=sfink

Comment 5

[Atila Butkovits]

https://hg.mozilla.org/mozilla-central/rev/14f7f1a60e27

Comment 6

[Intermittent Failures Robot]

1 failures in 3403 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows11-64-2009-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1843532&startday=2023-07-24&endday=2023-07-30&tree=all

Comment 7

[Jon Coppeard (:jonco)]

This doesn't seem to be failing any more.