Intermittent toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | single tracking bug
Categories
(Toolkit :: Performance Monitoring, defect, P5)
Tracking
()
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
Comment 1•2 years ago
|
||
Test ran on this platform since bug 1816558 landed.
Updated•2 years ago
|
Updated•2 years ago
|
Comment 3•2 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 10•2 years ago
|
||
Tier 1 here
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 22•1 year ago
|
||
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!
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 25•1 year ago
|
||
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.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 28•1 year ago
|
||
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.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 43•1 year ago
|
||
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.
Comment 44•1 year ago
|
||
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?
Comment 45•1 year ago
|
||
(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 ...
Comment 46•1 year ago
|
||
fyi https://searchfox.org/mozilla-central/rev/3b707c8fd7e978eebf24279ee51ccf07895cfbcb/toolkit/components/telemetry/tests/unit/test_UtilityScalars.js#14-18 is still doable to trigger one for sure, but the problem was related to https://searchfox.org/mozilla-central/rev/6e5b9a5a1edab13a1b2e2e90944b6e06b4d8149c/js/xpconnect/src/xpcpublic.h#734
Comment 47•1 year ago
|
||
(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.
Comment 48•1 year ago
|
||
(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).
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 52•1 year ago
|
||
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.
Comment 53•1 year ago
|
||
Updated•1 year ago
|
Comment 54•1 year ago
|
||
Updated•1 year ago
|
Comment 55•1 year ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 60•9 months ago
|
||
The patches that landed in bug 1880373 should have fixed most failures, and re-enabled the test.
Updated•9 months ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 67•5 months ago
|
||
The "no CPU time should be recorded in the other label" failure is being fixed in bug 1903836.
Comment 68•2 months ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.
Updated•1 month ago
|
Description
•