Open Bug 1872332 Opened 1 year ago Updated 7 days ago

Intermittent browser/base/content/test/performance/browser_windowopen.js | single tracking bug

Categories

(Toolkit :: Performance Monitoring, defect, P5)

Product:
Toolkit
Component:
Performance Monitoring
Type:
defect

Tracking

()

Tracking Flags:
Tracking Status
firefox-esr115 --- unaffected
firefox121 --- unaffected
firefox122 --- unaffected
firefox123 --- affected
firefox124 --- affected

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, intermittent-testcase, regression, Whiteboard: [retriggered])

Attachments

(1 obsolete file)

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

[task 2023-12-29T06:21:08.604Z] 06:21:08     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_windowopen.js | unexpected 2 changed rects: ({x1:0, x2:1279, y1:0, y2:43, w:1280, h:44}), window width: 1280, ({x1:1168, x2:1199, y1:48, y2:79, w:32, h:32}), window width: 1280 - 
[task 2023-12-29T06:21:08.604Z] 06:21:08     INFO - Stack trace:
[task 2023-12-29T06:21:08.604Z] 06:21:08     INFO - chrome://mochikit/content/browser-test.js:test_ok:1591
[task 2023-12-29T06:21:08.604Z] 06:21:08     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/head.js:reportUnexpectedFlicker:659
[task 2023-12-29T06:21:08.604Z] 06:21:08     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/head.js:withPerfObserver:718
[task 2023-12-29T06:21:08.605Z] 06:21:08     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_windowopen.js:null:115
[task 2023-12-29T06:21:08.605Z] 06:21:08     INFO - chrome://mochikit/content/browser-test.js:handleTask:1138
[task 2023-12-29T06:21:08.605Z] 06:21:08     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1210
[task 2023-12-29T06:21:08.605Z] 06:21:08     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1352
[task 2023-12-29T06:21:08.605Z] 06:21:08     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1127
[task 2023-12-29T06:21:08.605Z] 06:21:08     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1058

Hi Emilio! Can you please take a look at this? It seems that after Bug 1792098 landed, the failure line changed to TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_windowopen.js | unexpected 2 changed rects: ({x1:0, x2:1279, y1:0, y2:43, w:1280, h:44}), window width: 1280, ({x1:1168, x2:1199, y1:48, y2:79, w:32, h:32}), window width: 1280 - but this is no longer that frequent.

backfill range and retriggers

Thank you!

Flags: needinfo?(emilio)
Keywords: regression
Regressed by: 1792098
Whiteboard: [retriggered]

Set release status flags based on info from the regressing bug 1792098

status-firefox121: --- → unaffected
status-firefox122: --- → unaffected
status-firefox123: --- → affected
status-firefox-esr115: --- → unaffected

Yeah that failure seems like the one originally tracked in bug 1792098, in particular the pocket icon seems hovered, which is unexpected, see bug 1792098 comment 39.

Flags: needinfo?(emilio)

Set release status flags based on info from the regressing bug 1792098

status-firefox124: --- → affected

This is frequently failing on mozilla-beta on macosx1015-64 (especially shippable and devedition) with 173 total failures in the last 30 days: https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2024-01-11&endday=2024-02-10&tree=firefox-releases&failurehash=all&bug=1872332
Emilio, is this something you could look at?
Latest failure log: https://treeherder.mozilla.org/logviewer?job_id=446791946&repo=mozilla-beta&lineNumber=3766

[task 2024-02-10T11:17:30.774Z] 11:17:30     INFO - TEST-START | browser/base/content/test/performance/browser_windowopen.js
[task 2024-02-10T11:17:31.052Z] 11:17:31     INFO - GECKO(2950) | 1707563851052	Marionette	TRACE	Received observer notification browser-delayed-startup-finished
[task 2024-02-10T11:17:31.053Z] 11:17:31     INFO - GECKO(2950) | Waiting for browser load of about:home
[task 2024-02-10T11:17:31.053Z] 11:17:31     INFO - GECKO(2950) | Waiting for browser state change of about:home
[task 2024-02-10T11:17:31.058Z] 11:17:31     INFO - GECKO(2950) | Saw state f0001 and status 0
[task 2024-02-10T11:23:41.147Z] 11:23:41     INFO - Buffered messages logged at 11:17:30
[task 2024-02-10T11:23:41.148Z] 11:23:41     INFO - Entering test bound 
[task 2024-02-10T11:23:41.148Z] 11:23:41     INFO - Note: ensureDirtyRootFrame threw an exception:[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIDOMWindowUtils.ensureDirtyRootFrame]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/head.js :: dirtyFrame :: line 21"  data: no]
[task 2024-02-10T11:23:41.148Z] 11:23:41     INFO - Note: ensureDirtyRootFrame threw an exception:[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIDOMWindowUtils.ensureDirtyRootFrame]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/head.js :: dirtyFrame :: line 21"  data: no]
[task 2024-02-10T11:23:41.149Z] 11:23:41     INFO - Note: ensureDirtyRootFrame threw an exception:[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIDOMWindowUtils.ensureDirtyRootFrame]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/head.js :: dirtyFrame :: line 21"  data: no]
[task 2024-02-10T11:23:41.150Z] 11:23:41     INFO - Note: ensureDirtyRootFrame threw an exception:[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIDOMWindowUtils.ensureDirtyRootFrame]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/head.js :: dirtyFrame :: line 21"  data: no]
[task 2024-02-10T11:23:41.151Z] 11:23:41     INFO - Note: ensureDirtyRootFrame threw an exception:[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIDOMWindowUtils.ensureDirtyRootFrame]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/head.js :: dirtyFrame :: line 21"  data: no]
[task 2024-02-10T11:23:41.151Z] 11:23:41     INFO - Note: ensureDirtyRootFrame threw an exception:[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIDOMWindowUtils.ensureDirtyRootFrame]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/head.js :: dirtyFrame :: line 21"  data: no]
[task 2024-02-10T11:23:41.152Z] 11:23:41     INFO - Note: ensureDirtyRootFrame threw an exception:[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIDOMWindowUtils.ensureDirtyRootFrame]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/head.js :: dirtyFrame :: line 21"  data: no]
[task 2024-02-10T11:23:41.153Z] 11:23:41     INFO - Note: ensureDirtyRootFrame threw an exception:[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIDOMWindowUtils.ensureDirtyRootFrame]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/head.js :: dirtyFrame :: line 21"  data: no]
[task 2024-02-10T11:23:41.153Z] 11:23:41     INFO - Note: ensureDirtyRootFrame threw an exception:[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIDOMWindowUtils.ensureDirtyRootFrame]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/head.js :: dirtyFrame :: line 21"  data: no]
[task 2024-02-10T11:23:41.155Z] 11:23:41     INFO - Buffered messages finished
[task 2024-02-10T11:23:41.156Z] 11:23:41     INFO - TEST-UNEXPECTED-TIMEOUT | browser/base/content/test/performance/browser_windowopen.js | application timed out after 370 seconds with no output
[task 2024-02-10T11:23:41.156Z] 11:23:41     INFO - TEST-INFO took 370227ms
[task 2024-02-10T11:23:41.156Z] 11:23:41     INFO - Buffered messages finished
[task 2024-02-10T11:23:41.157Z] 11:23:41  WARNING - Force-terminating active process(es).
[task 2024-02-10T11:23:41.157Z] 11:23:41     INFO - Determining child pids from psutil...
[task 2024-02-10T11:23:41.158Z] 11:23:41     INFO - [2951, 2952, 2953, 2956, 2962, 2970, 2971, 2972, 2973, 2974, 2975, 2976, 2977, 2978]
[task 2024-02-10T11:23:41.158Z] 11:23:41     INFO - ==> process 2950 launched child process 2951
[task 2024-02-10T11:23:41.158Z] 11:23:41     INFO - ==> process 2950 launched child process 2952
[task 2024-02-10T11:23:41.159Z] 11:23:41     INFO - ==> process 2950 launched child process 2953
[task 2024-02-10T11:23:41.159Z] 11:23:41     INFO - ==> process 2950 launched child process 2954
[task 2024-02-10T11:23:41.160Z] 11:23:41     INFO - ==> process 2950 launched child process 2955
[task 2024-02-10T11:23:41.160Z] 11:23:41     INFO - ==> process 2950 launched child process 2956
[task 2024-02-10T11:23:41.160Z] 11:23:41     INFO - ==> process 2950 launched child process 2961
[task 2024-02-10T11:23:41.161Z] 11:23:41     INFO - ==> process 2950 launched child process 2962
[task 2024-02-10T11:23:41.161Z] 11:23:41     INFO - ==> process 2950 launched child process 2969
[task 2024-02-10T11:23:41.161Z] 11:23:41     INFO - ==> process 2950 launched child process 2970
[task 2024-02-10T11:23:41.162Z] 11:23:41     INFO - ==> process 2950 launched child process 2971
[task 2024-02-10T11:23:41.162Z] 11:23:41     INFO - ==> process 2950 launched child process 2972
[task 2024-02-10T11:23:41.163Z] 11:23:41     INFO - ==> process 2950 launched child process 2973
[task 2024-02-10T11:23:41.163Z] 11:23:41     INFO - ==> process 2950 launched child process 2974
[task 2024-02-10T11:23:41.163Z] 11:23:41     INFO - ==> process 2950 launched child process 2975
[task 2024-02-10T11:23:41.164Z] 11:23:41     INFO - ==> process 2950 launched child process 2976
[task 2024-02-10T11:23:41.164Z] 11:23:41     INFO - ==> process 2950 launched child process 2977
[task 2024-02-10T11:23:41.164Z] 11:23:41     INFO - ==> process 2950 launched child process 2978
[task 2024-02-10T11:23:41.165Z] 11:23:41     INFO - Found child pids: {2976, 2977, 2978, 2951, 2952, 2953, 2954, 2955, 2956, 2961, 2962, 2969, 2970, 2971, 2972, 2973, 2974, 2975}
[task 2024-02-10T11:23:41.165Z] 11:23:41     INFO - Failed to get child procs
[task 2024-02-10T11:23:41.166Z] 11:23:41     INFO - Killing process: 2976
[task 2024-02-10T11:23:41.166Z] 11:23:41     INFO - TEST-INFO | started process screencapture
[task 2024-02-10T11:23:41.342Z] 11:23:41     INFO - TEST-INFO | screencapture: exit 0
Flags: needinfo?(emilio)

I don't know why this test would time out so frequently only on beta and only on macOS. The screenshot shows a blank window.

Florian, do you know what might be going on? This looks like graphics maybe getting stuck or something? But without stacks is hard to figure out. Do you know how we could get stacks / minidumps of the processes that are timing out?

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

(In reply to Emilio Cobos Álvarez (:emilio) from comment #17)

I don't know why this test would time out so frequently only on beta and only on macOS. The screenshot shows a blank window.

Florian, do you know what might be going on?

I don't know what's going on. The profile of the test job shows the memory use was rather high during that test: https://share.firefox.dev/498uDe3
This probably means that we are capturing many screenshots for flicker detection... but it could just be that the cursor is blinking forever in the address bar.

This looks like graphics maybe getting stuck or something? But without stacks is hard to figure out. Do you know how we could get stacks / minidumps of the processes that are timing out?

Not completely sure what you mean, as the test log does contain a stack of the parent process: https://treeherder.mozilla.org/logviewer?job_id=446865325&repo=mozilla-beta&lineNumber=3895

If this is failing often enough to be easy to reproduce, we could try to start the Gecko Profiler before the test, and make the test capture and upload the profile after 300s (ie. before the test harness makes the test timeout).

Flags: needinfo?(florian)

The test log contains this warning:
Note: ensureDirtyRootFrame threw an exception:[Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIDOMWindowUtils.ensureDirtyRootFrame]" nsresult: "0x80004005 (NS_ERROR_FAILURE)" location: "JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/head.js :: dirtyFrame :: line 21" data: no]

Is it noise, or does it indicate something interesting?

Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered]
Attachment #9387244 - Attachment is obsolete: true

Most of the failures fixed by Bug 1945167, removing [disable-recommended] for now

Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: