Closed Bug 1744404 Opened 3 years ago Closed 9 days ago

Intermittent SimpleTimerTest.FindExpirationTime | Expected equality of these values:

Categories

(Core :: XPCOM, defect, P5)

Product:
Core
Component:
XPCOM
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown])

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

[task 2021-12-04T10:45:00.301Z] 10:45:00     INFO -  TEST-START | SimpleTimerTest.FindExpirationTime
[task 2021-12-04T10:45:00.323Z] 10:45:00  WARNING -  TEST-UNEXPECTED-FAIL | SimpleTimerTest.FindExpirationTime | Expected equality of these values:
[task 2021-12-04T10:45:00.323Z] 10:45:00     INFO -    t
[task 2021-12-04T10:45:00.324Z] 10:45:00     INFO -      Which is: 8-byte object <EE-60 BE-67 C0-00 00-00>
[task 2021-12-04T10:45:00.324Z] 10:45:00     INFO -    middle
[task 2021-12-04T10:45:00.324Z] 10:45:00     INFO -      Which is: 8-byte object <A4-2C 6D-5F CE-00 00-00>
[task 2021-12-04T10:45:00.324Z] 10:45:00     INFO -  Found time should be equal to default @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestTimers.cpp:516
[task 2021-12-04T10:45:00.324Z] 10:45:00  WARNING -  TEST-UNEXPECTED-FAIL | SimpleTimerTest.FindExpirationTime | Expected equality of these values:
[task 2021-12-04T10:45:00.324Z] 10:45:00     INFO -    t
[task 2021-12-04T10:45:00.324Z] 10:45:00     INFO -      Which is: 8-byte object <EE-60 BE-67 C0-00 00-00>
[task 2021-12-04T10:45:00.325Z] 10:45:00     INFO -    middle
[task 2021-12-04T10:45:00.325Z] 10:45:00     INFO -      Which is: 8-byte object <A4-2C 6D-5F CE-00 00-00>
[task 2021-12-04T10:45:00.325Z] 10:45:00     INFO -  Found time should be equal to default @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestTimers.cpp:520
[task 2021-12-04T10:45:00.325Z] 10:45:00  WARNING -  TEST-UNEXPECTED-FAIL | SimpleTimerTest.FindExpirationTime | test completed (time: 23ms)

Update:
There have been 39 failures within the last 7 days:

  • 9 failures on OS X 10.15 WebRender debug/opt
  • 1 failure on OS X 10.15 WebRender Shippable opt
  • 15 failures on Windows 10 x86 2004 WebRender opt
  • 2 failures on Windows 10 x64 2004 asan WebRender opt
  • 10 failures on Windows 10 x64 2004 WebRender opt
  • 2 failures on Windows 10 x64 2004 WebRender Shippable opt

Recent failures: https://treeherder.mozilla.org/logviewer?job_id=396302333&repo=autoland&lineNumber=7522

[task 2022-11-11T15:11:22.298Z] 15:11:22     INFO -  TEST-START | SimpleTimerTest.FindExpirationTime
[task 2022-11-11T15:11:22.728Z] 15:11:22  WARNING -  TEST-UNEXPECTED-FAIL | SimpleTimerTest.FindExpirationTime | Expected equality of these values:
[task 2022-11-11T15:11:22.728Z] 15:11:22     INFO -    t
[task 2022-11-11T15:11:22.728Z] 15:11:22     INFO -      Which is: 8-byte object <4A-16 22-78 5A-00 00-00>
[task 2022-11-11T15:11:22.729Z] 15:11:22     INFO -    middle
[task 2022-11-11T15:11:22.729Z] 15:11:22     INFO -      Which is: 8-byte object <C6-80 26-A2 5B-00 00-00>
[task 2022-11-11T15:11:22.729Z] 15:11:22     INFO -  Found time should be equal to default @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestTimers.cpp:517
[task 2022-11-11T15:11:22.730Z] 15:11:22  WARNING -  TEST-UNEXPECTED-FAIL | SimpleTimerTest.FindExpirationTime | test completed (time: 430ms)

Nika, can you help us assign this to someone?
Thank you.

Flags: needinfo?(nika)
Whiteboard: [stockwell needswork:owner]

Olli, it looks like you originally added this test. Do you know what might be going wrong here? I'm wondering a bit if this could have been impacted by bug 1767396 in some way.

Flags: needinfo?(nika) → needinfo?(smaug)

FWIW I am able to reproduce this (intermittently but reliably) with "./mach gtest SimpleTimerTest.*"

The test is adding some timers and then performing some queries on what timers are in the queue but, from what I can tell, something else (on another thread) is occasionally adding timers as well which can mess up the tests. I am looking into this a bit more to see if this can be fixed easily.

Having dug into this a bit more, it seems that the BackgroundHangThread is what is adding the additional timers. I can't immediately see why there is a BHT involved/in existence for these tests or if this was intended/expected. I'm thinking that, when this test was originally written in 2017 (https://hg.mozilla.org/mozilla-central/rev/f85000b56528fbb1e6688795d763550cce9ced06), there were no other threads adding timers to
but that something changed between then and late 2021 (when https://hg.mozilla.org/mozilla-central/rev/20b482455364fc14118bd32de96ae52cc81c7f3a was made) such that other threads were now active during the test.

From my perspective I don't see any reason for other threads to be around/active during this test and, in fact, other threads that are interacting with the TimerThread used by the test really invalidates what the test is checking.

Olli: Does my summary above match with your recollection? Did you have any expectation that other threads would be interacting with the timer thread when you wrote those tests? Do you have any idea why a BackgroundHangThread would be created for these tests?

Oh, and I should also add that I tried putting in a local hack to make TimerThread::AddTimer ignore any timer coming from the BackgroundHangThread and that did make the intermittent failures completely go away.

Oh, did this become more common because of https://bugzilla.mozilla.org/show_bug.cgi?id=965392 ?
I wonder if there was something else happening late 2021, but bug 965392 added even more timers?
Do you see other timers if you disable the stuff bug 965392 added?
I guess disable somewhere around here https://searchfox.org/mozilla-central/rev/43ee5e789b079e94837a21336e9ce2420658fd19/toolkit/components/backgroundhangmonitor/BackgroundHangMonitor.cpp#591,594

(and now I wonder if bug 965392 broke also idle handling. Does it end up running timers on the main thread...)

Flags: needinfo?(smaug)

Thanks for the feedback Olli and for directing me to that bug. I will check into that and see if that could be the cause.

I will try backing out the changes in https://bugzilla.mozilla.org/show_bug.cgi?id=965392 and see if that can be implicated in the behavior.

What do you mean about broken idle handling and running timers on the main thread?

Idle task handling on the main thread relies on things like whether there is refreshdriver running or whether there are pending soon-running timers in the timer thread targeted to the main thread. The latter one skips *_LOW_PRIORITY timers, but bug 965392 uses nsITimer::TYPE_ONE_SHOT, not TYPE_ONE_SHOT_LOW_PRIORITY.
See https://searchfox.org/mozilla-central/rev/43ee5e789b079e94837a21336e9ce2420658fd19/xpcom/threads/MainThreadIdlePeriod.cpp#46 and it calls https://searchfox.org/mozilla-central/rev/43ee5e789b079e94837a21336e9ce2420658fd19/xpcom/threads/TimerThread.cpp#724,750
So, I wonder if bug 965392 added timers which disturb normal idle detection. Nothing about this bug though.

In what will come as a surprise to no one, disabling the BackgroundHangMonitor (around https://searchfox.org/mozilla-central/rev/43ee5e789b079e94837a21336e9ce2420658fd19/toolkit/components/backgroundhangmonitor/BackgroundHangMonitor.cpp#591,594 as suggested above) also causes the failures to cease.

After locally backing out https://bugzilla.mozilla.org/show_bug.cgi?id=965392 I have been unable to reproduce the failure after many attempts so it seems like these failures did indeed start with that change.

I have read and re-read the comments on https://bugzilla.mozilla.org/show_bug.cgi?id=965392 so I think I have a decent high-level understanding of what that change is accomplishing but I haven't fully dug into the code yet.

Since @florian authored that change and @dthayer reviewed it I'll pull them into this conversation for their thoughts too.

tl;dr summary: The intermittent unit test failures of this ticket are due to the BackgroundHangTimer thread adding timers during the test (which consists of adding timers and then examining the pending timers list). This seems to have started with https://bugzilla.mozilla.org/show_bug.cgi?id=965392 where the background hang thread was made to use the timer thread. Olli has further raised the concern that the addition of these timers might be in a way that disturbs idle detection.

I'll add my two-cents here.

Part of me says that the BackgroundHangMonitor shouldn't be enabled for unit tests that aren't testing the BackgroundHangMonitor. On the other hand, having it automatically disabled for unit tests might make it easier for tests to be written for functionality that is subtly incompatible with it.

So maybe these tests should explicitly disable it (can that be done?) since they are specifically looking at the details of some behavior of the timer thread and need to operate in a controlled environment?

Flags: needinfo?(florian)
Flags: needinfo?(dothayer)

My vote is to kill BHR for unit tests. I think it's unlikely that it will actually provide value by flagging incompatibilities in other components, but that it's very likely that it will waste more time by causing more spurious intermittent failures.

Flags: needinfo?(dothayer)

+1 to what Doug said. I don't think BHR adds any value to unit tests. (I'm talking about gtests only here, for the other test suites like mochitests it's better to have something that matches what Firefox does.)

Flags: needinfo?(florian)

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=418244910&repo=autoland

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: REOPENED → RESOLVED
Closed: 2 years ago → 11 months ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=460776063&repo=autoland

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: REOPENED → RESOLVED
Closed: 11 months ago → 4 months ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=483354004&repo=autoland

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: REOPENED → RESOLVED
Closed: 4 months ago → 1 month ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=491009400&repo=autoland

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: REOPENED → RESOLVED
Closed: 1 month ago → 9 days ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.