Closed Bug 1775836 Opened 3 years ago Closed 1 year ago

Intermittent dom/ipc/tests/browser_ProcessPriorityManager.js | single tracking bug

Categories

(Core :: DOM: Content Processes, defect, P3)

defect

Tracking

()

RESOLVED FIXED
121 Branch
Tracking Status
firefox121 --- fixed

People

(Reporter: jmaher, Unassigned)

References

Details

(Keywords: intermittent-failure, intermittent-testcase, Whiteboard: [stockwell disable-recommended])

Attachments

(1 obsolete file)

No description provided.

Additional information about this bug failures and frequency patterns can be found by running: ./mach test-info failure-report --bug 1775836

Severity: -- → S3
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago1 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 1 years ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Update

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

  • 18 failures on Linux 18.04 x64 WebRender opt/debug
  • 15 failures on Linux 18.04 x64 WebRender Shippable opt/debug
  • 1 failure on Windows 11 x86 22H2 WebRender Shippable opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=430889155&repo=autoland&lineNumber=15932

[task 2023-09-30T18:23:12.946Z] 18:23:12     INFO - TEST-PASS | dom/ipc/tests/browser_ProcessPriorityManager.js | Process with child ID 2 reached expected priority: FOREGROUND - true == true - 
[task 2023-09-30T18:23:12.946Z] 18:23:12     INFO - Buffered messages finished
[task 2023-09-30T18:23:12.946Z] 18:23:12     INFO - TEST-UNEXPECTED-FAIL | dom/ipc/tests/browser_ProcessPriorityManager.js | Should have seen no process priority change for child ID 14 - "FOREGROUND" == null - {"filename":"chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js","name":"ensureNoPriorityChange","sourceId":630,"lineNumber":113,"columnNumber":12,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js","name":"waitForBrowserTreePriority","sourceId":630,"lineNumber":148,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js","name":"assertPriorityChangeOnBackground","sourceId":630,"lineNumber":274,"columnNumber":41,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js","name":"test_video_background_tab/<","sourceId":630,"lineNumber":694,"columnNumber":11,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"resource://testing-common/BrowserTestUtils.sys.mjs","name":"withNewTab","sourceId":582,"lineNumber":146,"columnNumber":22,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js","name":"test_video_background_tab","sourceId":630,"lineNumber":655,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":549,"lineNumber":1131,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":549,"lineNumber":1203,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":549,"lineNumber":1345,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":549,"lineNumber":1120,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":576,"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:1120:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"async*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:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nasync*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:1058:13\n","nativeSavedFrame":{}},"formattedStack":"handleTask@chrome://mochikit/content/browser-test.js:1131:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nasync*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:1058:13\n","nativeSavedFrame":{}},"formattedStack":"async*test_video_background_tab@chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:655:26\nhandleTask@chrome://mochikit/content/browser-test.js:1131:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nasync*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:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"async*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:146:22\nasync*test_video_background_tab@chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:655:26\nhandleTask@chrome://mochikit/content/browser-test.js:1131:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nasync*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:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"test_video_background_tab/<@chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:694:11\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:146:22\nasync*test_video_background_tab@chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:655:26\nhandleTask@chrome://mochikit/content/browser-test.js:1131:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nasync*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:1058:13\n","nativeSavedFrame":{}},"formattedStack":"assertPriorityChangeOnBackground@chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:274:41\ntest_video_background_tab/<@chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:694:11\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:146:22\nasync*test_video_background_tab@chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:655:26\nhandleTask@chrome://mochikit/content/browser-test.js:1131:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nasync*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:1058:13\n","nativeSavedFrame":{}},"formattedStack":"async*waitForBrowserTreePriority@chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:148:18\nassertPriorityChangeOnBackground@chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:274:41\ntest_video_background_tab/<@chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:694:11\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:146:22\nasync*test_video_background_tab@chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:655:26\nhandleTask@chrome://mochikit/content/browser-test.js:1131:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nasync*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:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"ensureNoPriorityChange@chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:113:12\nasync*waitForBrowserTreePriority@chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:148:18\nassertPriorityChangeOnBackground@chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:274:41\ntest_video_background_tab/<@chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:694:11\nasync*withNewTab@resource://testing-common/BrowserTestUtils.sys.mjs:146:22\nasync*test_video_background_tab@chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:655:26\nhandleTask@chrome://mochikit/content/browser-test.js:1131:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1203:18\nasync*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:1058:13\n","nativeSavedFrame":{}}
[task 2023-09-30T18:23:12.946Z] 18:23:12     INFO - Stack trace:
[task 2023-09-30T18:23:12.946Z] 18:23:12     INFO - chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:ensureNoPriorityChange:113
[task 2023-09-30T18:23:12.947Z] 18:23:12     INFO - chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:waitForBrowserTreePriority:148
[task 2023-09-30T18:23:12.947Z] 18:23:12     INFO - chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:assertPriorityChangeOnBackground:274
[task 2023-09-30T18:23:12.947Z] 18:23:12     INFO - chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:test_video_background_tab/<:694
[task 2023-09-30T18:23:12.947Z] 18:23:12     INFO - resource://testing-common/BrowserTestUtils.sys.mjs:withNewTab:146
[task 2023-09-30T18:23:12.947Z] 18:23:12     INFO - chrome://mochitests/content/browser/dom/ipc/tests/browser_ProcessPriorityManager.js:test_video_background_tab:655
[task 2023-09-30T18:23:12.947Z] 18:23:12     INFO - chrome://mochikit/content/browser-test.js:handleTask:1131
[task 2023-09-30T18:23:12.947Z] 18:23:12     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1203
[task 2023-09-30T18:23:12.947Z] 18:23:12     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1345
[task 2023-09-30T18:23:12.947Z] 18:23:12     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1120
[task 2023-09-30T18:23:12.947Z] 18:23:12     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1058
[task 2023-09-30T18:23:12.948Z] 18:23:12     INFO - TEST-PASS | dom/ipc/tests/browser_ProcessPriorityManager.js | Tabs should be running in separate processes. - 2814 != 2432 -

Kagami, can you assign this to someone?
Thank you.

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

Hi Kris, it seems you are the person who touched dom/ipc/ProcessPriorityManager.cpp last time in bug 1834629, would you like to take a look here?

Flags: needinfo?(krosylight) → needinfo?(kwright)

It looks like it started failing frequently on Friday. Maybe the first step is to do some retriggers to narrow that down a bit. There's nothing obviously related that landed, looking back from the first failure. The closest was bug 1853244 which changed the .ini files to .toml though I don't know how that could cause an issue here.

I'll try to bisect this on treeherder a bit.

Flags: needinfo?(kwright)

Going back about 10 pushes before the first failure (see bc4), it looks like this test was being skipped.

TEST-START | dom/ipc/tests/browser_ProcessPriorityManager.js
TEST-SKIP | dom/ipc/tests/browser_ProcessPriorityManager.js | took 0ms

I think this strengthens my theory that this is related to bug 1853244, though I'll have to investigate more to see. However, I'm not sure why it was being skipped before. That doesn't make any sense to me.

This was the .ini entry (plus some support files):

[browser_ProcessPriorityManager.js]
skip-if = (os != "win") || (os != "linux") || (os != "mac")

I did some retriggers of bc tests around the landing of bug 1853244. There are a few odd issues here.

  1. Prior to the landing of that, it appears we were just never running browser_ProcessPriorityManager.js. Who knows when that happened. Looking back at the failures in this bug, the last time I see a failure besides esr102 was a failure on release in the 2022-09-04 summary. Before that, there was a failure on autoland on 2022-08-14. I assume Linux opt just has been failing for a long time and we never noticed because it never ran. In the short term, maybe the path forward here is to disable this test on Linux opt. We'll still get Linux testing in debug builds. This feature has a lot of OS-specific code paths, so we want to avoid disabling it entirely on any given OS.

  2. I triggered bc1 through bc7 on a bunch of pushes a bug 1853244 landed (for linux 64 opt bc spi-nw), as you can see here. On the pushes for bug 1853244, bug 1854456, and bug 1854551, browser_ProcessPriorityManager.js (and maybe the entire dom/ipc directory?) is never run. Then on the first push for bug 1171441, suddenly it is being run. Very bizarre. Joel, is it expected that your .toml change would cause this directory to just not get run like that? The bc test runs there are mostly (but not entirely)

Flags: needinfo?(jmaher)

previously this was in the browser.ini as:

[browser_ProcessPriorityManager.js]
skip-if = (os != "win") || (os != "linux") || (os != "mac")

now it is:

["browser_ProcessPriorityManager.js"]
skip-if = ["os == 'android'"]

prior to this we skipped this test on linux:
https://treeherder.mozilla.org/logviewer?job_id=430081428&repo=autoland

so the test was never ran, but the directory was scheduled.

I have seen this behavior before (earlier this year, before any .toml stuff) and have been puzzled by it. I see in the batch6 landing that only .ini manifests were scheduled. Our first 2 rounds we did verify logs of tests (on central) that things were running properly. Possibly there is a quirk with test identification/selection on autoland.

As for the topic of this bug, is it possible that this was not run anywhere before? The logic was sort of a mess.

Flags: needinfo?(jmaher)

Sheriffs: if the failure rate here is too high, I think it would make sense to disable it on Linux opt.

There have been around 38 failures within the last 7 days, and 79 failures within the last 30 days.
It has not yet reached our disable-recommended queue, but if it does, we will go on with disabling it on Linux opt.

Update:

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

  • 1 failure on linux1804-64-asan-qr opt
  • 28 failures on linux1804-64-qr opt and debug
  • 20 failures on linux1804-64-shippable-qr opt
  • 1 failure on windows11-32-2009-qr opt
  • 1 failure on windows11-64-2009-asan-qr opt

Recent failure log.

Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → FIXED

Bug was closed by mistake. Reopening.

Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Assignee: nobody → imoraru

This has reached the "disable-recommended" state. Made a patch to disable this test on Linux opt due to frequent failures and as per comment 49. Please remember to re-enable the test when making a fix for the failures.

Hi Andrew! Can you please take another look at this?
Thank you!

Flags: needinfo?(continuation)
Assignee: imoraru → nobody
Assignee: nobody → imoraru
Depends on: 1864446

It looks like the failure is happening in test_video_background_tab() at the assertPriorityChangeOnBackground with the comment "The tab with the unmuted video should stay at PROCESS_PRIORITY_FOREGROUND when backgrounded.". I looked at 15 logs, and they all had the exact same line numbers for all frames in the assertion stack.

The actual assertion is in ensureNoPriorityChange(), and it is complaining that the video tab is in noChangeChildIDs with priority FOREGROUND. This is interesting because (as the comment above suggests) the initial priority is also FOREGROUND. So, I think for some reason the priority is changing to something else, then changing back to FOREGROUND. It would be kind of cool to record a log of the priorities we saw and then give a better error message. I filed bug 1864446 for that.

I'm not familiar with the mechanism we use for ensuring prioritization of video playing audio. I'm guessing this is the mHoldsPlayingAudioWakeLock stuff. So I'll have to read some code.

I implemented the logging I suggested in bug 1864446. The priority history is BACKGROUND_PERCEIVABLE then FOREGROUND.

It looks like the problem is that when we unmute the video element in the content process, it sends an async message to the parent. If the priority manager gets that message after BrowserPriorityChanged gets called from the tab switch then that means the process priority temporarily gets set to BACKGROUND_PERCEIVABLE. I can reproduce the issue sometimes and with logging I think I confirmed that is what is actually happening.

The fix is to wait after the unmute for the parent process to get the wakelock message from the unmute before doing the tab switch.

Assignee: imoraru → nobody
Flags: needinfo?(continuation)
Assignee: nobody → imoraru
Depends on: 1864559
Assignee: imoraru → nobody

Comment on attachment 9363137 [details]
Bug 1775836 - disable browser_ProcessPriorityManager.js on Linux opt for frequent failures. r=#intermittent-reviewers,mccr8,janv

My test fix is queued up for landing.

Attachment #9363137 - Attachment is obsolete: true

It looks like the failures are fixed. I do see a verify failure that is a timeout. I'm not sure if that is related to my changes or not. I guess we can keep an eye on that.

Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → FIXED
Target Milestone: --- → 121 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: