Closed Bug 1819845 Opened 2 years ago Closed 2 months ago

Intermittent toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | single tracking bug

Categories

(Toolkit :: Performance Monitoring, defect, P5)

defect

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, intermittent-testcase)

Attachments

(2 files, 1 obsolete file)

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


[task 2023-03-02T07:26:39.690Z] 07:26:39     INFO - TEST-START | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js
[task 2023-03-02T07:26:39.768Z] 07:26:39     INFO - GECKO(10088) | console.error: (new TypeError("can't access property \"get\", linkMap is undefined", "resource://gre/modules/NewTabUtils.sys.mjs", 2019))
[task 2023-03-02T07:26:40.365Z] 07:26:40     INFO - GECKO(10088) | JavaScript error: resource://gre/modules/XULStore.jsm, line 58: Error: Can't find profile directory.
[task 2023-03-02T07:26:40.757Z] 07:26:40     INFO - GECKO(10088) | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-03-02T07:26:40.804Z] 07:26:40     INFO - TEST-INFO | started process screenshot
[task 2023-03-02T07:26:40.918Z] 07:26:40     INFO - TEST-INFO | screenshot: exit 0
[task 2023-03-02T07:26:40.921Z] 07:26:40     INFO - Buffered messages logged at 07:26:39
[task 2023-03-02T07:26:40.921Z] 07:26:40     INFO - Entering test bound 
[task 2023-03-02T07:26:40.922Z] 07:26:40     INFO - Buffered messages logged at 07:26:40
[task 2023-03-02T07:26:40.923Z] 07:26:40     INFO - Console message: [JavaScript Error: "Error: Can't find profile directory." {file: "resource://gre/modules/XULStore.jsm" line: 58}]
[task 2023-03-02T07:26:40.923Z] 07:26:40     INFO - load@resource://gre/modules/XULStore.jsm:58:15
[task 2023-03-02T07:26:40.923Z] 07:26:40     INFO - XULStore@resource://gre/modules/XULStore.jsm:17:10
[task 2023-03-02T07:26:40.923Z] 07:26:40     INFO - 
[task 2023-03-02T07:26:40.923Z] 07:26:40     INFO - CPU time from ProcInfo before calling testFlushAllChildren:
[task 2023-03-02T07:26:40.924Z] 07:26:40     INFO -   pid: 3128, type = parent, cpu time = 3187.5ms
[task 2023-03-02T07:26:40.924Z] 07:26:40     INFO -   pid: 8964, type = web, cpu time = 78.125ms
[task 2023-03-02T07:26:40.925Z] 07:26:40     INFO -   pid: 4788, type = privilegedabout, cpu time = 250ms
[task 2023-03-02T07:26:40.925Z] 07:26:40     INFO -   pid: 1116, type = web, cpu time = 156.25ms
[task 2023-03-02T07:26:40.925Z] 07:26:40     INFO -   pid: 9724, type = extension, cpu time = 328.125ms
[task 2023-03-02T07:26:40.926Z] 07:26:40     INFO -   pid: 6556, type = utility, cpu time = 62.5ms
[task 2023-03-02T07:26:40.926Z] 07:26:40     INFO -   pid: 2836, type = preallocated, cpu time = 156.25ms
[task 2023-03-02T07:26:40.926Z] 07:26:40     INFO -   pid: 9048, type = gpu, cpu time = 1671.875ms
[task 2023-03-02T07:26:40.927Z] 07:26:40     INFO - CPU time for each label:
[task 2023-03-02T07:26:40.927Z] 07:26:40     INFO -   parent.active = 2282
[task 2023-03-02T07:26:40.928Z] 07:26:40     INFO -   parent.active.playing-audio = undefined
[task 2023-03-02T07:26:40.928Z] 07:26:40     INFO -   parent.active.playing-video = undefined
[task 2023-03-02T07:26:40.928Z] 07:26:40     INFO -   parent.inactive = 921
[task 2023-03-02T07:26:40.929Z] 07:26:40     INFO -   parent.inactive.playing-audio = undefined
[task 2023-03-02T07:26:40.930Z] 07:26:40     INFO -   parent.inactive.playing-video = undefined
[task 2023-03-02T07:26:40.930Z] 07:26:40     INFO -   prealloc = 327
[task 2023-03-02T07:26:40.930Z] 07:26:40     INFO -   privilegedabout = 250
[task 2023-03-02T07:26:40.931Z] 07:26:40     INFO -   rdd = undefined
[task 2023-03-02T07:26:40.931Z] 07:26:40     INFO -   socket = undefined
[task 2023-03-02T07:26:40.931Z] 07:26:40     INFO -   web.background = 63
[task 2023-03-02T07:26:40.932Z] 07:26:40     INFO -   web.background-perceivable = undefined
[task 2023-03-02T07:26:40.932Z] 07:26:40     INFO -   web.foreground = 249
[task 2023-03-02T07:26:40.932Z] 07:26:40     INFO -   extension = 328
[task 2023-03-02T07:26:40.933Z] 07:26:40     INFO -   gpu = 1671
[task 2023-03-02T07:26:40.933Z] 07:26:40     INFO -   gmplugin = undefined
[task 2023-03-02T07:26:40.934Z] 07:26:40     INFO -   utility = 62
[task 2023-03-02T07:26:40.934Z] 07:26:40     INFO -   __other__ = undefined
[task 2023-03-02T07:26:40.935Z] 07:26:40     INFO - CPU time from ProcInfo after calling testFlushAllChildren:
[task 2023-03-02T07:26:40.935Z] 07:26:40     INFO -   pid: 3128, type = parent, cpu time = 3203.125ms
[task 2023-03-02T07:26:40.935Z] 07:26:40     INFO -   pid: 8964, type = web, cpu time = 78.125ms
[task 2023-03-02T07:26:40.936Z] 07:26:40     INFO -   pid: 4788, type = privilegedabout, cpu time = 250ms
[task 2023-03-02T07:26:40.936Z] 07:26:40     INFO -   pid: 1116, type = web, cpu time = 156.25ms
[task 2023-03-02T07:26:40.937Z] 07:26:40     INFO -   pid: 9724, type = extension, cpu time = 328.125ms
[task 2023-03-02T07:26:40.937Z] 07:26:40     INFO -   pid: 6556, type = utility, cpu time = 62.5ms
[task 2023-03-02T07:26:40.937Z] 07:26:40     INFO -   pid: 2836, type = preallocated, cpu time = 171.875ms
[task 2023-03-02T07:26:40.938Z] 07:26:40     INFO -   pid: 9048, type = gpu, cpu time = 1671.875ms
[task 2023-03-02T07:26:40.938Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | The sum of CPU time used by all process types should match totalCpuTimeMs - 6153 == 6153 - 
[task 2023-03-02T07:26:40.939Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | reported parent cpu time should be at least what the first requestProcInfo returned - 3203 >= 3187 - 
[task 2023-03-02T07:26:40.939Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | reported parent cpu time should be at most what the second requestProcInfo returned - 3203 <= 3204 - 
[task 2023-03-02T07:26:40.940Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no media was played so the CPU time for parent.active.playing-audio should be undefined - "undefined" === "undefined" - 
[task 2023-03-02T07:26:40.940Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no media was played so the CPU time for parent.active.playing-video should be undefined - "undefined" === "undefined" - 
[task 2023-03-02T07:26:40.941Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no media was played so the CPU time for parent.inactive.playing-audio should be undefined - "undefined" === "undefined" - 
[task 2023-03-02T07:26:40.941Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no media was played so the CPU time for parent.inactive.playing-video should be undefined - "undefined" === "undefined" - 
[task 2023-03-02T07:26:40.942Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | reported cpu time for preallocated content processes should be at least the sum of what the first requestProcInfo returned. - 327 >= 156 - 
[task 2023-03-02T07:26:40.943Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | we used some CPU time in a foreground tab, but don't know how much as the process might have started as preallocated - 250 >= 1 - 
[task 2023-03-02T07:26:40.943Z] 07:26:40     INFO - no rdd process existed when we started our test, but some might have existed before
[task 2023-03-02T07:26:40.944Z] 07:26:40     INFO - no socket process existed when we started our test, but some might have existed before
[task 2023-03-02T07:26:40.944Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | reported cpu time for extension process should be at least what the first requestProcInfo returned. - 328 >= 328 - 
[task 2023-03-02T07:26:40.945Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | reported cpu time for extension process should be at most what the second requestProcInfo returned. - 328 <= 329 - 
[task 2023-03-02T07:26:40.946Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | reported cpu time for gpu process should be at least what the first requestProcInfo returned. - 1671 >= 1671 - 
[task 2023-03-02T07:26:40.946Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | reported cpu time for gpu process should be at most what the second requestProcInfo returned. - 1671 <= 1672 - 
[task 2023-03-02T07:26:40.947Z] 07:26:40     INFO - no gmplugin process existed when we started our test, but some might have existed before
[task 2023-03-02T07:26:40.947Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | reported cpu time for utility process should be at least what the first requestProcInfo returned. - 62 >= 62 - 
[task 2023-03-02T07:26:40.948Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | reported cpu time for utility process should be at most what the second requestProcInfo returned. - 62 <= 63 - 
[task 2023-03-02T07:26:40.948Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | web.background should be at least the time we spent. - 63 >= 62 - 
[task 2023-03-02T07:26:40.949Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | we used some CPU time in a foreground tab, but don't know how much - 249 >= 1 - 
[task 2023-03-02T07:26:40.949Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | CPU time should only be recorded in the web.background-perceivable label - "undefined" === "undefined" - 
[task 2023-03-02T07:26:40.950Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no CPU time should be recorded in the __other__ label - "undefined" === "undefined" - 
[task 2023-03-02T07:26:40.950Z] 07:26:40     INFO - GPU time for each label:
[task 2023-03-02T07:26:40.950Z] 07:26:40     INFO -   parent.active = undefined
[task 2023-03-02T07:26:40.951Z] 07:26:40     INFO -   parent.active.playing-audio = undefined
[task 2023-03-02T07:26:40.951Z] 07:26:40     INFO -   parent.active.playing-video = undefined
[task 2023-03-02T07:26:40.952Z] 07:26:40     INFO -   parent.inactive = undefined
[task 2023-03-02T07:26:40.952Z] 07:26:40     INFO -   parent.inactive.playing-audio = undefined
[task 2023-03-02T07:26:40.952Z] 07:26:40     INFO -   parent.inactive.playing-video = undefined
[task 2023-03-02T07:26:40.953Z] 07:26:40     INFO -   prealloc = undefined
[task 2023-03-02T07:26:40.953Z] 07:26:40     INFO -   privilegedabout = undefined
[task 2023-03-02T07:26:40.954Z] 07:26:40     INFO -   rdd = undefined
[task 2023-03-02T07:26:40.954Z] 07:26:40     INFO -   socket = undefined
[task 2023-03-02T07:26:40.954Z] 07:26:40     INFO -   web.background = undefined
[task 2023-03-02T07:26:40.955Z] 07:26:40     INFO -   web.background-perceivable = undefined
[task 2023-03-02T07:26:40.955Z] 07:26:40     INFO -   web.foreground = undefined
[task 2023-03-02T07:26:40.955Z] 07:26:40     INFO -   extension = undefined
[task 2023-03-02T07:26:40.956Z] 07:26:40     INFO -   gpu = 216
[task 2023-03-02T07:26:40.956Z] 07:26:40     INFO -   gmplugin = undefined
[task 2023-03-02T07:26:40.957Z] 07:26:40     INFO -   utility = undefined
[task 2023-03-02T07:26:40.957Z] 07:26:40     INFO -   __other__ = undefined
[task 2023-03-02T07:26:40.958Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | The sum of GPU time used by all process types should match totalGpuTimeMs - 216 == 216 - 
[task 2023-03-02T07:26:40.958Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no GPU time should be recorded in the __other__ label - "undefined" === "undefined" - 
[task 2023-03-02T07:26:40.959Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | some CPU time should have been recorded for the parentInactive main thread - 718 > 0 - 
[task 2023-03-02T07:26:40.959Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | some thread wake ups should have been recorded for the parentInactive main thread - 23 > 0 - 
[task 2023-03-02T07:26:40.960Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | some CPU time should have been recorded for the contentBackground main thread - 63 > 0 - 
[task 2023-03-02T07:26:40.961Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | some thread wake ups should have been recorded for the contentBackground main thread - 30 > 0 - 
[task 2023-03-02T07:26:40.961Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | some CPU time should have been recorded for the contentForeground main thread - 203 > 0 - 
[task 2023-03-02T07:26:40.962Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | some thread wake ups should have been recorded for the contentForeground main thread - 405 > 0 - 
[task 2023-03-02T07:26:40.962Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | some CPU time should have been recorded for the gpuProcess main thread - 15 > 0 - 
[task 2023-03-02T07:26:40.963Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | some thread wake ups should have been recorded for the gpuProcess main thread - 180 > 0 - 
[task 2023-03-02T07:26:40.963Z] 07:26:40     INFO - Leaving test bound 
[task 2023-03-02T07:26:40.964Z] 07:26:40     INFO - Entering test bound test_tracker_power
[task 2023-03-02T07:26:40.965Z] 07:26:40     INFO - Console message: [JavaScript Warning: "Request to access cookie or storage on http://trackertest.org/browser/toolkit/components/processtools/tests/browser/dummy.html was blocked because it came from a tracker and content blocking is enabled."]
[task 2023-03-02T07:26:40.965Z] 07:26:40     INFO - Buffered messages finished
[task 2023-03-02T07:26:40.965Z] 07:26:40     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | The CPU time of unknown trackers should have increased - 0 > 0 - {"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js","name":"test_tracker_power","sourceId":583,"lineNumber":381,"columnNumber":10,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"test_tracker_power@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js:381:10\n","nativeSavedFrame":{}}
[task 2023-03-02T07:26:40.965Z] 07:26:40     INFO - Stack trace:
[task 2023-03-02T07:26:40.965Z] 07:26:40     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js:test_tracker_power:381
[task 2023-03-02T07:26:40.966Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no new CPU time should have been recorded for ad trackers - 0 == 0 - 
[task 2023-03-02T07:26:40.967Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no new CPU time should have been recorded for analytics trackers - 0 == 0 - 
[task 2023-03-02T07:26:40.967Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no new CPU time should have been recorded for cryptomining trackers - 0 == 0 - 
[task 2023-03-02T07:26:40.968Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no new CPU time should have been recorded for fingerprinting trackers - 0 == 0 - 
[task 2023-03-02T07:26:40.968Z] 07:26:40     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | no new CPU time should have been recorded for social trackers - 0 == 0 - 
[task 2023-03-02T07:26:40.969Z] 07:26:40     INFO - Leaving test bound test_tracker_power
[task 2023-03-02T07:26:41.258Z] 07:26:41     INFO - GECKO(10088) | MEMORY STAT | vsize 2112340MB | vsizeMaxContiguous 68450008MB | residentFast 250MB | heapAllocated 122MB
[task 2023-03-02T07:26:41.259Z] 07:26:41     INFO - TEST-OK | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | took 1562ms
[task 2023-03-02T07:26:41.270Z] 07:26:41     INFO - checking window state
[task 2023-03-02T07:26:41.275Z] 07:26:41     INFO - TEST-START | toolkit/components/processtools/tests/browser/browser_test_procinfo.js
See Also: → 1816568
Assignee: nobody → aryx.bugmail
Status: NEW → ASSIGNED
Assignee: aryx.bugmail → nobody
Status: ASSIGNED → NEW
Keywords: leave-open
Pushed by archaeopteryx@coole-files.de: https://hg.mozilla.org/integration/autoland/rev/67d30d2d9d9e don't run browser_test_powerMetrics.js on Windows 11 opt. r=jmaher DONTBUILD

Tier 1 here

Summary: Intermittent [tier 2] toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | single tracking bug → Intermittent toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | single tracking bug

There have been 64 total failures in the last 7 days.
There are:

  • 54 failures on Windows 11 x64 22H2 WebRender debug
  • 10 failures on Windows 11 x86 22H2 WebRender debug

Recent failure log.

[task 2023-06-18T13:04:24.480Z] 13:04:24     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | reported cpu time for gpu process should be at most what the second requestProcInfo returned. - 2500 <= 2516 - 
[task 2023-06-18T13:04:24.481Z] 13:04:24     INFO - no gmplugin process existed when we started our test, but some might have existed before
[task 2023-06-18T13:04:24.481Z] 13:04:24     INFO - Buffered messages finished
[task 2023-06-18T13:04:24.486Z] 13:04:24     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | 'undefined' is not a number - {"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js","name":null,"sourceId":584,"lineNumber":214,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":537,"lineNumber":1131,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":537,"lineNumber":1203,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":537,"lineNumber":1345,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":537,"lineNumber":1120,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":562,"lineNumber":1056,"columnNumber":13,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"nextTest/<@chrome://mochikit/content/browser-test.js:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"Tester_execTest@chrome://mochikit/content/browser-test.js:1345:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1345:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"async*handleTask@chrome://mochikit/content/browser-test.js:1131:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1345:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js:214:14\nasync*handleTask@chrome://mochikit/content/browser-test.js:1131:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1345:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}}
[task 2023-06-18T13:04:24.486Z] 13:04:24     INFO - Stack trace:
[task 2023-06-18T13:04:24.486Z] 13:04:24     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js:null:214
[task 2023-06-18T13:04:24.486Z] 13:04:24     INFO - chrome://mochikit/content/browser-test.js:handleTask:1131
[task 2023-06-18T13:04:24.486Z] 13:04:24     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1203
[task 2023-06-18T13:04:24.486Z] 13:04:24     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1345
[task 2023-06-18T13:04:24.486Z] 13:04:24     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1120
[task 2023-06-18T13:04:24.486Z] 13:04:24     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1056
[task 2023-06-18T13:04:24.489Z] 13:04:24     INFO - GECKO(5328) | [Child 1308: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (1984167eda0) [pid = 1308] [serial = 1] [outer = 0] [url = http://example.org/browser/toolkit/components/processtools/tests/browser/dummy.html]
[task 2023-06-18T13:04:24.492Z] 13:04:24     INFO - GECKO(5328) | [Child 1308: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (19848a48800) [pid = 1308] [serial = 2] [outer = 0] [url = about:blank]
[task 2023-06-18T13:04:24.495Z] 13:04:24     INFO - GECKO(5328) | [Child 1308: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (19848a4b800) [pid = 1308] [serial = 3] [outer = 0] [url = http://example.org/browser/toolkit/components/processtools/tests/browser/dummy.html]
[task 2023-06-18T13:04:24.496Z] 13:04:24     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-06-18T13:04:24.502Z] 13:04:24     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | 'undefined' is not a number - {"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js","name":null,"sourceId":584,"lineNumber":224,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":537,"lineNumber":1131,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":537,"lineNumber":1203,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":537,"lineNumber":1345,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":537,"lineNumber":1120,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":562,"lineNumber":1056,"columnNumber":13,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"nextTest/<@chrome://mochikit/content/browser-test.js:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"Tester_execTest@chrome://mochikit/content/browser-test.js:1345:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1345:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"async*handleTask@chrome://mochikit/content/browser-test.js:1131:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1345:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js:224:14\nasync*handleTask@chrome://mochikit/content/browser-test.js:1131:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1345:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}}
[task 2023-06-18T13:04:24.502Z] 13:04:24     INFO - Stack trace:
[task 2023-06-18T13:04:24.502Z] 13:04:24     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js:null:224
[task 2023-06-18T13:04:24.502Z] 13:04:24     INFO - chrome://mochikit/content/browser-test.js:handleTask:1131
[task 2023-06-18T13:04:24.505Z] 13:04:24     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1203
[task 2023-06-18T13:04:24.505Z] 13:04:24     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1345
[task 2023-06-18T13:04:24.505Z] 13:04:24     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1120
[task 2023-06-18T13:04:24.505Z] 13:04:24     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1056
[task 2023-06-18T13:04:24.505Z] 13:04:24     INFO - GECKO(5328) | [Child 1308, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2023-06-18T13:04:24.506Z] 13:04:24     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | web.background should be at least the time we spent. - 93 >= 62 - 

Hello Doug! As the owner of this component, could you help us assign the bug to someone?

Thank you!

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

There have been 38 total failures in the last 7 days.
There are:

  • 4 failures on windows11-32-2009-qr debug
  • 34 failures on windows11-64-2009-qr debug

Recent failure log.

See Also: → 1778932

There have been 36 total failures in the last 7 days.
There are:

  • 4 failures on windows11-32-2009-qr debug
  • 32 failures on windows11-64-2009-qr debug

Recent failure log.

There have been 32 total failures in the last 7 days.
There are:

  • 8 failures on windows11-32-2009-qr debug
  • 24 failures on windows11-64-2009-qr debug

Recent failure log.

Mike, as the owner of this component, can you help us assign the bug to someone? Thank you.

Flags: needinfo?(mconley)
Whiteboard: [stockwell unknown] → [stockwell unknown][stockwell needswork:owner]

Hey gerard-majax, reading the logs here, it looks like we're failing to properly set the cpuTimePerProcessTypeMs Glean probe value for the utility process pretty frequently. I'm not really familiar with the utility process at all... any idea what we might need to do here in order to ensure that a utility process is running and we've collected power metrics for it?

Flags: needinfo?(mconley) → needinfo?(lissyx+mozillians)

(In reply to Mike Conley (:mconley) (:⚙️) from comment #44)

Hey gerard-majax, reading the logs here, it looks like we're failing to properly set the cpuTimePerProcessTypeMs Glean probe value for the utility process pretty frequently. I'm not really familiar with the utility process at all... any idea what we might need to do here in order to ensure that a utility process is running and we've collected power metrics for it?

no, we've looked at that a lot with florian, and the problem was unclear to me, and fixing it was depending on other stuff ...

Flags: needinfo?(lissyx+mozillians)

(In reply to Mike Conley (:mconley) (:⚙️) from comment #44)

Hey gerard-majax, reading the logs here, it looks like we're failing to properly set the cpuTimePerProcessTypeMs Glean probe value for the utility process pretty frequently. I'm not really familiar with the utility process at all... any idea what we might need to do here in order to ensure that a utility process is running and we've collected power metrics for it?

What we need to do wasn't completely clear last time Alex and I discussed it, but at least the root cause of the problem is known: https://searchfox.org/mozilla-central/rev/6e5b9a5a1edab13a1b2e2e90944b6e06b4d8149c/toolkit/components/processtools/ProcInfo_win.cpp#38 returns early for our Windows 11 test machines (that happen to be virtual machines), causing the real code path used by most users to not be covered. When returning early there, all the CPU time measurements have a precision of 1/64s (ie 15.625ms), whereas the code path used by physical machines has a 1ms precision.

If I remember correctly, the utility process has more reported failures here because it frequently uses less than 15.625ms of CPU time.

(In reply to :gerard-majax from comment #46)

the problem was related to https://searchfox.org/mozilla-central/rev/6e5b9a5a1edab13a1b2e2e90944b6e06b4d8149c/js/xpconnect/src/xpcpublic.h#734

Ah, this mention of xpc::IsInAutomation reminds me that our plan was to make the code I pointed to in comment 47 not return early when we are in a VM if we are in our CI, to ensure the code used most of the time gets proper code coverage. That turned out to be difficult because we realized xpc::IsInAutomation doesn't work in content processes. I don't remember why it's broken, but fixing it was non-trivial (at least we couldn't figure it out within an hour or two).

Update:

There have been 45 total failures in the last 7 days.
There are:

  • 9 failures on windows11-32-2009-qr debug
  • 36failures on windows11-64-2009-qr debug

Recent failure log.

Attachment #9361715 - Attachment description: Bug 1819845 - Disable browser_test_powerMetrics.js also on win !debug for frequent failures. r=#intermittent-reviewers → Bug 1819845 - Disable browser_test_powerMetrics.js also on win debug for frequent failures. r=#intermittent-reviewers
Pushed by csabou@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/1724ae71ab99 Disable browser_test_powerMetrics.js also on win debug for frequent failures. r=#intermittent-reviewers,jmaher
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Depends on: 1880373

The patches that landed in bug 1880373 should have fixed most failures, and re-enabled the test.

Flags: needinfo?(dothayer)
Whiteboard: [stockwell disabled]
Attachment #9386701 - Attachment is obsolete: true
Depends on: 1903836

The "no CPU time should be recorded in the other label" failure is being fixed in bug 1903836.

Status: NEW → RESOLVED
Closed: 2 months ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: