This was found by enabling the float-cast-overflow check in UBSan and running existing tests. This type of issue can create inconsistencies across platforms, architectures and optimization levels.

Found with m-c 20220704-f7c192231f50

To enable this check add the following to your mozconfig:

ac_add_options --enable-undefined-sanitizer="float-cast-overflow"

This issue is found by the existing test: dom/canvas/test/webgl-conf/generated/test_conformance__glsl__bugs__angle-d3d11-compiler-error.html (and many others)

gecko/dom/base/CCGCScheduler.cpp:276:16: runtime error: -384.001 is outside the range of representable values of type 'unsigned int'
    #0 0x7f70004810b4 in mozilla::CCGCScheduler::NoteGCSliceEnd(mozilla::TimeStamp, mozilla::TimeStamp) /builds/worker/checkouts/gecko/dom/base/CCGCScheduler.cpp:276:16
    #1 0x7f70008cab6c in DOMGCSliceCallback(JSContext*, JS::GCProgress, JS::GCDescription const&) /builds/worker/checkouts/gecko/dom/base/nsJSEnvironment.cpp:1806:18
    #2 0x7f700b3be470 in js::gcstats::Statistics::endSlice() /builds/worker/checkouts/gecko/js/src/gc/Statistics.cpp:1219:7
    #3 0x7f700b340a21 in ~AutoGCSlice /builds/worker/checkouts/gecko/js/src/gc/Statistics.h:495:26
    #4 0x7f700b340a21 in js::gc::GCRuntime::gcCycle(bool, js::SliceBudget const&, JS::GCReason) /builds/worker/checkouts/gecko/js/src/gc/GC.cpp:3774:1
    #5 0x7f700b342940 in js::gc::GCRuntime::collect(bool, js::SliceBudget const&, JS::GCReason) /builds/worker/checkouts/gecko/js/src/gc/GC.cpp:3953:9
    #6 0x7f70008c3e41 in GarbageCollectImpl(JS::GCReason, nsJSContext::IsShrinking, js::SliceBudget const&) /builds/worker/checkouts/gecko/dom/base/nsJSEnvironment.cpp:1048:5
    #7 0x7f70008c4190 in nsJSContext::RunIncrementalGCSlice(JS::GCReason, nsJSContext::IsShrinking, js::SliceBudget&) /builds/worker/checkouts/gecko/dom/base/nsJSEnvironment.cpp:1085:3
    #8 0x7f700048348c in mozilla::CCGCScheduler::GCRunnerFiredDoGC(mozilla::TimeStamp, mozilla::GCRunnerStep const&) /builds/worker/checkouts/gecko/dom/base/CCGCScheduler.cpp:424:3
    #9 0x7f7000482c0a in mozilla::CCGCScheduler::GCRunnerFired(mozilla::TimeStamp) /builds/worker/checkouts/gecko/dom/base/CCGCScheduler.cpp:383:10
    #10 0x7f6ffd83a45f in std::function<bool (mozilla::TimeStamp)>::operator()(mozilla::TimeStamp) const /builds/worker/fetches/sysroot-x86_64-linux-gnu/usr/lib/gcc/x86_64-linux-gnu/7.5.0/../../../../include/c++/7.5.0/bits/std_function.h:706:14
    #11 0x7f6ffd83a028 in mozilla::IdleTaskRunner::Run() /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:125:14
    #12 0x7f7000483edc in mozilla::CCGCScheduler::RunNextCollectorTimer(JS::GCReason, mozilla::TimeStamp) /builds/worker/checkouts/gecko/dom/base/CCGCScheduler.cpp:490:13
    #13 0x7f70008ca59f in nsJSContext::MaybeRunNextCollectorSlice(nsIDocShell*, JS::GCReason) /builds/worker/checkouts/gecko/dom/base/nsJSEnvironment.cpp:1683:18
    #14 0x7f70095e090d in nsDocShell::OpenInitializedChannel(nsIChannel*, nsIURILoader*, unsigned int) /builds/worker/checkouts/gecko/docshell/base/nsDocShell.cpp:10722:3
    #15 0x7f70095d872d in nsDocShell::DoURILoad(nsDocShellLoadState*, mozilla::Maybe<unsigned int>, nsIRequest**) /builds/worker/checkouts/gecko/docshell/base/nsDocShell.cpp:10585:10
    #16 0x7f70095262df in nsDocShell::InternalLoad(nsDocShellLoadState*, mozilla::Maybe<unsigned int>) /builds/worker/checkouts/gecko/docshell/base/nsDocShell.cpp:9625:8
    #17 0x7f7009586939 in nsDocShell::LoadURI(nsDocShellLoadState*, bool, bool) /builds/worker/checkouts/gecko/docshell/base/nsDocShell.cpp:881:8
    #18 0x7f700085c12f in nsFrameLoader::ReallyStartLoadingInternal() /builds/worker/checkouts/gecko/dom/base/nsFrameLoader.cpp:780:23
    #19 0x7f700085b51e in nsFrameLoader::ReallyStartLoading() /builds/worker/checkouts/gecko/dom/base/nsFrameLoader.cpp:654:17
    #20 0x7f70005cecd6 in mozilla::dom::Document::MaybeInitializeFinalizeFrameLoaders() /builds/worker/checkouts/gecko/dom/base/Document.cpp:9374:13
    #21 0x7f700068606f in applyImpl<mozilla::dom::Document, void (mozilla::dom::Document::*)()> /builds/worker/workspace/obj-build/dist/include/nsThreadUtils.h:1147:12
    #22 0x7f700068606f in apply<mozilla::dom::Document, void (mozilla::dom::Document::*)()> /builds/worker/workspace/obj-build/dist/include/nsThreadUtils.h:1153:12
    #23 0x7f700068606f in mozilla::detail::RunnableMethodImpl<mozilla::dom::Document*, void (mozilla::dom::Document::*)(), true, (mozilla::RunnableKind)0>::Run() /builds/worker/workspace/obj-build/dist/include/nsThreadUtils.h:1200:13
    #24 0x7f70003145a4 in nsContentUtils::RemoveScriptBlocker() /builds/worker/checkouts/gecko/dom/base/nsContentUtils.cpp:5732:17
    #25 0x7f70005c0b68 in mozilla::dom::Document::EndUpdate() /builds/worker/checkouts/gecko/dom/base/Document.cpp:7942:3
    #26 0x7f6fff600c03 in nsHtml5AutoFlush::~nsHtml5AutoFlush() /builds/worker/checkouts/gecko/parser/html/nsHtml5TreeOpExecutor.cpp:97:18
    #27 0x7f6fff600218 in nsHtml5TreeOpExecutor::RunFlushLoop() /builds/worker/checkouts/gecko/parser/html/nsHtml5TreeOpExecutor.cpp:712:5
    #28 0x7f6fff60a4c0 in nsHtml5ExecutorReflusher::Run() /builds/worker/checkouts/gecko/parser/html/nsHtml5TreeOpExecutor.cpp:79:16
    #29 0x7f6ffd84a49f in mozilla::SchedulerGroup::Runnable::Run() /builds/worker/checkouts/gecko/xpcom/threads/SchedulerGroup.cpp:140:20
    #30 0x7f6ffd89d622 in mozilla::RunnableTask::Run() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:538:16
    #31 0x7f6ffd85de6d in mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:851:26
    #32 0x7f6ffd85afd8 in mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:683:15
    #33 0x7f6ffd85b700 in mozilla::TaskController::ProcessPendingMTTask(bool) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:461:36
    #34 0x7f6ffd8a6651 in operator() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:187:37
    #35 0x7f6ffd8a6651 in mozilla::detail::RunnableFunction<mozilla::TaskController::InitializeInternal()::$_0>::Run() /builds/worker/workspace/obj-build/dist/include/nsThreadUtils.h:531:5
    #36 0x7f6ffd87f00b in nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1205:16
    #37 0x7f6ffd889504 in NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:465:10
    #38 0x7f6ffee71c08 in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:85:21
    #39 0x7f6ffed0f671 in RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:380:10
    #40 0x7f6ffed0f671 in RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:373:3
    #41 0x7f6ffed0f671 in MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:355:3
    #42 0x7f70056edcb7 in nsBaseAppShell::Run() /builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp:150:27
    #43 0x7f700a432b37 in XRE_RunAppShell() /builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp:875:20
    #44 0x7f6ffed0f671 in RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:380:10
    #45 0x7f6ffed0f671 in RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:373:3
    #46 0x7f6ffed0f671 in MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:355:3
    #47 0x7f700a431cdb in XRE_InitChildProcess(int, char**, XREChildData const*) /builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp:734:34
    #48 0x55cc58cd5825 in content_process_main(mozilla::Bootstrap*, int, char**) /builds/worker/checkouts/gecko/browser/app/../../ipc/contentproc/plugin-container.cpp:57:28
    #49 0x55cc58cd5bd6 in main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:338:18
    #50 0x7f70244efb96 in __libc_start_main /tmp/glibc/csu/../csu/libc-start.c:310
    #51 0x55cc58c15c80 in _start (/builds/worker/workspace/build/application/firefox/firefox+0x72c80) (BuildId: 3b22a95bcd67bed31200e38e427c48e5f84f3827)

Set release status flags based on info from the regressing bug 1774651

:sfink, since you are the author of the regressor, bug 1774651, could you take a look?
For more information, please visit auto_nag documentation.

This code is reporting a cast issue in some stat reporting code … definitely not a failure case which matters for user experience.
What would be the way to proper way to move this location in a skip-list, or to avoid this reporting?

The rounding issue is expected, this is truncating to an integral 0-100 percent. I don't think this is what the check is complaining about.

The negative value is very much not. It seems like the error is coming from

uint32_t percent =
      uint32_t(idleDuration.ToSeconds() / sliceDuration.ToSeconds() * 100);

which means that either one or the other is negative, or idleDuration < 0. For the latter, idleDuration = sliceDuration - nonIdleDuration so negative would mean nonIdleDuration > sliceDuration. The only way nonIdleDuration is set to a nonzero value different from sliceDuration is with

    if (*mTriggeredGCDeadline < aEnd) {
      // Overran the idle deadline.
      nonIdleDuration = aEnd - *mTriggeredGCDeadline;
    }

and because of the if (...), that will always be positive. So it doesn't seem possible.

Which leaves the case of a negative duration. By the logic above, nonIdleDuration = aEnd - *mTriggeredGCDeadline but it can't be negative because of the if (...). sliceDuration = aEnd - aStart from its sole assignment. So it seems aStart and aEnd are out of order.

There is a single caller:

      sScheduler.NoteGCSliceEnd(aDesc.lastSliceStart(aCx), aDesc.lastSliceEnd(aCx));

The slice begin/end gets set in Statistics::beginSlice and endSlice from js::ReallyNow() which calls mozilla::TimeStamp::Now().

I can add an assert when setting a slice's end time that time is flowing forward, though it looks like it already checks for that and aborts in that case. Still, in an opt build none of those aborts will crash, and even in a debug build some of them won't. I would have expected the end timestamp to be null in this case, though, which would assert in a debug build.

@tsmith, is this a debug or opt build?

Oops, didn't mean to clear needinfo.

It is an opt build.

I am trying to collect a rr trace but this issue is not consistently reproducible. I'll keep trying and create a Pernosco session if successful.

A Pernosco session is available here: https://pernos.co/debug/zQDTO-TgicDfanzld5YEcA/index.html

(In reply to Tyson Smith [:tsmith] from comment #7)

A Pernosco session is available here: https://pernos.co/debug/zQDTO-TgicDfanzld5YEcA/index.html

Wow, thank you, that is extremely helpful.

Here's my logic error above:

The only way nonIdleDuration is set to a nonzero value different from sliceDuration is with

    if (*mTriggeredGCDeadline < aEnd) {
      // Overran the idle deadline.
      nonIdleDuration = aEnd - *mTriggeredGCDeadline;
    }

and because of the if (...), that will always be positive. So it doesn't seem possible.

Past-me, you are an idiot. Sure, it's positive, but that's not the point: the point is that it's larger than it should be, larger than the difference between aStart and aEnd. The deadline had expired long before aStart.

I just started looking at the recording, but it should be straightforward to track down at this point. Thanks again!

What happened:

• idle slice runs and computes a deadline 50ms in the future
• start timestamp is grabbed and used with the deadline to compute the budget: 49ms.
• ...175ms mysteriously passes...
• while still creating the SliceBudget object, the current time is fetched and added to the budget to serve as a budgeted deadline.
• GC starts
• Statistics::beginSlice records the current time, which is 125ms past the deadline. This will be used as aStart.

So the bug here is pretty straightforward. This should be treated a slice that started idle but overran, by a lot. Or maybe I can stop the slice from happening somehow.

But I kind of want to know how this happened -- it shouldn't be doing anything in between computing the idle deadline and beginning the slice. It should all be pretty boring CPU-only code. Sure, it goes a little slower because of the sanitizer, but 175ms is ridiculous (and it's a suspiciously round number too). When I look at the rr counters, the event counter is identical (554091). The number of instructions says that only 45k instructions and 0 events ran between the two calls to TimeStamp::Now(). 0 events means no system calls or anything.

Unless rr fuzzes clock_gettime(CLOCK_MONOTONIC, ...)? Or maybe the clock jumped forward? Hm... actually, the trace says that clock_gettime is handled by sanitizer_common_interceptors. So maybe it's the sanitizer fuzzing the time value? That's pretty cool if so. And it would mean I can just fix the bug above.

https://hg.mozilla.org/mozilla-central/rev/29f86bbb3299