Closed Bug 1782718 Opened 2 years ago Closed 2 years ago

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

Categories

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

defect

Tracking

()

RESOLVED FIXED
105 Branch
Tracking Status
firefox-esr91 --- unaffected
firefox-esr102 --- unaffected
firefox103 --- unaffected
firefox104 --- unaffected
firefox105 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: jstutte)

References

(Regression)

Details

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

Attachments

(2 files)

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


[task 2022-08-02T12:38:09.490Z] 12:38:09     INFO - TEST-START | dom/ipc/tests/browser_content_shutdown_with_endless_js.js
[task 2022-08-02T12:38:09.905Z] 12:38:09     INFO - GECKO(3969) | 2022-08-02 12:38:09.903 firefox[3969:61461] Persistent UI failed to open file file:///Users/cltbld/Library/Saved%20Application%20State/org.mozilla.nightly.savedState/window_1.data: No such file or directory (2)
[task 2022-08-02T12:38:54.614Z] 12:38:54     INFO - TEST-INFO | started process screencapture
[task 2022-08-02T12:38:54.731Z] 12:38:54     INFO - TEST-INFO | screencapture: exit 0
[task 2022-08-02T12:38:54.731Z] 12:38:54     INFO - Buffered messages logged at 12:38:09
[task 2022-08-02T12:38:54.731Z] 12:38:54     INFO - Entering test bound 
[task 2022-08-02T12:38:54.732Z] 12:38:54     INFO - Create and shutdown a content process for http://mochi.test:8888/browser/dom/ipc/tests/file_dummy.html
[task 2022-08-02T12:38:54.732Z] 12:38:54     INFO - Old process count: 7
[task 2022-08-02T12:38:54.732Z] 12:38:54     INFO - Buffered messages logged at 12:38:10
[task 2022-08-02T12:38:54.732Z] 12:38:54     INFO - New process count: 8
[task 2022-08-02T12:38:54.732Z] 12:38:54     INFO - TEST-PASS | dom/ipc/tests/browser_content_shutdown_with_endless_js.js | Process created. - 
[task 2022-08-02T12:38:54.732Z] 12:38:54     INFO - TEST-PASS | dom/ipc/tests/browser_content_shutdown_with_endless_js.js | removeTab - 
[task 2022-08-02T12:38:54.732Z] 12:38:54     INFO - New count: 7
[task 2022-08-02T12:38:54.733Z] 12:38:54     INFO - TEST-PASS | dom/ipc/tests/browser_content_shutdown_with_endless_js.js | Shutdown of content process complete. - 
[task 2022-08-02T12:38:54.733Z] 12:38:54     INFO - Create and shutdown a content process for http://mochi.test:8888/browser/dom/ipc/tests/file_endless_js.html
[task 2022-08-02T12:38:54.733Z] 12:38:54     INFO - Old process count: 7
[task 2022-08-02T12:38:54.733Z] 12:38:54     INFO - Buffered messages finished
[task 2022-08-02T12:38:54.733Z] 12:38:54     INFO - TEST-UNEXPECTED-FAIL | dom/ipc/tests/browser_content_shutdown_with_endless_js.js | Test timed out - 
[task 2022-08-02T12:39:01.779Z] 12:39:01     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-02T12:39:01.779Z] 12:39:01     INFO - TEST-UNEXPECTED-FAIL | dom/ipc/tests/browser_content_shutdown_with_endless_js.js | waiting for vsync to be disabled - timed out after 50 tries. - false == true - JS frame :: chrome://mochikit/content/browser-test.js :: ensureVsyncDisabled :: line 575
[task 2022-08-02T12:39:01.779Z] 12:39:01     INFO - Stack trace:
[task 2022-08-02T12:39:01.779Z] 12:39:01     INFO - chrome://mochikit/content/browser-test.js:ensureVsyncDisabled:575
[task 2022-08-02T12:39:01.780Z] 12:39:01     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-02T12:39:01.780Z] 12:39:01     INFO - TEST-UNEXPECTED-FAIL | dom/ipc/tests/browser_content_shutdown_with_endless_js.js | vsync remained enabled at the end of the test. Is there an animation still running? Consider talking to the performance team for tips to solve this. - false == true - JS frame :: chrome://mochikit/content/browser-test.js :: ensureVsyncDisabled :: line 576
[task 2022-08-02T12:39:01.780Z] 12:39:01     INFO - Stack trace:
[task 2022-08-02T12:39:01.780Z] 12:39:01     INFO - chrome://mochikit/content/browser-test.js:ensureVsyncDisabled:576
[task 2022-08-02T12:39:01.780Z] 12:39:01     INFO - GECKO(3969) | MEMORY STAT | vsize 402276MB | residentFast 335MB | heapAllocated 115MB
[task 2022-08-02T12:39:01.780Z] 12:39:01     INFO - TEST-OK | dom/ipc/tests/browser_content_shutdown_with_endless_js.js | took 52291ms
[task 2022-08-02T12:39:01.781Z] 12:39:01     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-02T12:39:01.781Z] 12:39:01     INFO - TEST-UNEXPECTED-FAIL | dom/ipc/tests/browser_content_shutdown_with_endless_js.js | Found a tab after previous test timed out: http://mochi.test:8888/browser/dom/ipc/tests/file_endless_js.html - 
[task 2022-08-02T12:39:01.789Z] 12:39:01     INFO - checking window state
[task 2022-08-02T12:39:01.791Z] 12:39:01     INFO - TEST-START | dom/ipc/tests/browser_crash_oopiframe.js
Flags: needinfo?(jstutte)
Regressed by: 1777198

Just saw https://bugzilla.mozilla.org/show_bug.cgi?id=1777198#c14, let's see if it still fails after latest land in comment 15.

Flags: needinfo?(jstutte)

:jstutte, since you are the author of the regressor, bug 1777198, could you take a look?
For more information, please visit auto_nag documentation.

Flags: needinfo?(jstutte)

(In reply to Cosmin Sabou [:CosminS] from comment #1)

Just saw https://bugzilla.mozilla.org/show_bug.cgi?id=1777198#c14, let's see if it still fails after latest land in comment 15.

There is still an issue here, the test needs an update.

Flags: needinfo?(jstutte)
Assignee: nobody → jstutte
Status: NEW → ASSIGNED
Pushed by jstutte@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e06a58bd4c0a
Make browser_content_shutdown_with_endless_js.js more robust against other processes' noise. r=smaug
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → 105 Branch

This test is still failing

Failure log

Status: RESOLVED → REOPENED
Flags: needinfo?(jstutte)
Resolution: FIXED → ---
Target Milestone: 105 Branch → ---

Uhm, this is a different issue than the patch solved (and it was already there with the first version of the test):

  • those failures seem to happen only on macosx (so far)
  • from the log it seems we do never get notified that the content process has launched such that we do not even enter the inner function of withNewTab (there is no TEST-PASS | dom/ipc/tests/browser_content_shutdown_with_endless_js.js | Content process created. for the HANG_PAGE)
  • there is always a TEST-UNEXPECTED-FAIL | dom/ipc/tests/browser_content_shutdown_with_endless_js.js | waiting for vsync to be disabled - timed out after 50 tries. - false == true - JS frame :: chrome://mochikit/content/browser-test.js :: ensureVsyncDisabled :: line 575 nearby (which has been introduced only a few days ago)

So it looks as if there was a problem with BrowserTestUtils.withNewTab (with this patch) and/or BrowserTestUtils.openNewForegroundTab (previous version of the test) that might be visible only if the content process is 100% busy with JS on load?

Florian, do you have any hint how to proceed here? From bug 1782559 it seems that this is not the only test that experiences this.

There might be a chance that we just need to wait running the JS loop in the content process until things settle and then send a message to the parent that we are ready for shutdown before entering the blocking loop?

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

(BTW, I do not think that these failures tell us anything bad about the tested functionality of aborting JS on content process shutdown, so if we do not have a good strategy here we might just want to disable it for macosx for now)

Flags: needinfo?(smolnar)

(In reply to Jens Stutte [:jstutte] from comment #9)

  • there is always a TEST-UNEXPECTED-FAIL | dom/ipc/tests/browser_content_shutdown_with_endless_js.js | waiting for vsync to be disabled - timed out after 50 tries. - false == true - JS frame :: chrome://mochikit/content/browser-test.js :: ensureVsyncDisabled :: line 575 nearby (which has been introduced only a few days ago)

The first failure message is "TEST-UNEXPECTED-FAIL | dom/ipc/tests/browser_content_shutdown_with_endless_js.js | Test timed out - ", so the test already failed before we detected vsync remained enabled at the end.

From having only read the previous comments in this bug and not looked at the code or anything else, I would guess after the timeout there's a tab that still runs the tab loading animation (the bouncing favicon), so vsync remains enabled.

The best way to verify would be to look at a profile of the failure. I'll try to get one.

Florian, do you have any hint how to proceed here? From bug 1782559 it seems that this is not the only test that experiences this.

I would be surprised if this was related to bug 1782559 (the root cause there was the animated favicon of about:robots that kept animating even though its tab had been closed).

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

I would be surprised if this was related to bug 1782559 (the root cause there was the animated favicon of about:robots that kept animating even though its tab had been closed).

Thanks, so I assume having a blocking javascript (here on purpose) has pretty much the same effect as having a stuck animation and the vsync failure is just a consequence of some jitter ongoing with BrowserTestUtils.withNewTab. Olli pointed me to another possible cause.

Flags: needinfo?(smolnar)
Flags: needinfo?(florian)

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

The best way to verify would be to look at a profile of the failure. I'll try to get one.

Here are 2 profiles I got from try: https://share.firefox.dev/3SrAgvJ https://share.firefox.dev/3SsUWDA

There's indeed a tab-throbber-animation that keeps running in the parent process. But I see the busy content process also receives PVsync::Msg_Notify IPCs from the Parent Process; I don't know why, but it might be observing vsync too.

FWIW I started landing of the additional patch - it should do no harm and might help to avoid some edge cases. We'll see if this extra spin of the content process' main thread event loop is enough to unblock things here. Please note that I will not be able to look further into this for the next two weeks. Thanks!

Pushed by jstutte@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/dbfd0cc1f48f
file_endless_js should start the blocking script only after all onload listeners were triggered. r=smaug
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → FIXED
Target Milestone: --- → 105 Branch
See Also: → 1783652
See Also: → 1785098
See Also: → 1792516
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: