Open Bug 1436778 Opened 6 years ago Updated 2 years ago

UBSan: value is outside the range of representable values of type 'unsigned int' /dom/performance/PerformanceTiming.cpp:92

Categories

(Core :: Performance, defect)

60 Branch
defect

Tracking

()

Performance Impact none
Tracking Status
firefox98 --- wontfix

People

(Reporter: tsmith, Unassigned, NeedInfo)

References

(Blocks 2 open bugs)

Details

(Keywords: csectype-undefined, leave-open)

Attachments

(1 file)

This seems to be triggered after a few minutes with regular browsing.

Found in mozilla-central changeset: 402372:3df7961bad2c. Built with -fsanitize=enum,float-cast-overflow,signed-integer-overflow

/dom/performance/PerformanceTiming.cpp:92:27: runtime error: -4.5 is outside the range of representable values of type 'unsigned int'
    #0 0x7f6f67cb6e3a in mozilla::dom::PerformanceTiming::PerformanceTiming(mozilla::dom::Performance*, nsITimedChannel*, nsIHttpChannel*, double) /dom/performance/PerformanceTiming.cpp:92:27
    #1 0x7f6f67cae2ea in mozilla::dom::PerformanceMainThread::Timing() /dom/performance/PerformanceMainThread.cpp:83:19
    #2 0x7f6f64c37068 in mozilla::dom::PerformanceBinding::get_timing(JSContext*, JS::Handle<JSObject*>, mozilla::dom::Performance*, JSJitGetterCallArgs) /objdir-ff-ubsan/dom/bindings/PerformanceBinding.cpp:100:69
    #3 0x7f6f65fe64aa in mozilla::dom::GenericBindingGetter(JSContext*, unsigned int, JS::Value*) /dom/bindings/BindingUtils.cpp:2906:13
    #4 0x7f6f6e46a88e in CallJSNative /js/src/jscntxtinlines.h:291:15
    #5 0x7f6f6e46a88e in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct) /js/src/vm/Interpreter.cpp:473
    #6 0x7f6f6e46b4cf in InternalCall(JSContext*, js::AnyInvokeArgs const&) /js/src/vm/Interpreter.cpp:522:12
    #7 0x7f6f6e46b6aa in js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>) /js/src/vm/Interpreter.cpp:541:10
    #8 0x7f6f6e46c898 in js::CallGetter(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>) /js/src/vm/Interpreter.cpp:656:12
    #9 0x7f6f6f3fc5f5 in CallGetter(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::Value>, JS::Handle<js::Shape*>, JS::MutableHandle<JS::Value>) /js/src/vm/NativeObject.cpp:2145:16
    #10 0x7f6f6f3dc4c1 in GetExistingProperty<js::AllowGC::CanGC> /js/src/vm/NativeObject.cpp:2198:12
    #11 0x7f6f6f3dc4c1 in NativeGetPropertyInline<js::AllowGC::CanGC> /js/src/vm/NativeObject.cpp:2401
    #12 0x7f6f6f3dc4c1 in js::NativeGetProperty(JSContext*, JS::Handle<js::NativeObject*>, JS::Handle<JS::Value>, JS::Handle<jsid>, JS::MutableHandle<JS::Value>) /js/src/vm/NativeObject.cpp:2437
    #13 0x7f6f6e3d2eb4 in js::GetProperty(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::Value>, JS::Handle<jsid>, JS::MutableHandle<JS::Value>) /js/src/vm/NativeObject.h:1630:12
    #14 0x7f6f6e3d2cc7 in js::GetProperty(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::Value>, js::PropertyName*, JS::MutableHandle<JS::Value>) /js/src/jsobj.h:822:12
    #15 0x7f6f6e472593 in js::GetProperty(JSContext*, JS::Handle<JS::Value>, JS::Handle<js::PropertyName*>, JS::MutableHandle<JS::Value>) /js/src/vm/Interpreter.cpp:4405:12
    #16 0x7f6f6e482647 in GetPropertyOperation(JSContext*, js::InterpreterFrame*, JS::Handle<JSScript*>, unsigned char*, JS::MutableHandle<JS::Value>, JS::MutableHandle<JS::Value>) /js/src/vm/Interpreter.cpp:219:12
    #17 0x7f6f6e43f114 in Interpret(JSContext*, js::RunState&) /js/src/vm/Interpreter.cpp:2815:10
    #18 0x7f6f6e433428 in js::RunScript(JSContext*, js::RunState&) /js/src/vm/Interpreter.cpp:423:12
    #19 0x7f6f6e46a779 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct) /js/src/vm/Interpreter.cpp:495:15
    #20 0x7f6f6e46b4cf in InternalCall(JSContext*, js::AnyInvokeArgs const&) /js/src/vm/Interpreter.cpp:522:12
    #21 0x7f6f6e46b6aa in js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>) /js/src/vm/Interpreter.cpp:541:10
    #22 0x7f6f6ef228a0 in js::fun_call(JSContext*, unsigned int, JS::Value*) /js/src/jsfun.cpp:1185:12
    #23 0x7f6f6e46a88e in CallJSNative /js/src/jscntxtinlines.h:291:15
    #24 0x7f6f6e46a88e in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct) /js/src/vm/Interpreter.cpp:473
    #25 0x7f6f6e46b4cf in InternalCall(JSContext*, js::AnyInvokeArgs const&) /js/src/vm/Interpreter.cpp:522:12
    #26 0x7f6f6e45088f in Interpret(JSContext*, js::RunState&) /js/src/vm/Interpreter.cpp:3096:18
    #27 0x7f6f6e433428 in js::RunScript(JSContext*, js::RunState&) /js/src/vm/Interpreter.cpp:423:12
    #28 0x7f6f6e46d0f3 in js::ExecuteKernel(JSContext*, JS::Handle<JSScript*>, JSObject&, JS::Value const&, js::AbstractFramePtr, JS::Value*) /js/src/vm/Interpreter.cpp:706:15
    #29 0x7f6f6e46d5d9 in js::Execute(JSContext*, JS::Handle<JSScript*>, JSObject&, JS::Value*) /js/src/vm/Interpreter.cpp:738:12
    #30 0x7f6f6ee923b8 in ExecuteScript(JSContext*, JS::Handle<JSObject*>, JS::Handle<JSScript*>, JS::Value*) /js/src/jsapi.cpp:4715:12
    #31 0x7f6f6ee92c52 in ExecuteScript(JSContext*, JS::AutoObjectVector&, JS::Handle<JSScript*>, JS::Value*) /js/src/jsapi.cpp:4734:12
    #32 0x7f6f6ee927df in JS_ExecuteScript(JSContext*, JS::AutoObjectVector&, JS::Handle<JSScript*>, JS::MutableHandle<JS::Value>) /js/src/jsapi.cpp:4755:12
    #33 0x7f6f6469866a in nsJSUtils::ExecutionContext::CompileAndExec(JS::CompileOptions&, JS::SourceBufferHolder&, JS::MutableHandle<JSScript*>) /dom/base/nsJSUtils.cpp:266:8
    #34 0x7f6f67d59635 in mozilla::dom::ScriptLoader::EvaluateScript(mozilla::dom::ScriptLoadRequest*) /dom/script/ScriptLoader.cpp:2286:25
    #35 0x7f6f67d55361 in mozilla::dom::ScriptLoader::ProcessRequest(mozilla::dom::ScriptLoadRequest*) /dom/script/ScriptLoader.cpp:1929:10
    #36 0x7f6f67d536d0 in mozilla::dom::ScriptLoader::ProcessInlineScript(nsIScriptElement*, mozilla::dom::ScriptKind) /dom/script/ScriptLoader.cpp:1572:10
    #37 0x7f6f67d448c2 in mozilla::dom::ScriptLoader::ProcessScriptElement(nsIScriptElement*) /dom/script/ScriptLoader.cpp:1307:10
    #38 0x7f6f67d44138 in mozilla::dom::ScriptElement::MaybeProcessScript() /dom/script/ScriptElement.cpp:147:18
    #39 0x7f6f63299fa1 in nsIScriptElement::AttemptToExecute() /objdir-ff-ubsan/dist/include/nsIScriptElement.h:247:18
    #40 0x7f6f6327687f in nsHtml5TreeOpExecutor::RunScript(nsIContent*) /parser/html/nsHtml5TreeOpExecutor.cpp:736:22
    #41 0x7f6f632727e6 in nsHtml5TreeOpExecutor::RunFlushLoop() /parser/html/nsHtml5TreeOpExecutor.cpp:540:7
    #42 0x7f6f6329dc01 in nsHtml5ExecutorFlusher::Run() /parser/html/nsHtml5StreamParser.cpp:131:20
    #43 0x7f6f609334c0 in mozilla::SchedulerGroup::Runnable::Run() /xpcom/threads/SchedulerGroup.cpp:395:25
    #44 0x7f6f60970301 in nsThread::ProcessNextEvent(bool, bool*) /xpcom/threads/nsThread.cpp:1040:14
    #45 0x7f6f609ad37a in NS_ProcessNextEvent(nsIThread*, bool) /xpcom/threads/nsThreadUtils.cpp:517:10
    #46 0x7f6f61d08381 in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /ipc/glue/MessagePump.cpp:97:21
    #47 0x7f6f61b67090 in MessageLoop::Run() /ipc/chromium/src/base/message_loop.cc:299:3
    #48 0x7f6f67f81b95 in nsBaseAppShell::Run() /widget/nsBaseAppShell.cpp:157:27
    #49 0x7f6f6e05a73d in XRE_RunAppShell() /toolkit/xre/nsEmbedFunctions.cpp:873:22
    #50 0x7f6f61d093a8 in mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) /ipc/glue/MessagePump.cpp:269:9
    #51 0x7f6f61b67090 in MessageLoop::Run() /ipc/chromium/src/base/message_loop.cc:299:3
    #52 0x7f6f6e059c8e in XRE_InitChildProcess(int, char**, XREChildData const*) /toolkit/xre/nsEmbedFunctions.cpp:699:34
    #53 0x517a89 in content_process_main(mozilla::Bootstrap*, int, char**) /browser/app/../../ipc/contentproc/plugin-container.cpp:63:30
    #54 0x517c32 in main /browser/app/nsBrowserApp.cpp:280:18
    #55 0x7f6f9899b1c0 in __libc_start_main /build/glibc-itYbWN/glibc-2.26/csu/../csu/libc-start.c:308
    #56 0x4207a9 in _start (/objdir-ff-ubsan/dist/bin/firefox+0x4207a9)
I don't see anything related to devtools here and PerformanceTiming.cpp is supposed to link to Core/DOM. Moving.
Component: Developer Tools: Performance Tools (Profiler/Timeline) → DOM
Product: Firefox → Core
Worth looking further into? Could you set a priority number?
Flags: needinfo?(amarchesini)
Tom, Is it something that can be fixed with your latest changes?
Flags: needinfo?(amarchesini) → needinfo?(tom)
This is the line:

>     Telemetry::Accumulate(Telemetry::TIME_TO_RESPONSE_START_MS,
>                          mTimingData->ResponseStartHighRes(aPerformance) -
>                          mTimingData->ZeroTime());

Calling

> Accumulate(HistogramID aHistogram, uint32_t aSample)

At the time this was logged, we didn't have Timing Jitter; but clamping was enabled and it was probably at 2ms.

The code has changed significantly since then. Tyson, do you still see this? If not I'm inclined to close as Invalid.
Flags: needinfo?(tom) → needinfo?(twsmith)
I was able to trigger the issue again by opening random news sites and google maps.
mozilla-central changeset: 409900:7b9da7139d94 from this morning.
Built with -fsanitize=enum,float-cast-overflow

dom/performance/PerformanceTiming.cpp:95:27: runtime error: -2 is outside the range of representable values of type 'unsigned int'
    #0 0x7fc89b62b851 in mozilla::dom::PerformanceTiming::PerformanceTiming(mozilla::dom::Performance*, nsITimedChannel*, nsIHttpChannel*, double) dom/performance/PerformanceTiming.cpp:95:27
    #1 0x7fc89b6249d0 in mozilla::dom::PerformanceMainThread::Timing() dom/performance/PerformanceMainThread.cpp:83:19
    #2 0x7fc899eb34bc in mozilla::dom::PerformanceBinding::get_timing(JSContext*, JS::Handle<JSObject*>, mozilla::dom::Performance*, JSJitGetterCallArgs) objdir-ff-ubsan/dom/bindings/PerformanceBinding.cpp:106:69
    #3 0x7fc89a602314 in mozilla::dom::GenericBindingGetter(JSContext*, unsigned int, JS::Value*) dom/bindings/BindingUtils.cpp:2905:13
    #4 0x7fc89e9a9d35 in CallJSNative js/src/vm/JSContext-inl.h:290:15
    #5 0x7fc89e9a9d35 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct) js/src/vm/Interpreter.cpp:467
    #6 0x7fc89e9aa439 in InternalCall(JSContext*, js::AnyInvokeArgs const&) js/src/vm/Interpreter.cpp:516:12
    #7 0x7fc89e9aa4e7 in js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>) js/src/vm/Interpreter.cpp:535:10
    #8 0x7fc89e9aac4b in js::CallGetter(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>) js/src/vm/Interpreter.cpp:650:12
    #9 0x7fc89f2019f7 in CallGetter js/src/vm/NativeObject.cpp:2155:16
    #10 0x7fc89f2019f7 in GetExistingProperty<js::AllowGC::CanGC> js/src/vm/NativeObject.cpp:2208
    #11 0x7fc89f2019f7 in NativeGetPropertyInline<js::AllowGC::CanGC> js/src/vm/NativeObject.cpp:2410
    #12 0x7fc89f2019f7 in js::NativeGetProperty(JSContext*, JS::Handle<js::NativeObject*>, JS::Handle<JS::Value>, JS::Handle<jsid>, JS::MutableHandle<JS::Value>) js/src/vm/NativeObject.cpp:2446
    #13 0x7fc89e937787 in js::GetProperty(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::Value>, JS::Handle<jsid>, JS::MutableHandle<JS::Value>) js/src/vm/NativeObject.h:1629:12
    #14 0x7fc89e9ad878 in GetProperty js/src/vm/JSObject.h:821:12
    #15 0x7fc89e9ad878 in js::GetProperty(JSContext*, JS::Handle<JS::Value>, JS::Handle<js::PropertyName*>, JS::MutableHandle<JS::Value>) js/src/vm/Interpreter.cpp:4395
    #16 0x7fc89e99b8ea in GetPropertyOperation js/src/vm/Interpreter.cpp:213:12
    #17 0x7fc89e99b8ea in Interpret(JSContext*, js::RunState&) js/src/vm/Interpreter.cpp:2803
    #18 0x7fc89e98dc86 in js::RunScript(JSContext*, js::RunState&) js/src/vm/Interpreter.cpp:417:12
    #19 0x7fc89e9a9e01 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct) js/src/vm/Interpreter.cpp:489:15
    #20 0x7fc89e9aa439 in InternalCall(JSContext*, js::AnyInvokeArgs const&) js/src/vm/Interpreter.cpp:516:12
    #21 0x7fc89e9aa4e7 in js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>) js/src/vm/Interpreter.cpp:535:10
    #22 0x7fc89f1876d9 in js::fun_call(JSContext*, unsigned int, JS::Value*) js/src/vm/JSFunction.cpp:1182:12
    #23 0x7fc89e9a9d35 in CallJSNative js/src/vm/JSContext-inl.h:290:15
    #24 0x7fc89e9a9d35 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct) js/src/vm/Interpreter.cpp:467
    #25 0x7fc89e9aa439 in InternalCall(JSContext*, js::AnyInvokeArgs const&) js/src/vm/Interpreter.cpp:516:12
    #26 0x7fc89e9a3b5c in CallFromStack js/src/vm/Interpreter.cpp:522:12
    #27 0x7fc89e9a3b5c in Interpret(JSContext*, js::RunState&) js/src/vm/Interpreter.cpp:3084
    #28 0x7fc89e98dc86 in js::RunScript(JSContext*, js::RunState&) js/src/vm/Interpreter.cpp:417:12
    #29 0x7fc89e9aafb7 in js::ExecuteKernel(JSContext*, JS::Handle<JSScript*>, JSObject&, JS::Value const&, js::AbstractFramePtr, JS::Value*) js/src/vm/Interpreter.cpp:700:15
    #30 0x7fc89e9ab32b in js::Execute(JSContext*, JS::Handle<JSScript*>, JSObject&, JS::Value*) js/src/vm/Interpreter.cpp:732:12
    #31 0x7fc89efce83f in ExecuteScript(JSContext*, JS::Handle<JSObject*>, JS::Handle<JSScript*>, JS::Value*) js/src/jsapi.cpp:4710:12
    #32 0x7fc89efcea06 in ExecuteScript(JSContext*, JS::AutoVector<JSObject*>&, JS::Handle<JSScript*>, JS::Value*) js/src/jsapi.cpp:4729:12
    #33 0x7fc899bfb32a in nsJSUtils::ExecutionContext::CompileAndExec(JS::CompileOptions&, JS::SourceBufferHolder&, JS::MutableHandle<JSScript*>) dom/base/nsJSUtils.cpp:268:8
    #34 0x7fc89b67eac9 in mozilla::dom::ScriptLoader::EvaluateScript(mozilla::dom::ScriptLoadRequest*) dom/script/ScriptLoader.cpp:2321:25
    #35 0x7fc89b67c78e in mozilla::dom::ScriptLoader::ProcessRequest(mozilla::dom::ScriptLoadRequest*) dom/script/ScriptLoader.cpp:1950:10
    #36 0x7fc89b67b4e1 in mozilla::dom::ScriptLoader::ProcessInlineScript(nsIScriptElement*, mozilla::dom::ScriptKind) dom/script/ScriptLoader.cpp:1591:10
    #37 0x7fc89b6721b3 in mozilla::dom::ScriptLoader::ProcessScriptElement(nsIScriptElement*) dom/script/ScriptLoader.cpp:1310:10
    #38 0x7fc89b671c1c in mozilla::dom::ScriptElement::MaybeProcessScript() dom/script/ScriptElement.cpp:141:18
    #39 0x7fc89922d5ee in nsIScriptElement::AttemptToExecute() objdir-ff-ubsan/dist/include/nsIScriptElement.h:247:18
    #40 0x7fc89920ff57 in nsHtml5TreeOpExecutor::RunScript(nsIContent*) parser/html/nsHtml5TreeOpExecutor.cpp:738:22
    #41 0x7fc89920db41 in nsHtml5TreeOpExecutor::RunFlushLoop() parser/html/nsHtml5TreeOpExecutor.cpp:537:7
    #42 0x7fc89922f305 in nsHtml5ExecutorFlusher::Run() parser/html/nsHtml5StreamParser.cpp:133:18
    #43 0x7fc897ed885f in mozilla::SchedulerGroup::Runnable::Run() xpcom/threads/SchedulerGroup.cpp:415:25
    #44 0x7fc897ee2cc1 in nsThread::ProcessNextEvent(bool, bool*) xpcom/threads/nsThread.cpp:1096:14
    #45 0x7fc897eff670 in NS_ProcessNextEvent(nsIThread*, bool) xpcom/threads/nsThreadUtils.cpp:519:10
    #46 0x7fc89891fd2b in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) ipc/glue/MessagePump.cpp:97:21
    #47 0x7fc89884d1d9 in RunHandler ipc/chromium/src/base/message_loop.cc:319:3
    #48 0x7fc89884d1d9 in MessageLoop::Run() ipc/chromium/src/base/message_loop.cc:299
    #49 0x7fc89b792906 in nsBaseAppShell::Run() widget/nsBaseAppShell.cpp:157:27
    #50 0x7fc89e793cf4 in XRE_RunAppShell() toolkit/xre/nsEmbedFunctions.cpp:893:22
    #51 0x7fc89884d1d9 in RunHandler ipc/chromium/src/base/message_loop.cc:319:3
    #52 0x7fc89884d1d9 in MessageLoop::Run() ipc/chromium/src/base/message_loop.cc:299
    #53 0x7fc89e7938d4 in XRE_InitChildProcess(int, char**, XREChildData const*) toolkit/xre/nsEmbedFunctions.cpp:719:34
    #54 0x42d216 in content_process_main(mozilla::Bootstrap*, int, char**) browser/app/../../ipc/contentproc/plugin-container.cpp:50:30
    #55 0x42d2f8 in main browser/app/nsBrowserApp.cpp:280:18
    #56 0x7fc8bc76e1c0 in __libc_start_main /build/glibc-itYbWN/glibc-2.26/csu/../csu/libc-start.c:308
    #57 0x407159 in _start (objdir-ff-ubsan/dist/bin/firefox+0x407159)
Flags: needinfo?(twsmith)
Assignee: nobody → tom
Priority: -- → P2
Keywords: leave-open
Comment on attachment 8966693 [details]
Bug 1436778 Add an assertion to hopefully get a reproduction for a hard-to-repro timer jitter bug

https://reviewboard.mozilla.org/r/235402/#review241244

Replacing NS_WARNING with a MOZ_ASSERT will make this code to crash in debug builds. This seems an easier way to detect if/when this happens.

::: dom/performance/PerformanceTiming.cpp:89
(Diff revision 1)
>      aPerformance->IsSystemPrincipal()
>      ? aZeroTime
>      : nsRFPService::ReduceTimePrecisionAsMSecs(aZeroTime,
>          aPerformance->GetRandomTimelineSeed())));
>  
> +  int64_t timeToResponseStart = 

extra space after '='

::: dom/performance/PerformanceTiming.cpp:93
(Diff revision 1)
>  
> +  int64_t timeToResponseStart = 
> +    mTimingData->ResponseStartHighRes(aPerformance) - mTimingData->ZeroTime();
> +  if (timeToResponseStart < 0) {
> +      NS_WARNING(nsPrintfCString("Heisenbug Reproduced: Please file line in 1436778. %s %f - %f (%f)",
> +          (aPerformance->IsSystemPrincipal() ? "System" : "Not-System"), 

extra space here as well.

::: dom/performance/PerformanceTiming.cpp:95
(Diff revision 1)
> +    mTimingData->ResponseStartHighRes(aPerformance) - mTimingData->ZeroTime();
> +  if (timeToResponseStart < 0) {
> +      NS_WARNING(nsPrintfCString("Heisenbug Reproduced: Please file line in 1436778. %s %f - %f (%f)",
> +          (aPerformance->IsSystemPrincipal() ? "System" : "Not-System"), 
> +          mTimingData->ResponseStartHighRes(aPerformance),
> +          mTimingData->ZeroTime(), aZeroTime).get());

I don't see how this warning can be useful.
What about:

#ifdef DEBUG
int64_t timeToResponseStart = ...
MOZ_ASSERT(timeToResponseStart >=0, "Heisenbug Reproduced: Please file line in 1436778");
Attachment #8966693 - Flags: review?(amarchesini)
(In reply to Andrea Marchesini [:baku] from comment #7)
> Replacing NS_WARNING with a MOZ_ASSERT will make this code to crash in debug
> builds. This seems an easier way to detect if/when this happens.
> 
> ...
>
> I don't see how this warning can be useful.
> What about:
> 
> #ifdef DEBUG
> int64_t timeToResponseStart = ...
> MOZ_ASSERT(timeToResponseStart >=0, "Heisenbug Reproduced: Please file line
> in 1436778");

I switched it to an NS_ERROR paired with an assert, because I need the local variables; but MOZ_ASSERT can't take a printf style string.
(In reply to Tom Ritter [:tjr] from comment #9)
> I switched it to an NS_ERROR paired with an assert, because I need the local
> variables; but MOZ_ASSERT can't take a printf style string.

Just found MOZ_CRASH_UNSAFE_PRINTF, switched to that
Comment on attachment 8966693 [details]
Bug 1436778 Add an assertion to hopefully get a reproduction for a hard-to-repro timer jitter bug

https://reviewboard.mozilla.org/r/235402/#review242190

Please expose this just to debug builds.

::: dom/performance/PerformanceTiming.cpp:89
(Diff revision 3)
>      aPerformance->IsSystemPrincipal()
>      ? aZeroTime
>      : nsRFPService::ReduceTimePrecisionAsMSecs(aZeroTime,
>          aPerformance->GetRandomTimelineSeed())));
>  
> +  if (mTimingData->ResponseStartHighRes(aPerformance) - mTimingData->ZeroTime() < 0) {

#ifdef DEBUG
if (mTimingData->Resp... {
}
#endif
Attachment #8966693 - Flags: review?(amarchesini) → review+
Keywords: checkin-needed
Pushed by ryanvm@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/1e6febc9f5af
Add an assertion to hopefully get a reproduction for a hard-to-repro timer jitter bug r=baku
Keywords: checkin-needed
At this point, I believe this isn't related to timer clamping/jittering (although timer clamping can mask the issue.)

By changing my assertion to use the underlying, unclamped data

>   if (mTimingData->TimeStampToDOMHighRes(aPerformance, mTimingData->mResponseStart) - aZeroTime < 0) {
>    MOZ_CRASH_UNSAFE_PRINTF("Heisenbug Reproduced: Please file line in 1436778. %f - %f",
>      mTimingData->TimeStampToDOMHighRes(aPerformance, mTimingData->mResponseStart),
>      aZeroTime);
>  }

We still see the assertion file. Note that the assertion needs to be _outside_ the if() { telemetry } block. But it seems like mResponseStart should always be > aZeroTime (which is actually navigationStart.)
Assignee: tom → nobody
The leave-open keyword is there and there is no activity for 6 months.
:hsinyi, maybe it's time to close this bug?
Flags: needinfo?(htsai)
Blocks: ubsan

Hey Tyson, do you still see this issue recently? Thanks

Flags: needinfo?(htsai) → needinfo?(twsmith)

Yes I can still repro it in a matter of seconds with a m-c build.

A mozconfig with the following should do what you need, if you want a build.
ac_add_options --enable-address-sanitizer
ac_add_options --enable-undefined-sanitizer="enum,float-cast-overflow"

Flags: needinfo?(twsmith)
Component: DOM → DOM: Core & HTML

The leave-open keyword is there and there is no activity for 6 months.
:hsinyi, maybe it's time to close this bug?

Flags: needinfo?(htsai)

If we can still repo it, then we should keep it open

Flags: needinfo?(htsai)

The leave-open keyword is there and there is no activity for 6 months.
:hsinyi, maybe it's time to close this bug?

Flags: needinfo?(htsai)

(In reply to Release mgmt bot [:sylvestre / :calixte / :marco for bugbug] from comment #22)

The leave-open keyword is there and there is no activity for 6 months.
:hsinyi, maybe it's time to close this bug?

no.

Component: DOM: Core & HTML → Performance
Flags: needinfo?(htsai)
Priority: P2 → --

The performance component is for issues that are actually affecting the performance. In this case this has to do with how this is measured and timing jitters but this is not actually code maintained by the Performance Team, directing this back to the right component and needinfo'ing baku.

Component: Performance → DOM: Core & HTML
Flags: needinfo?(amarchesini)

Tjr, I don't understand why this assertion should be correct. Here we compare 2 values: responseStart and zeroTime.

In the crash I have, zeroTime is generated when the docShell starts the loading of the document. ResponseStart is generated by necko, when we receive the response and this happens before zeroTime. So, the assertion seems invalid for the top-level document.

Flags: needinfo?(amarchesini) → needinfo?(tom)

When can that happen, when would navigationStart be earlier than responseStart.
Though, if we reduce the precision of zerotime but responseStart, couldn't this happen in such case?

(and yes, performance team is supposed to take take of performance API, and Performance component has been used for that :) )

Component: DOM: Core & HTML → Performance

Talking with smaug, it seems that this could be a DocumentChannel regression. Matt, do you mind to take a look?

Flags: needinfo?(matt.woodrow)
Whiteboard: [qf-]

Clearing ni, since I think this is on Matt's queue...

Flags: needinfo?(tom)

Matt, do you have any ETA on that bug?

This is not something I've been looking at sorry.

This bug is 2 years old, way before DocumentChannel existed, so I don't think it's a regression from that.

I have an idea about the let-localhost-be-localhost specific issue though, will comment there.

Flags: needinfo?(matt.woodrow)

(In reply to Matt Woodrow (:mattwoodrow) from comment #30)

This is not something I've been looking at sorry.

This bug is 2 years old, way before DocumentChannel existed, so I don't think it's a regression from that.

I have an idea about the let-localhost-be-localhost specific issue though, will comment there.

Matt, any chance you remember your idea? :) thanks!

The leave-open keyword is there and there is no activity for 6 months.
:kmoir, maybe it's time to close this bug?

Flags: needinfo?(kmoir)

deferring to mattwoodrow

Flags: needinfo?(kmoir) → needinfo?(matt.woodrow)

It doesn't look like anything got fixed here, so I assume it still reproduces and should stay open.

Flags: needinfo?(matt.woodrow)

The leave-open keyword is there and there is no activity for 6 months.
:plawless, maybe it's time to close this bug?

Flags: needinfo?(plawless)

I'm not sure exactly who to ask about this.

Tom, I am still able to reproduce this issue in CI. I see you started on a diagnostic patch, I can try to get a Pernosco session if you'd find that helpful, just ni? me.

Flags: needinfo?(tom)

This seems to be trigger by quite a few tests.

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

In this pernosco session, aPerformance->CreationTimeStamp() is 8757741470549 and mresponsestart is 8741669588843 leading to a negative duration of -16071881706 here (one frame up, two frames up, three frames up).

Creation Timestamp comes from GetDOMTiming()->GetNavigationStartTimeStamp() which is set in nsDOMNavigationTiming::NotifyNavigationStart. This happens in this process, I saw it in pernosco.

mResponseStart is set - I think - here in nsHttpTransaction. It seems (and man I wish Searchfox has process coverage information) that this value comes from another process.

Timestamps across processes are not reliably comparable.

This Telemetry accumlator is the only place we ever subtract a zero time. We add it in a lot of places but we never subtract it. This would explain why this is the only place this warning fires and why we (maybe?) aren't making any bad values appear in the performance timing APIs.

What to do about this is something I haven't yet thought about, but figuring out who cares about this telemetry value might be a good place to start.

Flags: needinfo?(tom)

baku, is this something you could have a look at?

Flags: needinfo?(amarchesini)

I don't think this is baku's realm, I'll try to find an owner who cares about TIME_TO_RESPONSE_START_MS...

Flags: needinfo?(amarchesini)

I am interested in that negative duration mentioned in comment 39 because I believe I've seen something similar before. So NI myself on that.

Flags: needinfo?(sefeng)

This issue is currently triggered in CI when the 'float-cast-overflow' UBSan check is enabled. This issue will need to be addressed before the check can be enabled by default.

If it requires too much effort to fix immediately please ni? me and let me know. If necessary it will be added to a suppression list. Thank you :)

Performance Impact: --- → -
Whiteboard: [qf-]

If you could suppress this for now that would be great. We've started a long email thread about the implications of this issue; and while a fix isn't directly hinging on that thread I'm not sure what the fix will be right now.

Flags: needinfo?(twsmith)
See Also: → 1758039
No longer blocks: let-localhost-be-localhost
Severity: normal → --

The leave-open keyword is there and there is no activity for 6 months.
:fdoty, maybe it's time to close this bug?
For more information, please visit auto_nag documentation.

Flags: needinfo?(fdoty)

Checking in to see if this is still an issue? Seems as if 7mo ago it was asked to be suppressed, but with the potential of a fix in the works.

Flags: needinfo?(sefeng)
Flags: needinfo?(plawless)
Flags: needinfo?(fdoty)
You need to log in before you can comment on or make changes to this bug.