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

[task 2022-04-30T11:35:58.685Z] 11:35:58     INFO - TEST-START | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js
[task 2022-04-30T11:35:59.130Z] 11:35:59     INFO - GECKO(7908) | [Parent 1008, IPC I/O Parent] WARNING: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_win.cc:167
[task 2022-04-30T11:35:59.167Z] 11:35:59     INFO - TEST-INFO | started process screenshot
[task 2022-04-30T11:35:59.252Z] 11:35:59     INFO - TEST-INFO | screenshot: exit 0
[task 2022-04-30T11:35:59.265Z] 11:35:59     INFO - Buffered messages logged at 11:35:58
[task 2022-04-30T11:35:59.265Z] 11:35:59     INFO - Entering test bound 
[task 2022-04-30T11:35:59.266Z] 11:35:59     INFO - Buffered messages logged at 11:35:59
[task 2022-04-30T11:35:59.266Z] 11:35:59     INFO - CPU time from ProcInfo before calling testFlushAllChildren:
[task 2022-04-30T11:35:59.267Z] 11:35:59     INFO -   pid: 1008, type = parent, cpu time = 3234.375ms
[task 2022-04-30T11:35:59.267Z] 11:35:59     INFO -   pid: 1576, type = extension, cpu time = 343.75ms
[task 2022-04-30T11:35:59.268Z] 11:35:59     INFO -   pid: 4508, type = gpu, cpu time = 1750ms
[task 2022-04-30T11:35:59.268Z] 11:35:59     INFO -   pid: 8492, type = web, cpu time = 218.75ms
[task 2022-04-30T11:35:59.269Z] 11:35:59     INFO -   pid: 2800, type = privilegedabout, cpu time = 265.625ms
[task 2022-04-30T11:35:59.269Z] 11:35:59     INFO -   pid: 7812, type = web, cpu time = 171.875ms
[task 2022-04-30T11:35:59.270Z] 11:35:59     INFO -   pid: 6980, type = preallocated, cpu time = 62.5ms
[task 2022-04-30T11:35:59.270Z] 11:35:59     INFO - CPU time for each label:
[task 2022-04-30T11:35:59.271Z] 11:35:59     INFO -   parent.active = 500
[task 2022-04-30T11:35:59.271Z] 11:35:59     INFO -   parent.active.playing-audio = undefined
[task 2022-04-30T11:35:59.272Z] 11:35:59     INFO -   parent.active.playing-video = undefined
[task 2022-04-30T11:35:59.272Z] 11:35:59     INFO -   parent.inactive = 2734
[task 2022-04-30T11:35:59.273Z] 11:35:59     INFO -   parent.inactive.playing-audio = undefined
[task 2022-04-30T11:35:59.273Z] 11:35:59     INFO -   parent.inactive.playing-video = undefined
[task 2022-04-30T11:35:59.274Z] 11:35:59     INFO -   prealloc = 358
[task 2022-04-30T11:35:59.274Z] 11:35:59     INFO -   privilegedabout = 187
[task 2022-04-30T11:35:59.274Z] 11:35:59     INFO -   rdd = undefined
[task 2022-04-30T11:35:59.275Z] 11:35:59     INFO -   socket = undefined
[task 2022-04-30T11:35:59.275Z] 11:35:59     INFO -   web.background = 78
[task 2022-04-30T11:35:59.275Z] 11:35:59     INFO -   web.background-perceivable = undefined
[task 2022-04-30T11:35:59.276Z] 11:35:59     INFO -   web.foreground = 373
[task 2022-04-30T11:35:59.276Z] 11:35:59     INFO -   extension = 343
[task 2022-04-30T11:35:59.276Z] 11:35:59     INFO -   gpu = 1750
[task 2022-04-30T11:35:59.277Z] 11:35:59     INFO -   gmplugin = undefined
[task 2022-04-30T11:35:59.277Z] 11:35:59     INFO -   utility = undefined
[task 2022-04-30T11:35:59.277Z] 11:35:59     INFO -   __other__ = undefined
[task 2022-04-30T11:35:59.278Z] 11:35:59     INFO - CPU time from ProcInfo after calling testFlushAllChildren:
[task 2022-04-30T11:35:59.278Z] 11:35:59     INFO -   pid: 1008, type = parent, cpu time = 3265.625ms
[task 2022-04-30T11:35:59.279Z] 11:35:59     INFO -   pid: 1576, type = extension, cpu time = 343.75ms
[task 2022-04-30T11:35:59.279Z] 11:35:59     INFO -   pid: 4508, type = gpu, cpu time = 1750ms
[task 2022-04-30T11:35:59.279Z] 11:35:59     INFO -   pid: 8492, type = web, cpu time = 218.75ms
[task 2022-04-30T11:35:59.280Z] 11:35:59     INFO -   pid: 2800, type = privilegedabout, cpu time = 265.625ms
[task 2022-04-30T11:35:59.280Z] 11:35:59     INFO -   pid: 7812, type = web, cpu time = 171.875ms
[task 2022-04-30T11:35:59.280Z] 11:35:59     INFO -   pid: 6980, type = preallocated, cpu time = 62.5ms
[task 2022-04-30T11:35:59.281Z] 11:35:59     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 - 6323 == 6323 - 
[task 2022-04-30T11:35:59.282Z] 11:35:59     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 - 3234 >= 3234 - 
[task 2022-04-30T11:35:59.283Z] 11:35:59     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 - 3234 <= 3266 - 
[task 2022-04-30T11:35:59.284Z] 11:35:59     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 2022-04-30T11:35:59.285Z] 11:35:59     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 2022-04-30T11:35:59.285Z] 11:35:59     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 2022-04-30T11:35:59.286Z] 11:35:59     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 2022-04-30T11:35:59.287Z] 11:35:59     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. - 358 >= 62 - 
[task 2022-04-30T11:35:59.287Z] 11:35:59     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 - 187 >= 1 - 
[task 2022-04-30T11:35:59.288Z] 11:35:59     INFO - no rdd process existed when we started our test, but some might have existed before
[task 2022-04-30T11:35:59.288Z] 11:35:59     INFO - no socket process existed when we started our test, but some might have existed before
[task 2022-04-30T11:35:59.289Z] 11:35:59     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. - 343 >= 343 - 
[task 2022-04-30T11:35:59.289Z] 11:35:59     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. - 343 <= 344 - 
[task 2022-04-30T11:35:59.290Z] 11:35:59     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. - 1750 >= 1750 - 
[task 2022-04-30T11:35:59.291Z] 11:35:59     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. - 1750 <= 1750 - 
[task 2022-04-30T11:35:59.291Z] 11:35:59     INFO - no gmplugin process existed when we started our test, but some might have existed before
[task 2022-04-30T11:35:59.292Z] 11:35:59     INFO - no utility process existed when we started our test, but some might have existed before
[task 2022-04-30T11:35:59.292Z] 11:35:59     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | web.background should be at least the time we spent. - 78 >= 78 - 
[task 2022-04-30T11:35:59.293Z] 11:35:59     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 - 373 >= 1 - 
[task 2022-04-30T11:35:59.294Z] 11:35:59     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 2022-04-30T11:35:59.294Z] 11:35:59     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 2022-04-30T11:35:59.295Z] 11:35:59     INFO - GPU time for each label:
[task 2022-04-30T11:35:59.295Z] 11:35:59     INFO -   parent.active = undefined
[task 2022-04-30T11:35:59.295Z] 11:35:59     INFO -   parent.active.playing-audio = undefined
[task 2022-04-30T11:35:59.296Z] 11:35:59     INFO -   parent.active.playing-video = undefined
[task 2022-04-30T11:35:59.296Z] 11:35:59     INFO -   parent.inactive = undefined
[task 2022-04-30T11:35:59.296Z] 11:35:59     INFO -   parent.inactive.playing-audio = undefined
[task 2022-04-30T11:35:59.297Z] 11:35:59     INFO -   parent.inactive.playing-video = undefined
[task 2022-04-30T11:35:59.298Z] 11:35:59     INFO -   prealloc = undefined
[task 2022-04-30T11:35:59.298Z] 11:35:59     INFO -   privilegedabout = undefined
[task 2022-04-30T11:35:59.299Z] 11:35:59     INFO -   rdd = undefined
[task 2022-04-30T11:35:59.299Z] 11:35:59     INFO -   socket = undefined
[task 2022-04-30T11:35:59.300Z] 11:35:59     INFO -   web.background = undefined
[task 2022-04-30T11:35:59.300Z] 11:35:59     INFO -   web.background-perceivable = undefined
[task 2022-04-30T11:35:59.301Z] 11:35:59     INFO -   web.foreground = undefined
[task 2022-04-30T11:35:59.301Z] 11:35:59     INFO -   extension = undefined
[task 2022-04-30T11:35:59.301Z] 11:35:59     INFO -   gpu = 189
[task 2022-04-30T11:35:59.302Z] 11:35:59     INFO -   gmplugin = undefined
[task 2022-04-30T11:35:59.302Z] 11:35:59     INFO -   utility = undefined
[task 2022-04-30T11:35:59.302Z] 11:35:59     INFO -   __other__ = undefined
[task 2022-04-30T11:35:59.303Z] 11:35:59     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 - 189 == 189 - 
[task 2022-04-30T11:35:59.303Z] 11:35:59     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 2022-04-30T11:35:59.304Z] 11:35:59     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | some CPU time should have been recorded for the parentInactive main thread - 1578 > 0 - 
[task 2022-04-30T11:35:59.304Z] 11:35:59     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 - 198 > 0 - 
[task 2022-04-30T11:35:59.305Z] 11:35:59     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | some CPU time should have been recorded for the contentBackground main thread - 62 > 0 - 
[task 2022-04-30T11:35:59.305Z] 11:35:59     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 - 18 > 0 - 
[task 2022-04-30T11:35:59.306Z] 11:35:59     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | some CPU time should have been recorded for the contentForeground main thread - 265 > 0 - 
[task 2022-04-30T11:35:59.306Z] 11:35:59     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 - 469 > 0 - 
[task 2022-04-30T11:35:59.307Z] 11:35:59     INFO - Buffered messages finished
[task 2022-04-30T11:35:59.307Z] 11:35:59     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | 'undefined' is not a number - JS frame :: chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js :: <TOP_LEVEL> :: line 305
[task 2022-04-30T11:35:59.307Z] 11:35:59     INFO - Stack trace:
[task 2022-04-30T11:35:59.307Z] 11:35:59     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js:null:305
[task 2022-04-30T11:35:59.308Z] 11:35:59     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 - 143 > 0 - 
[task 2022-04-30T11:35:59.308Z] 11:35:59     INFO - Leaving test bound 
[task 2022-04-30T11:35:59.308Z] 11:35:59     INFO - GECKO(7908) | MEMORY STAT | vsize 2112339MB | vsizeMaxContiguous 66679565MB | residentFast 240MB | heapAllocated 107MB
[task 2022-04-30T11:35:59.309Z] 11:35:59     INFO - TEST-OK | toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js | took 495ms
[task 2022-04-30T11:35:59.309Z] 11:35:59     INFO - checking window state

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

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=382317377&repo=mozilla-central

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

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

This is failing frequently now. The failure line is 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":578,"lineNumber":214,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_powerMetrics.js:214:14\n","nativeSavedFrame":{}} - Failure log.

Hi Joel! Can you please take a look at this? This seems to be frequent on windows 11. The frequency rate increased after Bug 1816568 landed(I guess it is somehow expected since we didn't had windows 11 before that). Maybe you could help us assign this to someone or to give more insight about this.
Thank you!

thanks for mentioning this. I saw this a few times on try pushes, but not this frequent, so we need to do something about these failures.

Looking at the logs from comment 14 ^; I see:

[task 2023-02-27T21:03:31.164Z] 21:03:31     INFO -   privilegedabout = 406
[task 2023-02-27T21:03:31.165Z] 21:03:31     INFO -   rdd = undefined
[task 2023-02-27T21:03:31.165Z] 21:03:31     INFO -   socket = undefined
[task 2023-02-27T21:03:31.166Z] 21:03:31     INFO -   web.background = 62
[task 2023-02-27T21:03:31.167Z] 21:03:31     INFO -   web.background-perceivable = undefined
[task 2023-02-27T21:03:31.167Z] 21:03:31     INFO -   web.foreground = 717
[task 2023-02-27T21:03:31.168Z] 21:03:31     INFO -   extension = 1062
[task 2023-02-27T21:03:31.168Z] 21:03:31     INFO -   gpu = 953
[task 2023-02-27T21:03:31.169Z] 21:03:31     INFO -   gmplugin = undefined
[task 2023-02-27T21:03:31.169Z] 21:03:31     INFO -   utility = undefined
[task 2023-02-27T21:03:31.169Z] 21:03:31     INFO -   __other__ = undefined
[task 2023-02-27T21:03:31.170Z] 21:03:31     INFO - CPU time from ProcInfo after calling testFlushAllChildren:
[task 2023-02-27T21:03:31.170Z] 21:03:31     INFO -   pid: 2664, type = parent, cpu time = 7296.875ms
[task 2023-02-27T21:03:31.171Z] 21:03:31     INFO -   pid: 10024, type = utility, cpu time = 0ms
[task 2023-02-27T21:03:31.171Z] 21:03:31     INFO -   pid: 5196, type = gpu, cpu time = 984.375ms
[task 2023-02-27T21:03:31.172Z] 21:03:31     INFO -   pid: 8204, type = web, cpu time = 250ms
[task 2023-02-27T21:03:31.172Z] 21:03:31     INFO -   pid: 3528, type = extension, cpu time = 1062.5ms
[task 2023-02-27T21:03:31.173Z] 21:03:31     INFO -   pid: 1412, type = preallocated, cpu time = 171.875ms
[task 2023-02-27T21:03:31.174Z] 21:03:31     INFO -   pid: 9092, type = privilegedabout, cpu time = 406.25ms
[task 2023-02-27T21:03:31.175Z] 21:03:31     INFO -   pid: 1296, type = web, cpu time = 296.875ms

what is interesting here is the utility has cpu time of 0ms. I believe this is causing the problems with the test. I don't know if there is an issue with utility on windows11, or something with the configuration.

:florian, could you take a look at this and see what can be done to fix this (to avoid disabling)

Update

There have been 51 failures within the last 7 days:

• 2 failures on Windows 10 x64 2004 WebRender opt
• 1 failure on Windows 10 x64 2004 WebRender Shippable opt
• 1 failure on Windows 11 x86 22H2 WebRender debug
• 28 failures on Windows 11 x64 22H2 WebRender debug/opt
• 19 failures on Windows 11 x64 22H2 WebRender Shippable opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=407527668&repo=mozilla-central&lineNumber=16033

(In reply to Joel Maher ( :jmaher ) (UTC -8) from comment #16)

what is interesting here is the utility has cpu time of 0ms. I believe this is causing the problems with the test. I don't know if there is an issue with utility on windows11, or something with the configuration.

:florian, could you take a look at this and see what can be done to fix this (to avoid disabling)

This test relies on ProcInfo working well, and bug 1778932 shows browser_test_procinfo.js frequently failing on Windows 11, reporting incorrect 0 values. I think bug 1778932 should be investigated before we spend time on this bug, as it's likely that will fix both tests at once.

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