Open Bug 1778932 Opened 3 years ago Updated 16 hours ago

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

Categories

(Toolkit :: Performance Monitoring, defect, P3)

Product:
Toolkit
Component:
Performance Monitoring
Type:
defect

Tracking

()

Status:
REOPENED
Tracking Flags:
Tracking Status
firefox-esr115 --- unaffected
firefox-esr128 --- unaffected
firefox129 --- unaffected
firefox130 --- unaffected
firefox131 --- wontfix

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, intermittent-testcase, regression)

Attachments

(1 file)

Bug 1778932 - Disable browser_test_procinfo.js on windows !debug for frequent failures. r=#intermittent-reviewers,aryx
48 bytes, text/x-phabricator-request
Details | Review

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

[task 2022-07-11T04:38:31.128Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time in the threads - 835 > 0 - 
[task 2022-07-11T04:38:31.129Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | The total CPU time of the process should be at least the sum of the CPU time spent by the still alive threads - 842 >= 835 - 
[task 2022-07-11T04:38:31.129Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child proc type should not be browser - "socket" != "browser" - 
[task 2022-07-11T04:38:31.130Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child proc type should be known - "socket" != "unknown" - 
[task 2022-07-11T04:38:31.130Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time - 140826154 > 0 - 
[task 2022-07-11T04:38:31.130Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time in the threads - 137 > 0 - 
[task 2022-07-11T04:38:31.131Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | The total CPU time of the process should be at least the sum of the CPU time spent by the still alive threads - 141 >= 137 - 
[task 2022-07-11T04:38:31.131Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child proc type should not be browser - "preallocated" != "browser" - 
[task 2022-07-11T04:38:31.132Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child proc type should be known - "preallocated" != "unknown" - 
[task 2022-07-11T04:38:31.132Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time - 260588316 > 0 - 
[task 2022-07-11T04:38:31.132Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time in the threads - 262 > 0 - 
[task 2022-07-11T04:38:31.133Z] 04:38:31     INFO - Buffered messages finished
[task 2022-07-11T04:38:31.134Z] 04:38:31     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | The total CPU time of the process should be at least the sum of the CPU time spent by the still alive threads - 261 >= 262 - JS frame :: chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js :: checkProcessCpuTime :: line 40
[task 2022-07-11T04:38:31.134Z] 04:38:31     INFO - Stack trace:
[task 2022-07-11T04:38:31.134Z] 04:38:31     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:checkProcessCpuTime:40
[task 2022-07-11T04:38:31.134Z] 04:38:31     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info/<:118
[task 2022-07-11T04:38:31.134Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child proc type should not be browser - "webIsolated" != "browser" - 
[task 2022-07-11T04:38:31.135Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child proc should have been set - 6 != 0 - 
[task 2022-07-11T04:38:31.135Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child proc type should be known - "webIsolated" != "unknown" - 
[task 2022-07-11T04:38:31.135Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child process should have an origin - "http://example.com" != "" - 
[task 2022-07-11T04:38:31.136Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time - 800980221 > 0 - 
[task 2022-07-11T04:38:31.136Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time in the threads - 795 > 0 - 
[task 2022-07-11T04:38:31.137Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | The total CPU time of the process should be at least the sum of the CPU time spent by the still alive threads - 801 >= 795 - 
[task 2022-07-11T04:38:31.137Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child proc type should not be browser - "web" != "browser" - 
[task 2022-07-11T04:38:31.138Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child proc should have been set - 2 != 0 - 
[task 2022-07-11T04:38:31.138Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child proc type should be known - "web" != "unknown" - 
[task 2022-07-11T04:38:31.138Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time - 789826103 > 0 - 
[task 2022-07-11T04:38:31.139Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time in the threads - 784 > 0 - 
[task 2022-07-11T04:38:31.139Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | The total CPU time of the process should be at least the sum of the CPU time spent by the still alive threads - 790 >= 784 - 
[task 2022-07-11T04:38:31.140Z] 04:38:31     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child proc type should not be browser - "privilegedabout" != "browser" -

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

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE

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

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

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

  • 16 failures on Windows 11 x64 22H2 WebRender opt
  • 13 failures on Windows 11 x64 22H2 WebRender Shippable opt
  • 1 failure on Windows 7 WebRender Shippable opt

Recent failure log.

[task 2023-03-16T10:15:28.783Z] 10:15:28     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child proc type should be known - "utility" != "unknown" - 
[task 2023-03-16T10:15:28.783Z] 10:15:28     INFO - Buffered messages finished
[task 2023-03-16T10:15:28.786Z] 10:15:28     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time - 0 > 0 - {"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"checkProcessCpuTime","sourceId":582,"lineNumber":20,"columnNumber":10,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"test_proc_info/<","sourceId":582,"lineNumber":115,"columnNumber":30,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"test_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:115:30\n","nativeSavedFrame":{}},"formattedStack":"checkProcessCpuTime@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:20:10\ntest_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:115:30\n","nativeSavedFrame":{}}
[task 2023-03-16T10:15:28.786Z] 10:15:28     INFO - Stack trace:
[task 2023-03-16T10:15:28.786Z] 10:15:28     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:checkProcessCpuTime:20
[task 2023-03-16T10:15:28.786Z] 10:15:28     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info/<:115
[task 2023-03-16T10:15:28.787Z] 10:15:28     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-03-16T10:15:28.790Z] 10:15:28     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time in the threads - 0 > 0 - {"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"checkProcessCpuTime","sourceId":582,"lineNumber":26,"columnNumber":10,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"test_proc_info/<","sourceId":582,"lineNumber":115,"columnNumber":30,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"test_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:115:30\n","nativeSavedFrame":{}},"formattedStack":"checkProcessCpuTime@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:26:10\ntest_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:115:30\n","nativeSavedFrame":{}}
[task 2023-03-16T10:15:28.790Z] 10:15:28     INFO - Stack trace:
[task 2023-03-16T10:15:28.790Z] 10:15:28     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:checkProcessCpuTime:26
[task 2023-03-16T10:15:28.790Z] 10:15:28     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info/<:115
[task 2023-03-16T10:15:28.791Z] 10:15:28     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | The total CPU time of the process should be at least the sum of the CPU time spent by the still alive threads - 0 >= 0 -

Hello Jens! Any chance you could help us assign this to someone?

Thank you!

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

I assume that we just see some dying process. IIUC we bail out from retrieving procinfo at severel places, for example here and that in such a case we may find cpuTime to be just zero.

The question would be, if the test is meant to create a stable enough environment where it is not supposed to happen that a child process goes away while looking at all of them. Maybe procInfo should have a presumablyDead flag to keep track of such bail outs such that we can ignore them ?

Flags: needinfo?(jstutte) → needinfo?(smaug)

florian would be a better person to say anything about the test.

Flags: needinfo?(smaug) → needinfo?(florian)

@florian, did you get a chance to look into this?
Thank you

Flags: needinfo?(florian)
Flags: needinfo?(florian)
See Also: → 1767149

It seems there are at least 2 failure modes.

  • One that is low frequency, affects preallocated content processes, and has happened on Windows 7, 10 and 11, for several months.
  • One that is high frequency, Windows 11 only, and affects utility processes. This one has started recently (maybe started when we started running tests on Win11 in CI).

I haven't been able to reproduce either of these. Bug 1767149 seems related, and using --verify I could make it fail locally, but I'm not sure the failures I was seeing locally have anything to do with the failures we have in CI.

Alex, Yannis, any idea about what would be specific to Windows 11 or the utility process here?

Flags: needinfo?(yjuglaret)
Flags: needinfo?(lissyx+mozillians)

(In reply to Florian Quèze [:florian] from comment #39)

It seems there are at least 2 failure modes.

  • One that is low frequency, affects preallocated content processes, and has happened on Windows 7, 10 and 11, for several months.

My try run where I attempted to reproduce gave me a profile of this failure case: https://share.firefox.dev/3Zw51lK I haven't found anything particularly useful in it (yet?).

As we discussed with Florian, it might be helpful to augment the test case and make sure we get a view of the Utility actors [https://searchfox.org/mozilla-central/rev/9e3413f54ed6c9165b5659558091d766d34a731f/toolkit/components/aboutprocesses/content/aboutProcesses.js#269] on the process reporting 0 time. This way we might be able to know if it's a in-birth or death process or what.

Flags: needinfo?(lissyx+mozillians)

Update

There have been 32 failures within the last 7 days:

  • 1 failure on Linux 18.04 x64 WebRender debug
  • 1 failure on Windows 11 x86 22H2 WebRender debug
  • 12 failures on Windows 11 x64 22H2 WebRender opt
  • 17 failures on Windows 11 x64 22H2 WebRender Shippable opt
  • 1 failure on Windows 7 WebRender Shippable opt

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

[task 2023-04-15T23:25:24.282Z] 23:25:24     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child proc type should be known - "utility" != "unknown" - 
[task 2023-04-15T23:25:24.283Z] 23:25:24     INFO - Buffered messages finished
[task 2023-04-15T23:25:24.292Z] 23:25:24     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time - 0 > 0 - {"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"checkProcessCpuTime","sourceId":586,"lineNumber":20,"columnNumber":10,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"test_proc_info/<","sourceId":586,"lineNumber":115,"columnNumber":30,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"resource://testing-common/BrowserTestUtils.sys.mjs","name":"withNewTab","sourceId":569,"lineNumber":154,"columnNumber":22,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"test_proc_info","sourceId":586,"lineNumber":55,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":534,"lineNumber":1043,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":534,"lineNumber":1115,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":534,"lineNumber":1257,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":534,"lineNumber":1032,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":563,"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:1032:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"Tester_execTest@chrome://mochikit/content/browser-test.js:1257:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1032:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1115:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1257:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1032:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"async*handleTask@chrome://mochikit/content/browser-test.js:1043:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1115:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1257:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1032:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"async*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:55:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1043:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1115:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1257:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1032:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"async*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:154:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:55:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1043:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1115:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1257:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1032:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"test_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:115:30\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:154:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:55:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1043:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1115:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1257:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1032:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"checkProcessCpuTime@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:20:10\ntest_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:115:30\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:154:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:55:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1043:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1115:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1257:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1032:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}}
[task 2023-04-15T23:25:24.292Z] 23:25:24     INFO - Stack trace:
[task 2023-04-15T23:25:24.292Z] 23:25:24     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:checkProcessCpuTime:20
[task 2023-04-15T23:25:24.292Z] 23:25:24     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info/<:115
[task 2023-04-15T23:25:24.293Z] 23:25:24     INFO - resource://testing-common/BrowserTestUtils.sys.mjs:withNewTab:154
[task 2023-04-15T23:25:24.293Z] 23:25:24     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info:55
[task 2023-04-15T23:25:24.293Z] 23:25:24     INFO - chrome://mochikit/content/browser-test.js:handleTask:1043
[task 2023-04-15T23:25:24.293Z] 23:25:24     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1115
[task 2023-04-15T23:25:24.293Z] 23:25:24     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1257
[task 2023-04-15T23:25:24.293Z] 23:25:24     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1032
[task 2023-04-15T23:25:24.293Z] 23:25:24     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1056
[task 2023-04-15T23:25:24.294Z] 23:25:24     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-04-15T23:25:24.303Z] 23:25:24     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time in the threads - 0 > 0 - {"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"checkProcessCpuTime","sourceId":586,"lineNumber":26,"columnNumber":10,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"test_proc_info/<","sourceId":586,"lineNumber":115,"columnNumber":30,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"resource://testing-common/BrowserTestUtils.sys.mjs","name":"withNewTab","sourceId":569,"lineNumber":154,"columnNumber":22,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"test_proc_info","sourceId":586,"lineNumber":55,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":534,"lineNumber":1043,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":534,"lineNumber":1115,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":534,"lineNumber":1257,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":534,"lineNumber":1032,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":563,"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:1032:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"Tester_execTest@chrome://mochikit/content/browser-test.js:1257:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1032:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1115:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1257:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1032:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"async*handleTask@chrome://mochikit/content/browser-test.js:1043:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1115:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1257:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1032:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"async*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:55:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1043:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1115:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1257:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1032:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"async*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:154:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:55:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1043:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1115:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1257:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1032:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"test_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:115:30\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:154:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:55:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1043:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1115:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1257:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1032:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}},"formattedStack":"checkProcessCpuTime@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:26:10\ntest_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:115:30\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:154:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:55:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1043:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1115:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1257:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1032:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1056:13\n","nativeSavedFrame":{}}
[task 2023-04-15T23:25:24.303Z] 23:25:24     INFO - Stack trace:
[task 2023-04-15T23:25:24.303Z] 23:25:24     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:checkProcessCpuTime:26
[task 2023-04-15T23:25:24.303Z] 23:25:24     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info/<:115
[task 2023-04-15T23:25:24.303Z] 23:25:24     INFO - resource://testing-common/BrowserTestUtils.sys.mjs:withNewTab:154
[task 2023-04-15T23:25:24.303Z] 23:25:24     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info:55
[task 2023-04-15T23:25:24.305Z] 23:25:24     INFO - chrome://mochikit/content/browser-test.js:handleTask:1043
[task 2023-04-15T23:25:24.305Z] 23:25:24     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1115
[task 2023-04-15T23:25:24.305Z] 23:25:24     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1257
[task 2023-04-15T23:25:24.305Z] 23:25:24     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1032
[task 2023-04-15T23:25:24.305Z] 23:25:24     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1056
[task 2023-04-15T23:25:24.305Z] 23:25:24     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | The total CPU time of the process should be at least the sum of the CPU time spent by the still alive threads - 0 >= 0 -

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

  • 1 failure on linux1804-64-qr debug
  • 18 failures on windows11-64-2009-qr opt
  • 10 failures on windows11-64-2009-shippable-qr opt
  • 1 failure on windows7-32-qr opt
  • 1 failure on windows7-32-shippable-qr opt

Recent failure log.

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

Flags: needinfo?(jmarshall)
Flags: needinfo?(jmarshall)

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

  • 22 failures on Windows 11 x64 22H2 WebRender Shippable opt
  • 17 failures on Windows 11 x64 22H2 WebRender opt
  • 1 failure on Windows 11 x64 22H2 CCov WebRender opt
  • 1 failure on Linux 18.04 x64 WebRender debug

Recent failure log.

[task 2023-06-13T20:07:26.197Z] 20:07:26     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child proc type should be known - "utility" != "unknown" - 
[task 2023-06-13T20:07:26.197Z] 20:07:26     INFO - Buffered messages finished
[task 2023-06-13T20:07:26.205Z] 20:07:26     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time - 0 > 0 - {"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"checkProcessCpuTime","sourceId":586,"lineNumber":20,"columnNumber":10,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"test_proc_info/<","sourceId":586,"lineNumber":115,"columnNumber":30,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"resource://testing-common/BrowserTestUtils.sys.mjs","name":"withNewTab","sourceId":570,"lineNumber":149,"columnNumber":22,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"test_proc_info","sourceId":586,"lineNumber":55,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":540,"lineNumber":1131,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":540,"lineNumber":1203,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":540,"lineNumber":1345,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":540,"lineNumber":1120,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":564,"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":"async*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:55:26\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":{}},"caller":null,"formattedStack":"async*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:149:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:55:26\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":{}},"caller":null,"formattedStack":"test_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:115:30\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:149:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:55:26\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":{}},"formattedStack":"checkProcessCpuTime@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:20:10\ntest_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:115:30\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:149:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:55:26\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-13T20:07:26.205Z] 20:07:26     INFO - Stack trace:
[task 2023-06-13T20:07:26.205Z] 20:07:26     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:checkProcessCpuTime:20
[task 2023-06-13T20:07:26.205Z] 20:07:26     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info/<:115
[task 2023-06-13T20:07:26.205Z] 20:07:26     INFO - resource://testing-common/BrowserTestUtils.sys.mjs:withNewTab:149
[task 2023-06-13T20:07:26.205Z] 20:07:26     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info:55
[task 2023-06-13T20:07:26.205Z] 20:07:26     INFO - chrome://mochikit/content/browser-test.js:handleTask:1131
[task 2023-06-13T20:07:26.205Z] 20:07:26     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1203
[task 2023-06-13T20:07:26.206Z] 20:07:26     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1345
[task 2023-06-13T20:07:26.206Z] 20:07:26     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1120
[task 2023-06-13T20:07:26.206Z] 20:07:26     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1056
[task 2023-06-13T20:07:26.206Z] 20:07:26     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-06-13T20:07:26.214Z] 20:07:26     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time in the threads - 0 > 0 - {"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"checkProcessCpuTime","sourceId":586,"lineNumber":26,"columnNumber":10,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"test_proc_info/<","sourceId":586,"lineNumber":115,"columnNumber":30,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"resource://testing-common/BrowserTestUtils.sys.mjs","name":"withNewTab","sourceId":570,"lineNumber":149,"columnNumber":22,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"test_proc_info","sourceId":586,"lineNumber":55,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":540,"lineNumber":1131,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":540,"lineNumber":1203,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":540,"lineNumber":1345,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":540,"lineNumber":1120,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":564,"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":"async*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:55:26\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":{}},"caller":null,"formattedStack":"async*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:149:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:55:26\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":{}},"caller":null,"formattedStack":"test_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:115:30\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:149:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:55:26\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":{}},"formattedStack":"checkProcessCpuTime@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:26:10\ntest_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:115:30\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:149:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:55:26\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-13T20:07:26.214Z] 20:07:26     INFO - Stack trace:
[task 2023-06-13T20:07:26.214Z] 20:07:26     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:checkProcessCpuTime:26
[task 2023-06-13T20:07:26.214Z] 20:07:26     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info/<:115
[task 2023-06-13T20:07:26.214Z] 20:07:26     INFO - resource://testing-common/BrowserTestUtils.sys.mjs:withNewTab:149
[task 2023-06-13T20:07:26.214Z] 20:07:26     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info:55
[task 2023-06-13T20:07:26.214Z] 20:07:26     INFO - chrome://mochikit/content/browser-test.js:handleTask:1131
[task 2023-06-13T20:07:26.214Z] 20:07:26     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1203
[task 2023-06-13T20:07:26.214Z] 20:07:26     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1345
[task 2023-06-13T20:07:26.214Z] 20:07:26     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1120
[task 2023-06-13T20:07:26.214Z] 20:07:26     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1056
[task 2023-06-13T20:07:26.215Z] 20:07:26     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | The total CPU time of the process should be at least the sum of the CPU time spent by the still alive threads - 0 >= 0 -

Hello Andrew! Any chance you could help us assign this to someone?

Thank you!

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

According to the moz.build files' component mapping as exposed by searchfox at https://searchfox.org/mozilla-central/source/toolkit/components/processtools/tests/browser/browser_test_procinfo.js this test is owned by "Toolkit :: Performance Monitoring". Moving to that component and clearing priority and severity so it can be considered for triage.

Severity: S4 → --
Component: DOM: Content Processes → Performance Monitoring
Flags: needinfo?(bugmail)
Priority: P5 → --
Product: Core → Toolkit
Flags: needinfo?(dothayer)
Assignee: nobody → csabou
Assignee: csabou → nobody
Keywords: leave-open

(In reply to Alexandre LISSY :gerard-majax from comment #41)

As we discussed with Florian, it might be helpful to augment the test case and make sure we get a view of the Utility actors [https://searchfox.org/mozilla-central/rev/9e3413f54ed6c9165b5659558091d766d34a731f/toolkit/components/aboutprocesses/content/aboutProcesses.js#269] on the process reporting 0 time. This way we might be able to know if it's a in-birth or death process or what.

Before disabling the test, can someone explore this?

woo, tons of failure on my w11 debug build ...

Attachment #9340650 - Attachment description: Bug 1778932 - Disable browser_test_procinfo.js on windows for frequent failures. r=#intermittent-reviewers,aryx → Bug 1778932 - Disable browser_test_procinfo.js on windows !debug for frequent failures. r=#intermittent-reviewers,aryx
Pushed by csabou@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/ec9819462d39 Disable browser_test_procinfo.js on windows !debug for frequent failures. r=aryx
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]

The root cause here and in bug 1819845 is the same: on virtual machines, we can't reliably get CPU use data at a resolution better than 1/64Hz (ie. in 15.625ms increments). See the code at https://searchfox.org/mozilla-central/rev/d31e56f7b3c2c18b8071a7b2a2fb6b4e01e3d3e8/toolkit/components/processtools/ProcInfo_win.cpp#36-39

My guess is that the Windows 11 VMs we use are faster than our Windows 10 VMs, and it became more common for a preallocated, utility or socket process to use less than 15.6ms of CPU time to start.

In terms of what to do to fix the bug, I tried forcing the use of the high precision method even on VM is xpc::IsInAutomation() https://hg.mozilla.org/try/rev/ab1efbf18d2d65f6b4081a29ca2f7c2f3ec2466e. That fixed browser_test_procinfo.js, but made browser_test_powerMetrics.js (ie bug 1819845) perma fail. It looks like xpc::IsInAutomation() always returns false in child processes, causing my patch to produce inconsistent CPU time values between the parent and child processes.

Flags: needinfo?(florian)
See Also: → 1819845
See Also: → 1775932
Severity: -- → S4
Priority: -- → P3

Update

There have been 40 total failures within the last 7 days:

  • 5 failures on Linux 18.04 x64 WebRender asan opt
  • 1 failure on Linux 18.04 x64 WebRender debug
  • 4 failures on Windows 11 x86 22H2 WebRender debug
  • 30 failures on Windows 11 x64 22H2 WebRender debug

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

[task 2023-11-10T02:13:41.781Z] 02:13:41     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child proc type should be known - "utility" != "unknown" - 
[task 2023-11-10T02:13:41.781Z] 02:13:41     INFO - Buffered messages finished
[task 2023-11-10T02:13:41.789Z] 02:13:41     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time - 0 > 0 - {"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"checkProcessCpuTime","sourceId":610,"lineNumber":17,"columnNumber":10,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"test_proc_info/<","sourceId":610,"lineNumber":109,"columnNumber":30,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"resource://testing-common/BrowserTestUtils.sys.mjs","name":"withNewTab","sourceId":594,"lineNumber":146,"columnNumber":22,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"test_proc_info","sourceId":610,"lineNumber":52,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":562,"lineNumber":1134,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":562,"lineNumber":1206,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":562,"lineNumber":1348,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":562,"lineNumber":1123,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":588,"lineNumber":1058,"columnNumber":13,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"nextTest/<@chrome://mochikit/content/browser-test.js:1123:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"Tester_execTest@chrome://mochikit/content/browser-test.js:1348:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1123:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1206:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1348:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1123:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"async*handleTask@chrome://mochikit/content/browser-test.js:1134:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1206:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1348:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1123:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"async*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:52:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1134:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1206:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1348:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1123:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"async*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:146:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:52:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1134:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1206:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1348:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1123:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"test_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:109:30\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:146:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:52:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1134:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1206:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1348:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1123:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"checkProcessCpuTime@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:17:10\ntest_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:109:30\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:146:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:52:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1134:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1206:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1348:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1123:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}}
[task 2023-11-10T02:13:41.790Z] 02:13:41     INFO - Stack trace:
[task 2023-11-10T02:13:41.790Z] 02:13:41     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:checkProcessCpuTime:17
[task 2023-11-10T02:13:41.790Z] 02:13:41     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info/<:109
[task 2023-11-10T02:13:41.790Z] 02:13:41     INFO - resource://testing-common/BrowserTestUtils.sys.mjs:withNewTab:146
[task 2023-11-10T02:13:41.790Z] 02:13:41     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info:52
[task 2023-11-10T02:13:41.790Z] 02:13:41     INFO - chrome://mochikit/content/browser-test.js:handleTask:1134
[task 2023-11-10T02:13:41.790Z] 02:13:41     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1206
[task 2023-11-10T02:13:41.790Z] 02:13:41     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1348
[task 2023-11-10T02:13:41.790Z] 02:13:41     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1123
[task 2023-11-10T02:13:41.790Z] 02:13:41     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1058
[task 2023-11-10T02:13:41.791Z] 02:13:41     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-11-10T02:13:41.799Z] 02:13:41     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time in the threads - 0 > 0 - {"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"checkProcessCpuTime","sourceId":610,"lineNumber":23,"columnNumber":10,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"test_proc_info/<","sourceId":610,"lineNumber":109,"columnNumber":30,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"resource://testing-common/BrowserTestUtils.sys.mjs","name":"withNewTab","sourceId":594,"lineNumber":146,"columnNumber":22,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"test_proc_info","sourceId":610,"lineNumber":52,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":562,"lineNumber":1134,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":562,"lineNumber":1206,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":562,"lineNumber":1348,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":562,"lineNumber":1123,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":588,"lineNumber":1058,"columnNumber":13,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"nextTest/<@chrome://mochikit/content/browser-test.js:1123:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"Tester_execTest@chrome://mochikit/content/browser-test.js:1348:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1123:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1206:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1348:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1123:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"async*handleTask@chrome://mochikit/content/browser-test.js:1134:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1206:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1348:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1123:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"async*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:52:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1134:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1206:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1348:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1123:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"async*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:146:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:52:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1134:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1206:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1348:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1123:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"test_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:109:30\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:146:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:52:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1134:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1206:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1348:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1123:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"checkProcessCpuTime@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:23:10\ntest_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:109:30\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:146:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:52:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1134:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1206:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1348:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1123:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}}
[task 2023-11-10T02:13:41.799Z] 02:13:41     INFO - Stack trace:
[task 2023-11-10T02:13:41.799Z] 02:13:41     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:checkProcessCpuTime:23
[task 2023-11-10T02:13:41.799Z] 02:13:41     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info/<:109
[task 2023-11-10T02:13:41.799Z] 02:13:41     INFO - resource://testing-common/BrowserTestUtils.sys.mjs:withNewTab:146
[task 2023-11-10T02:13:41.799Z] 02:13:41     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info:52
[task 2023-11-10T02:13:41.800Z] 02:13:41     INFO - chrome://mochikit/content/browser-test.js:handleTask:1134
[task 2023-11-10T02:13:41.800Z] 02:13:41     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1206
[task 2023-11-10T02:13:41.800Z] 02:13:41     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1348
[task 2023-11-10T02:13:41.800Z] 02:13:41     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1123
[task 2023-11-10T02:13:41.800Z] 02:13:41     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1058
[task 2023-11-10T02:13:41.800Z] 02:13:41     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | The total CPU time of the process should be at least the sum of the CPU time spent by the still alive threads - 0 >= 0 -

Florian, is this something you're still looking into?
Thank you.

Flags: needinfo?(dothayer) → needinfo?(florian)
Whiteboard: [stockwell disabled] → [stockwell disabled][stockwell needswork:owner]
Flags: needinfo?(yjuglaret)
Flags: needinfo?(florian)

Update

There have been 38 total failures within the last 7 days:

  • 3 failures on Windows 11 x86 22H2 WebRender debug
  • 35 failures on Windows 11 x64 22H2 WebRender debug

Recent log: https://treeherder.mozilla.org/logviewer?job_id=446789986&repo=mozilla-central&lineNumber=121457

[task 2024-02-10T11:15:45.124Z] 11:15:45     INFO - TEST-PASS | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Child proc type should be known - "utility" != "unknown" - 
[task 2024-02-10T11:15:45.124Z] 11:15:45     INFO - Buffered messages finished
[task 2024-02-10T11:15:45.133Z] 11:15:45     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/processtools/tests/browser/browser_test_procinfo.js | Got some cpu time - 0 > 0 - {"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"checkProcessCpuTime","sourceId":616,"lineNumber":17,"columnNumber":10,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"test_proc_info/<","sourceId":616,"lineNumber":109,"columnNumber":30,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"resource://testing-common/BrowserTestUtils.sys.mjs","name":"withNewTab","sourceId":600,"lineNumber":146,"columnNumber":22,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js","name":"test_proc_info","sourceId":616,"lineNumber":52,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":568,"lineNumber":1139,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":568,"lineNumber":1211,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":568,"lineNumber":1353,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":568,"lineNumber":1128,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":594,"lineNumber":1058,"columnNumber":13,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"nextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"Tester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"async*handleTask@chrome://mochikit/content/browser-test.js:1139:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"async*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:52:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1139:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"async*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:146:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:52:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1139:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"test_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:109:30\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:146:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:52:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1139:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"checkProcessCpuTime@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:17:10\ntest_proc_info/<@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:109:30\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:146:22\nasync*test_proc_info@chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:52:26\nasync*handleTask@chrome://mochikit/content/browser-test.js:1139:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nTester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}}
[task 2024-02-10T11:15:45.133Z] 11:15:45     INFO - Stack trace:
[task 2024-02-10T11:15:45.133Z] 11:15:45     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:checkProcessCpuTime:17
[task 2024-02-10T11:15:45.133Z] 11:15:45     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info/<:109
[task 2024-02-10T11:15:45.134Z] 11:15:45     INFO - resource://testing-common/BrowserTestUtils.sys.mjs:withNewTab:146
[task 2024-02-10T11:15:45.134Z] 11:15:45     INFO - chrome://mochitests/content/browser/toolkit/components/processtools/tests/browser/browser_test_procinfo.js:test_proc_info:52
[task 2024-02-10T11:15:45.134Z] 11:15:45     INFO - chrome://mochikit/content/browser-test.js:handleTask:1139
[task 2024-02-10T11:15:45.134Z] 11:15:45     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1211
[task 2024-02-10T11:15:45.134Z] 11:15:45     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1353
[task 2024-02-10T11:15:45.134Z] 11:15:45     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1128
[task 2024-02-10T11:15:45.134Z] 11:15:45     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1058
[task 2024-02-10T11:15:45.134Z] 11:15:45     INFO - Not taking screenshot here: see the one that was previously logged

Florian, can you please help us out with this bug?
Thank you.

Flags: needinfo?(florian)
Whiteboard: [stockwell disabled][stockwell unknown] → [stockwell disabled][stockwell needswork:owner]
Depends on: 1880373

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

Flags: needinfo?(florian)
Whiteboard: [stockwell disabled][stockwell needswork:owner]
Keywords: leave-open

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

  • 34 failures on linux1804-64-qr opt and debug
  • 68 failures on linux1804-64-shippable-qr opt
  • 1 failure on linux1804-64-tsan-qr opt

Recent failure log.

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

Flags: needinfo?(gijskruitbosch+bugs)
Whiteboard: [stockwell needswork:owner]

(In reply to Cristina Horotan [:chorotan] from comment #126)

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

  • 34 failures on linux1804-64-qr opt and debug
  • 68 failures on linux1804-64-shippable-qr opt
  • 1 failure on linux1804-64-tsan-qr opt

Recent failure log.

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

given the timeline on orange factor, there's a good chance this is also triggered by forkserver enabling

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

(In reply to Cristina Horotan [:chorotan] from comment #126)

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

  • 34 failures on linux1804-64-qr opt and debug
  • 68 failures on linux1804-64-shippable-qr opt
  • 1 failure on linux1804-64-tsan-qr opt

Recent failure log.

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

given the timeline on orange factor, there's a good chance this is also triggered by forkserver enabling

Thanks for the hint - I know nothing about fork server (nor am I particularly familiar with this automated test), can someone else take ownership of diagnosing what is going on here? It looks like we're checking for CPU time in all the child processes and the utility process has 0 cpu time or something.

Flags: needinfo?(lissyx+mozillians)
Flags: needinfo?(gpascutto)
Flags: needinfo?(gijskruitbosch+bugs)
Keywords: regression
Regressed by: 1874689

i've been having a look since yesterday already with florian

Flags: needinfo?(lissyx+mozillians)
Flags: needinfo?(gpascutto)
Assignee: nobody → lissyx+mozillians

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

we could capture in pernosco: https://pernos.co/debug/yqIsPg4FbYOEe8KVApt2eg/index.html#f{m[VWg,Als_,t[iQ,BxE_,f{e[VN8,Avo_,s{afxiBxpAA,bARs,u1V1A,o1wUW___/ but i lack infos on the process that is breaking so I'm waiting on https://treeherder.mozilla.org/jobs?repo=try&revision=c3efe083624d13dc76b71b90a71b07d17ca32bec

ok it took me a bit but it's PID 2074 we are interested in that trace, and indeed all threads are at 0 even the main thread. It seems to be a process that was spawn late regarding the test, i'm trying to verify whether it's a false positive or if maybe the process was blocked. At least at the time of reading the cpu time values, all the threads are blocked on some epoll/wait/sched_yield (the main one especially, trying to load libjitPI.so)

Readings:

  • /proc/2074/task/2074/stat: 2074 (Web Content) t 1714 1620 1 0 -1 1077936448 458 0 0 0 0 0 0 0 20 0 3 0 250224 2631233536 26103 18446744073709551615 94303992295424 94303993139152 140722378272496 0 0 0 0 4102 3832 0 0 0 17 44 0 0 0 0 0 94303993153648 94303993153768 94303998791680 140722378279114 140722378279463 140722378279463 140722378284985 133
  • /proc/2074/task/2078/stat: 2078 (AsyncSi~lThread) S 1714 1620 1 0 -1 4194368 9 0 0 0 0 0 0 0 20 0 3 0 250230 2631233536 26103 18446744073709551615 94303992295424 94303993139152 140722378272496 0 0 0 0 4102 3832 0 0 0 -1 44 0 0 0 0 0 94303993153648 94303993153768 94303998791680 140722378279114 140722378279463 140722378279463 140722378284985 0
  • /proc/2074/task/2079/stat: 2079 (IPC I/O Child) t 1714 1620 1 0 -1 1077936192 30 0 0 0 0 0 0 0 20 0 3 0 250230 2631233536 26103 18446744073709551615 94303992295424 94303993139152 140722378272496 0 0 0 0 4102 3832 0 0 0 -1 44 0 0 0 0 0 94303993153648 94303993153768 94303998791680 140722378279114 140722378279463 140722378279463 140722378284985 133

States according to proc_pid_stat(5) are S Sleeping in an interruptible wait and t Tracing stop (Linux 2.6.33 onward). Field 13 and 14 are reporting 0, consistent with the data reported to the test. The process' clock_gettime() succeeded and returned {tv_sec=0, tv_nsec=14120638}

According to that pernosco trace, i have no proof that the PID 2074 is deadlocked in a way ; two threads will show that the blocked state they are in is going to move into running state later. It seems like the test took a picture of the process at an unlucky time and we may just adjust the test to verify we have cpu time on those threads when they got a chance to be scheduled

No longer regressed by: 1874689
Depends on: 1913434

All the recent failures are on Linux, and will be addressed by bug 1921749.

See Also: → 1921749
Assignee: lissyx+mozillians → nobody
Whiteboard: [stockwell disable-recommended]

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

Status: REOPENED → RESOLVED
Closed: 3 years ago → 6 months ago
status-firefox131: affected → wontfix
Resolution: --- → INCOMPLETE

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

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

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

Status: REOPENED → RESOLVED
Closed: 6 months ago → 3 months ago
Resolution: --- → INCOMPLETE

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

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: