Open Bug 1571186 Opened 5 years ago Updated 5 days ago

Intermittent ExpirationTracker.main | Expected: (timeDiffMS) < (periodMS), actual: 2434 vs 100 @ /builds/worker/workspace/build/src/xpcom/tests/gtest/TestExpirationTracker.cpp:135

Categories

(Core :: XPCOM, defect, P5)

Product:
Core
Component:
XPCOM
Type:
defect

Tracking

()

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, leave-open, regression, Whiteboard: [disabled on OSX debug][stockwell unknown])

Attachments

(2 files)

Bug 1571186 - Disable TestExpirationTracker on debug OSX for frequent failures.
48 bytes, text/x-phabricator-request
Details | Review
Bug 1571186 - Disable ExpirationTracker gtest on all OSX
48 bytes, text/x-phabricator-request
Details | Review

Filed by: ncsoregi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=259746335&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/X00CDAFYQwi8I8S9gG4fHA/runs/0/artifacts/public/logs/live_backing.log

[task 2019-08-03T05:20:58.353Z] 05:20:58 INFO - [1666, Main Thread] WARNING: Expired objects were not removed or marked used: file /builds/worker/workspace/build/src/obj-firefox/dist/include/nsExpirationTracker.h, line 257
[task 2019-08-03T05:21:00.368Z] 05:21:00 INFO - [1666, Main Thread] WARNING: Expired objects were not removed or marked used: file /builds/worker/workspace/build/src/obj-firefox/dist/include/nsExpirationTracker.h, line 257
[task 2019-08-03T05:21:00.887Z] 05:21:00 INFO - [1666, Main Thread] WARNING: Expired objects were not removed or marked used: file /builds/worker/workspace/build/src/obj-firefox/dist/include/nsExpirationTracker.h, line 257
[task 2019-08-03T05:21:01.959Z] 05:21:01 INFO - [1666, Main Thread] WARNING: Expired objects were not removed or marked used: file /builds/worker/workspace/build/src/obj-firefox/dist/include/nsExpirationTracker.h, line 257
[task 2019-08-03T05:21:02.220Z] 05:21:02 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Expected: (timeDiffMS) < (periodMS), actual: 2434 vs 100 @ /builds/worker/workspace/build/src/xpcom/tests/gtest/TestExpirationTracker.cpp:135
[task 2019-08-03T05:21:02.221Z] 05:21:02 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Value of: aObj->mExpired
[task 2019-08-03T05:21:02.221Z] 05:21:02 INFO - Actual: false
[task 2019-08-03T05:21:02.221Z] 05:21:02 INFO - Expected: true @ /builds/worker/workspace/build/src/xpcom/tests/gtest/TestExpirationTracker.cpp:136
[task 2019-08-03T05:21:02.221Z] 05:21:02 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Expected: (timeDiffMS) < (periodMS), actual: 2435 vs 100 @ /builds/worker/workspace/build/src/xpcom/tests/gtest/TestExpirationTracker.cpp:135
[task 2019-08-03T05:21:02.221Z] 05:21:02 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Value of: aObj->mExpired
[task 2019-08-03T05:21:02.221Z] 05:21:02 INFO - Actual: false
[task 2019-08-03T05:21:02.221Z] 05:21:02 INFO - Expected: true @ /builds/worker/workspace/build/src/xpcom/tests/gtest/TestExpirationTracker.cpp:136
[task 2019-08-03T05:21:02.221Z] 05:21:02 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Expected: (timeDiffMS) < (periodMS), actual: 2435 vs 100 @ /builds/worker/workspace/build/src/xpcom/tests/gtest/TestExpirationTracker.cpp:135
[task 2019-08-03T05:21:02.221Z] 05:21:02 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Value of: aObj->mExpired
[task 2019-08-03T05:21:02.221Z] 05:21:02 INFO - Actual: false
[task 2019-08-03T05:21:02.221Z] 05:21:02 INFO - Expected: true @ /builds/worker/workspace/build/src/xpcom/tests/gtest/TestExpirationTracker.cpp:136
[task 2019-08-03T05:21:02.222Z] 05:21:02 INFO - [1666, Main Thread] WARNING: Expired objects were not removed or marked used: file /builds/worker/workspace/build/src/obj-firefox/dist/include/nsExpirationTracker.h, line 257
[task 2019-08-03T05:21:02.536Z] 05:21:02 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Expected: (timeDiffMS) < (periodMS), actual: 2519 vs 100 @ /builds/worker/workspace/build/src/xpcom/tests/gtest/TestExpirationTracker.cpp:135
[task 2019-08-03T05:21:02.536Z] 05:21:02 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Value of: aObj->mExpired
[task 2019-08-03T05:21:02.536Z] 05:21:02 INFO - Actual: false
[task 2019-08-03T05:21:02.536Z] 05:21:02 INFO - Expected: true @ /builds/worker/workspace/build/src/xpcom/tests/gtest/TestExpirationTracker.cpp:136

It looks like the failure rate really increased on the 22nd, and that failures are most common on OSX debug. Maybe some backfilling could narrow down a regression range.

I can take a look.

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

Ok, great, it looks like somebody has done a bunch of retriggers. I'll try skimming through the log for anything that looks timing related.

Flags: needinfo?(continuation)

I fiddled with this ages ago in bug 1544452 because its timing is flaky on our mac 10.14 machines (used to be a permafail) and even after increasing the time difference threshold by over 10 times it continues to retrigger occasionally. We never found anything explicitly wrong with our mac timers and it seemed the test just ran too slow on try hardware. It fell off my radar since the number of intermittents had become insignificant but the only way I could think to permanently fix it was to rework the test to accommodate for unreliable timing.

See Also: → 1544452

Should this test get disabled on OSX debug? Looking at TreeHerder for the 22nd, it looks like it started failing more frequently but nothing looks obviously related to expiration tracking in a gtest.

Flags: needinfo?(kwright)

(In reply to Andrew McCreight [:mccr8] from comment #84)

Should this test get disabled on OSX debug? Looking at TreeHerder for the 22nd, it looks like it started failing more frequently but nothing looks obviously related to expiration tracking in a gtest.

I'm all for disabling this. We still test it on other platforms and this doesn't seem to be a real issue that causes trouble in production (it's not even locally reproducible unless you throttle your task scheduling beyond recognition) so I don't think there's a big risk to disabling it.

Flags: needinfo?(kwright)

Apparently this test has a history of failures, and it recently
started failing frequently for no apparent reason.

Assignee: nobody → continuation
Status: NEW → ASSIGNED
Pushed by amccreight@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ad5ff7969604
Disable TestExpirationTracker on debug OSX for frequent failures. r=KrisWright
Keywords: leave-open
Whiteboard: [disabled on OSX debug]

This bug failed 34 times in the last 7 days. Occurs on macosx1014-64-qr, macosx1014-64-shippable-qr on opt build type.

Recent log:
https://treeherder.mozilla.org/logviewer?job_id=332201992&repo=autoland

Nika: Can you please take a look at this bug?

Flags: needinfo?(nika)

Maybe this should just be disabled entirely on OSX?

Flags: needinfo?(nika) → needinfo?(kwright)
Assignee: continuation → nobody
Status: ASSIGNED → NEW

There are 34 total failures in the last 7 days on

  • macosx1014-64-qr opt
  • macosx1014-64-shippable-qr opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=332201992&repo=autoland&lineNumber=2707

[task 2021-03-05T16:43:43.398Z] 16:43:43 INFO - TEST-START | ExpirationTracker.main
[task 2021-03-05T16:44:27.458Z] 16:44:27 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Expected: (timeDiffMS) < (periodMS), actual: 2494 vs 100 @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:133
[task 2021-03-05T16:44:27.459Z] 16:44:27 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Value of: aObj->mExpired
[task 2021-03-05T16:44:27.459Z] 16:44:27 INFO - Actual: false
[task 2021-03-05T16:44:27.459Z] 16:44:27 INFO - Expected: true @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:134
[task 2021-03-05T16:44:27.460Z] 16:44:27 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Expected: (timeDiffMS) < (periodMS), actual: 2494 vs 100 @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:133
[task 2021-03-05T16:44:27.460Z] 16:44:27 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Value of: aObj->mExpired
[task 2021-03-05T16:44:27.460Z] 16:44:27 INFO - Actual: false
[task 2021-03-05T16:44:27.460Z] 16:44:27 INFO - Expected: true @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:134
[task 2021-03-05T16:44:27.461Z] 16:44:27 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Expected: (timeDiffMS) < (periodMS), actual: 2494 vs 100 @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:133
[task 2021-03-05T16:44:27.461Z] 16:44:27 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Value of: aObj->mExpired
[task 2021-03-05T16:44:27.461Z] 16:44:27 INFO - Actual: false
[task 2021-03-05T16:44:27.462Z] 16:44:27 INFO - Expected: true @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:134
[task 2021-03-05T16:44:27.462Z] 16:44:27 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Expected: (timeDiffMS) < (periodMS), actual: 2494 vs 100 @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:133
[task 2021-03-05T16:44:27.462Z] 16:44:27 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Value of: aObj->mExpired
[task 2021-03-05T16:44:27.462Z] 16:44:27 INFO - Actual: false
[task 2021-03-05T16:44:27.463Z] 16:44:27 INFO - Expected: true @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:134
[task 2021-03-05T16:44:27.846Z] 16:44:27 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Expected: (timeDiffMS) < (periodMS), actual: 2549 vs 100 @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:133
[task 2021-03-05T16:44:27.846Z] 16:44:27 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Value of: aObj->mExpired
[task 2021-03-05T16:44:27.847Z] 16:44:27 INFO - Actual: false
[task 2021-03-05T16:44:27.847Z] 16:44:27 INFO - Expected: true @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:134
[task 2021-03-05T16:44:27.847Z] 16:44:27 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Expected: (timeDiffMS) < (periodMS), actual: 2549 vs 100 @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:133
[task 2021-03-05T16:44:27.847Z] 16:44:27 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Value of: aObj->mExpired
[task 2021-03-05T16:44:27.848Z] 16:44:27 INFO - Actual: false
[task 2021-03-05T16:44:27.848Z] 16:44:27 INFO - Expected: true @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:134
[task 2021-03-05T16:44:28.129Z] 16:44:28 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Expected: (timeDiffMS) < (periodMS), actual: 2480 vs 100 @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:133
[task 2021-03-05T16:44:28.130Z] 16:44:28 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Value of: aObj->mExpired
[task 2021-03-05T16:44:28.130Z] 16:44:28 INFO - Actual: false
[task 2021-03-05T16:44:28.130Z] 16:44:28 INFO - Expected: true @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:134
[task 2021-03-05T16:44:28.654Z] 16:44:28 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Expected: (timeDiffMS) < (periodMS), actual: 2529 vs 100 @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:133
[task 2021-03-05T16:44:28.654Z] 16:44:28 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Value of: aObj->mExpired
[task 2021-03-05T16:44:28.654Z] 16:44:28 INFO - Actual: false
[task 2021-03-05T16:44:28.655Z] 16:44:28 INFO - Expected: true @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:134
[task 2021-03-05T16:44:28.655Z] 16:44:28 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Expected: (timeDiffMS) < (periodMS), actual: 2529 vs 100 @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:133
[task 2021-03-05T16:44:28.655Z] 16:44:28 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Value of: aObj->mExpired
[task 2021-03-05T16:44:28.656Z] 16:44:28 INFO - Actual: false
[task 2021-03-05T16:44:28.656Z] 16:44:28 INFO - Expected: true @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:134
[task 2021-03-05T16:44:29.484Z] 16:44:29 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Expected: (timeDiffMS) < (periodMS), actual: 2404 vs 100 @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:133
[task 2021-03-05T16:44:29.888Z] 16:44:29 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | Expected: (timeDiffMS) < (periodMS), actual: 2430 vs 100 @ /builds/worker/checkouts/gecko/xpcom/tests/gtest/TestExpirationTracker.cpp:133
[task 2021-03-05T16:44:31.433Z] 16:44:31 WARNING - TEST-UNEXPECTED-FAIL | ExpirationTracker.main | test completed (time: 48151ms)

Whiteboard: [disabled on OSX debug] → [disabled on OSX debug][stockwell needswork:owner]

(In reply to Andrew McCreight [:mccr8] from comment #95)

Maybe this should just be disabled entirely on OSX?

We are still testing on other platforms and I won't be getting around to reworking this test in the near future so I think we should go ahead and do this for the time being. I'll file a followup about properly fixing it on mac.

Flags: needinfo?(kwright)

We already had this disabled on debug but it still produces intermittents with no clear reason on opt. We still test this on other platforms so I want to go ahead and disable this outright until we can fix this properly. Followup filed in bug 1696959.

See Also: → 1696959
Pushed by kwright@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/1f462666dedf
Disable ExpirationTracker gtest on all OSX r=xpcom-reviewers,mccr8
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: