Closed Bug 1333312 Opened 3 years ago Closed 3 years ago

Intermittent toolkit/components/aboutperformance/tests/browser/browser_aboutperformance.js | aboutperformance-test:checkSanity error: {"message":"Item li.cpu doesn't match regexp /CPU usage: (\\d+)%/: CPU usage: NaN% (total 0ms).","lineNumber":78,"fileNam

Categories

(Toolkit :: Performance Monitoring, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla54
Tracking Status
firefox52 --- unaffected
firefox53 --- fixed
firefox54 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: Felipe)

Details

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

Attachments

(1 file)

Predominantly happens on linux64/asan.

[task 2017-01-26T01:00:36.927271Z] 01:00:36     INFO - TEST-PASS | toolkit/components/aboutperformance/tests/browser/browser_aboutperformance.js | The title appears in webpages, but not in addons - true == true - 
[task 2017-01-26T01:00:36.934002Z] 01:00:36     INFO - Buffered messages finished
[task 2017-01-26T01:00:36.937977Z] 01:00:36     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/aboutperformance/tests/browser/browser_aboutperformance.js | aboutperformance-test:checkSanity error: {"message":"Item li.cpu doesn't match regexp /CPU usage: (\\d+)%/: CPU usage: NaN% (total 0ms).","lineNumber":78,"fileName":"chrome://mochikit/content/tests/BrowserTestUtils/content-task.js line 52 > eval"} - false == true - JS frame :: chrome://mochitests/content/browser/toolkit/components/aboutperformance/tests/browser/browser_aboutperformance.js :: promiseExpectContent< :: line 229
[task 2017-01-26T01:00:36.940242Z] 01:00:36     INFO - Stack trace:
[task 2017-01-26T01:00:36.942416Z] 01:00:36     INFO -     chrome://mochitests/content/browser/toolkit/components/aboutperformance/tests/browser/browser_aboutperformance.js:promiseExpectContent<:229
[task 2017-01-26T01:00:36.944777Z] 01:00:36     INFO -     test_find_title@chrome://mochitests/content/browser/toolkit/components/aboutperformance/tests/browser/browser_aboutperformance.js:240:25
[task 2017-01-26T01:00:36.946823Z] 01:00:36     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-01-26T01:00:36.949151Z] 01:00:36     INFO -     process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:917:23
[task 2017-01-26T01:00:36.952631Z] 01:00:36     INFO -     walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:801:7
[task 2017-01-26T01:00:36.954923Z] 01:00:36     INFO -     Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:734:11
[task 2017-01-26T01:00:36.958039Z] 01:00:36     INFO -     schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:765:7
[task 2017-01-26T01:00:36.960202Z] 01:00:36     INFO -     completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:702:7
[task 2017-01-26T01:00:36.962855Z] 01:00:36     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:324:15
[task 2017-01-26T01:00:36.965239Z] 01:00:36     INFO -     promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-01-26T01:00:36.971108Z] 01:00:36     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-01-26T01:00:36.973326Z] 01:00:36     INFO -     promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-01-26T01:00:36.977047Z] 01:00:36     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-01-26T01:00:36.979448Z] 01:00:36     INFO -     promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-01-26T01:00:36.981597Z] 01:00:36     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-01-26T01:00:36.983896Z] 01:00:36     INFO -     promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-01-26T01:00:36.986085Z] 01:00:36     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-01-26T01:00:36.988386Z] 01:00:36     INFO -     promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-01-26T01:00:36.991832Z] 01:00:36     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-01-26T01:00:36.993998Z] 01:00:36     INFO -     promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-01-26T01:00:36.996328Z] 01:00:36     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-01-26T01:00:36.999896Z] 01:00:36     INFO -     promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-01-26T01:00:37.001882Z] 01:00:37     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-01-26T01:00:37.004647Z] 01:00:37     INFO -     TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-01-26T01:00:37.010747Z] 01:00:37     INFO -     asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-01-26T01:00:37.013075Z] 01:00:37     INFO -     test_find_title@chrome://mochitests/content/browser/toolkit/components/aboutperformance/tests/browser/browser_aboutperformance.js:240:25
[task 2017-01-26T01:00:37.015254Z] 01:00:37     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-01-26T01:00:37.017589Z] 01:00:37     INFO -     TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-01-26T01:00:37.019797Z] 01:00:37     INFO -     asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-01-26T01:00:37.021840Z] 01:00:37     INFO -     Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-01-26T01:00:37.023826Z] 01:00:37     INFO -     TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
[task 2017-01-26T01:00:37.025851Z] 01:00:37     INFO -     TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-01-26T01:00:37.028240Z] 01:00:37     INFO -     process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:917:23
[task 2017-01-26T01:00:37.030683Z] 01:00:37     INFO -     walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:801:7
[task 2017-01-26T01:00:37.033152Z] 01:00:37     INFO -     Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:734:11
[task 2017-01-26T01:00:37.036369Z] 01:00:37     INFO -     schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:765:7
[task 2017-01-26T01:00:37.038747Z] 01:00:37     INFO -     completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:702:7
[task 2017-01-26T01:00:37.042037Z] 01:00:37     INFO -     receiveMessage@resource://testing-common/ContentTask.jsm:113:9
[task 2017-01-26T01:00:37.046447Z] 01:00:37     INFO - TEST-PASS | toolkit/components/aboutperformance/tests/browser/browser_aboutperformance.js | The page title appears when about:performance is set to auto-refresh - true == true -
The test was updated recently in bug 1328254. Mark, might this be related to your change?
Flags: needinfo?(standard8)
(In reply to Geoff Brown [:gbrown] from comment #4)
> The test was updated recently in bug 1328254. Mark, might this be related to
> your change?

It probably is, since my change got that part of the test actually working.

It looks like the issue is here:

https://dxr.mozilla.org/mozilla-central/rev/1d025ac534a6333a8170a59a95a8a3673d4028ee/toolkit/components/aboutperformance/content/aboutPerformance.js#610

        cachedElements.eltCPU.textContent = `CPU usage: ${Math.ceil(delta.diff.jank.totalCPUTime / delta.diff.deltaT / 10)}%.`;

I'm guessing the `delta.diff.deltaT` is 0, hence causing the NaN.

Unfortunately I don't know enough about the background code to know where delta.diff might be being defined, or why it might be 0. I think Felipe reviewed some of this code, so lets try asking him.
Flags: needinfo?(standard8) → needinfo?(felipc)
I'm gonna pass the question to Yoric
Flags: needinfo?(felipc) → needinfo?(dteller)
I'm currently at Fosdem, I'll try and look at it by Wednesday.
I was too optimistic. I'll try and take a look at it next week, but I'm not sure I'll be able to.
Since it's predominantly linux64/asan I suggest we just disable this test there and not spend too much time on it.
Assignee: nobody → felipc
Status: NEW → ASSIGNED
Flags: needinfo?(dteller)
Comment on attachment 8835648 [details]
Bug 1333312 - Skip browser_aboutperformance.js on linux64-asan.

https://reviewboard.mozilla.org/r/111320/#review112814

Yeah, lets do it.
Attachment #8835648 - Flags: review?(standard8) → review+
Pushed by felipc@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/20a02827856f
Skip browser_aboutperformance.js on linux64-asan. r=standard8
https://hg.mozilla.org/mozilla-central/rev/20a02827856f
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla54
Whiteboard: [stockwell disabled]
You need to log in before you can comment on or make changes to this bug.