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

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

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

Comment 1

[Cosmin Sabou [:CosminS]]

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.

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 3

[Intermittent Failures Robot]

19 failures in 713 pushes (0.027 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 18
• mozilla-central: 1

Platform and build breakdown:

• macosx1100-64-shippable-qr: 11
  • opt: 11
• linux1804-64-qr: 2
  • debug: 1
  • opt: 1
• macosx1015-64-qr: 2
  • debug: 1
  • opt: 1
• windows10-32-2004-qr: 2
  • debug: 1
  • opt: 1
• windows10-64-2004-qr: 2
  • opt: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1782718&startday=2022-08-02&endday=2022-08-02&tree=all

Comment 4

[Jens Stutte [: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.

Comment 5

[Jens Stutte [:jstutte]]

Attachment: Bug 1782718 - Make browser_content_shutdown_with_endless_js.js more robust against other processes' noise. r?smaug

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e06a58bd4c0a
Make browser_content_shutdown_with_endless_js.js more robust against other processes' noise. r=smaug

Comment 7

[Sandor Molnar[:smolnar]]

https://hg.mozilla.org/mozilla-central/rev/e06a58bd4c0a

Comment 8

[Sandor Molnar[:smolnar]]

This test is still failing

Failure log

Comment 9

[Jens Stutte [:jstutte]]

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?

Comment 10

[Jens Stutte [:jstutte]]

(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)

Comment 11

[Florian Quèze [:florian]]

(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).

Comment 12

[Jens Stutte [:jstutte]]

Attachment: Bug 1782718 - file_endless_js should start the blocking script only after all onload listeners were triggered. r?smaug

Comment 13

[Jens Stutte [:jstutte]]

(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.

Comment 14

[Florian Quèze [: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.

Comment 15

[Jens Stutte [:jstutte]]

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!

Comment 16

[Pulsebot]

Pushed by [e-mail]:
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

Comment 17

[Intermittent Failures Robot]

19 failures in 663 pushes (0.029 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 16
• mozilla-central: 2
• try: 1

Platform and build breakdown:

• macosx1015-64-shippable-qr: 7
  • opt: 7
• macosx1015-64-qr: 9
  • opt: 9
• macosx1100-64-shippable-qr: 1
  • opt: 1
• windows10-32-2004-qr: 1
  • opt: 1
• windows10-64-2004-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1782718&startday=2022-08-04&endday=2022-08-04&tree=all

Comment 18

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/dbfd0cc1f48f

Comment 19

[Intermittent Failures Robot]

52 failures in 3057 pushes (0.017 failures/push) were associated with this bug in the last 7 days.

This is the #19 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 46
• mozilla-central: 5
• try: 1

Platform and build breakdown:

• macosx1100-64-shippable-qr: 15
  • opt: 15
• linux1804-64-qr: 3
  • debug: 1
  • opt: 2
• macosx1015-64-qr: 14
  • debug: 1
  • opt: 13
• windows10-32-2004-qr: 4
  • debug: 1
  • opt: 3
• windows10-64-2004-qr: 4
  • opt: 3
  • debug: 1
• windows7-32-qr: 1
  • opt: 1
• macosx1015-64-shippable-qr: 11
  • opt: 11

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1782718&startday=2022-08-01&endday=2022-08-07&tree=all

Comment 21

[Intermittent Failures Robot]

1 failures in 3339 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1782718&startday=2022-08-08&endday=2022-08-14&tree=all

Comment 23

[Intermittent Failures Robot]

2 failures in 3616 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1782718&startday=2022-09-05&endday=2022-09-11&tree=all

Comment 24

[Intermittent Failures Robot]

1 failures in 2909 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform and build breakdown:

• macosx1015-64-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1782718&startday=2022-09-19&endday=2022-09-25&tree=all

Comment 25

[Intermittent Failures Robot]

1 failures in 3530 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-release: 1

Platform and build breakdown:

• macosx1100-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1782718&startday=2023-01-09&endday=2023-01-15&tree=all