1372719 - Intermittent TEST-UNEXPECTED-TIMEOUT | dom/media/test/test_background_video_no_suspend_disabled.html | application timed out after 330 seconds with no output

Status: RESOLVED INCOMPLETE

(Core :: XPCOM, defect)

Description

[Treeherder Bug Filer]

Filed by: wkocher [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=106798382&repo=autoland

https://queue.taskcluster.net/v1/task/cqYQ0SKFTzK-reYv-R-VRQ/runs/0/artifacts/public/logs/live_backing.log

Comment 1

[JW Wang [:jwwang] [:jw_wang]]

https://treeherder.mozilla.org/logviewer.html#?job_id=106798382&repo=autoland&lineNumber=1972

20:22:30     INFO -  GECKO(3956) | firstTimeStamp 8.000000, mTimers[0]->Timeout() 1.000000, initialFirstTimer 07DD1040, current first 0AA07F80
20:22:30     INFO -  GECKO(3956) | Assertion failure: firstTimeStamp == mTimers[0]->Timeout(), at z:/build/build/src/xpcom/threads/TimerThread.cpp:659
20:22:42     INFO -  GECKO(3956) | #01: NS_GetTimerDeadlineHintOnCurrentThread(mozilla::TimeStamp,unsigned int) [xpcom/threads/nsTimerImpl.cpp:50]
20:22:42     INFO -  GECKO(3956) | #02: mozilla::MainThreadIdlePeriod::GetIdlePeriodHint(mozilla::TimeStamp *) [xpcom/threads/MainThreadIdlePeriod.cpp:33]
20:22:42     INFO -  GECKO(3956) | #03: nsThread::GetIdleDeadline() [xpcom/threads/nsThread.cpp:1062]
20:22:42     INFO -  GECKO(3956) | #04: nsThread::HasPendingEvents(bool *) [xpcom/threads/nsThread.cpp:1106]
20:22:42     INFO -  GECKO(3956) | #05: hasPendingEvents(nsIThread *) [xpcom/threads/nsThreadUtils.cpp:430]
20:22:42     INFO -  GECKO(3956) | #06: NS_HasPendingEvents(nsIThread *) [xpcom/threads/nsThreadUtils.cpp:448]
20:22:42     INFO -  GECKO(3956) | #07: nsBaseAppShell::OnProcessNextEvent(nsIThreadInternal *,bool) [widget/nsBaseAppShell.cpp:281]
20:22:42     INFO -  GECKO(3956) | #08: nsThread::ProcessNextEvent(bool,bool *) [xpcom/threads/nsThread.cpp:1357]
20:22:42     INFO -  GECKO(3956) | #09: NS_ProcessNextEvent(nsIThread *,bool) [xpcom/threads/nsThreadUtils.cpp:472]

A timer thread bug?

Comment 2

[Ben Kelly [:bkelly, not reviewing]]

Olli, the debugging information here seems pretty concerning.  It seems to indicate the first timeout is really wrong.

Perhaps instead of the loop doing std::push_heap() we should just do a single call to std::make_heap() on the entire list.

Comment 3

[Olli Pettay [:smaug][[e-mail]]]

I wonder how much slower make_heap is. maybe not at all.

Comment 4

[Ben Kelly [:bkelly, not reviewing]]

(In reply to Olli Pettay [:smaug] from comment #3)
> I wonder how much slower make_heap is. maybe not at all.

This:

http://en.cppreference.com/w/cpp/algorithm/make_heap

Says the complexity is:

"At most 3*std::distance(first, last) comparisons. "

While std::push_heap complexity is:

"At most log(N) comparisons where N=std::distance(first, last)"

So it would be a bit slower.

Looking at the debug, though, this suggests that the original first timestamp is wrong.  It says 8 milliseconds from "now", while the resulting timestamp is 1 millisecond from now.  The final result seems more correct to me.

Maybe we should instead be adding some kind of validation in other places to verify the heap is not corrupt.

Comment 5

[Ben Kelly [:bkelly, not reviewing]]

Windows VM again, though.  This could still be a problem with TimeStamp on that platform.

Comment 6

[Ben Kelly [:bkelly, not reviewing]]

Honza, is there any instrumentation on windows we could add to see if TimeStamp is switching between different modes or otherwise going backwards, etc?

Comment 7

[Honza Bambas (:mayhemer)]

(In reply to Ben Kelly [reviewing, but slowly][:bkelly] from comment #6)
> Honza, is there any instrumentation on windows we could add to see if
> TimeStamp is switching between different modes or otherwise going backwards,
> etc?

"is there any instrumentation on windows we could add" - what exactly do you mean?

Comment 8

[Ben Kelly [:bkelly, not reviewing]]

(In reply to Honza Bambas (:mayhemer) from comment #7)
> "is there any instrumentation on windows we could add" - what exactly do you
> mean?

The internal of the windows TimeStamp is a bit opaque to me.  Is there a way to printf_stderr() if its switched from using cpu counters to the tick approach?  Is that recorded somewhere?

Comment 9

[Honza Bambas (:mayhemer)]

Ah!  Now it's clear what you mean.  You need to impl logging at https://dxr.mozilla.org/mozilla-central/source/mozglue/misc/TimeStamp_windows.cpp#17

You can use mozlog usually as in other code or printf.  There are plenty of LOG()s around the win timestamp code already placed, including the "switch to GTC" signal.

Comment 10

[Ben Kelly [:bkelly, not reviewing]]

Maybe we should try to printing the value of sUseQPC on windows here:

https://dxr.mozilla.org/mozilla-central/source/mozglue/misc/TimeStamp_windows.cpp#129

If it only fails when sUseQPC is false, then maybe we could disable this assertion in that case.

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 1

Platform breakdown:
* windows7-32-vm: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1372719&startday=2017-06-12&endday=2017-06-18&tree=all