1481304 - All Mac content processes "Not Responding" in Activity Monitor (but seem to work fine)

Status: RESOLVED FIXED

(Core :: DOM: Content Processes, defect)

Description

[Daniel Veditz [:dveditz]]

On my system all content processes are listed as "Not Responding" in Activity Monitor on Mac, although they appear to work fine (I'm entering this bug in one). I first noticed this morning in a build from Friday or Saturday, and it persisted after upgrading and restarting twice (first the pending update and then to today's build).

On IRC Mossop confirmed he saw it too.

Comment 1

[Chris Peterson [:cpeterson]]

[Tracking Requested - why for this release]:

Alex, I bisected this regression to the following pushlog, which points to your fix for native events bug 1426100:

https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=47aef65bc40dae041cc2c8635fc2594d6ef8aaa4&tochange=edfca01b39ab8bde74f1de73e04fa52acc6a9382

Comment 2

[Josh Matthews [:jdm]]

This seems to have implications for shutting down content processes, too. Every time I start Firefox, I get a message about unsent crash reports that matches the number of content processes that existed in my previous session.

Comment 3

[Alex Gaynor [:Alex_Gaynor]]

Attachment: Bug 1481304 - shutdown connections to the windowserver in content processes; r?haik

They'll be reopened, so there's no security benefit, but this causes Activity
Monitor to not report the processes as 'not responding'.

Comment 4

[Phabricator Automation]

Comment on attachment 8998188 [details]
Bug 1481304 - shutdown connections to the windowserver in content processes; r?haik

Haik Aftandilian [:haik] has approved the revision.

https://phabricator.services.mozilla.com/D2855

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/8171af14faf2
shutdown connections to the windowserver in content processes; r=haik

Comment 6

[Daniel Varga [:dvarga]]

Backed out changeset 8171af14faf2 (Bug 1481304) for failure at devtools/client/debugger/new/test/mochitest/browser_dbg-toggling-tools.js

Backout:
https://hg.mozilla.org/integration/autoland/rev/aa72fd1d53db7e6ef515cf847a55471d58b6b5f8

Push link:
https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=8171af14faf2015a0a7b7d1c8346a0b5d65d6829&filter-searchStr=dt4&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-classifiedState=unclassified

Failure log:
https://treeherder.mozilla.org/logviewer.html#?job_id=192858889&repo=autoland&lineNumber=8497

13:43:28     INFO - TEST-START | devtools/client/debugger/new/test/mochitest/browser_dbg_rr_breakpoints-01.js
13:43:28     INFO - GECKO(1881) | MIDDLEMAN 1902 /var/folders/sj/5tdfp2md3435zt681kh36bjh00000x/T/Recording557062
13:43:28     INFO - GECKO(1881) | RECORDING 1903 /var/folders/sj/5tdfp2md3435zt681kh36bjh00000x/T/Recording557062
13:43:28     INFO - GECKO(1881) | [Child 1902, Main Thread] WARNING: FileDescriptorSet destroyed with unconsumed descriptors: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/file_descriptor_set_posix.cc, line 22
13:43:28     INFO - GECKO(1881) | [Child 1902, Main Thread] WARNING: FileDescriptorSet destroyed with unconsumed descriptors: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/file_descriptor_set_posix.cc, line 22
13:43:28     INFO - GECKO(1881) | [Child 1902, Main Thread] WARNING: FileDescriptorSet destroyed with unconsumed descriptors: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/file_descriptor_set_posix.cc, line 22
13:43:29     INFO - GECKO(1881) | [Child 1902, Main Thread] WARNING: FileDescriptorSet destroyed with unconsumed descriptors: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/file_descriptor_set_posix.cc, line 22
13:43:29     INFO - GECKO(1881) | [Child 1902, Main Thread] WARNING: FileDescriptorSet destroyed with unconsumed descriptors: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/file_descriptor_set_posix.cc, line 22
13:43:29     INFO - GECKO(1881) | [Child 1902, Unnamed thread 116d33410] WARNING: FileDescriptorSet destroyed with unconsumed descriptors: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/file_descriptor_set_posix.cc, line 22
13:43:29     INFO - GECKO(1881) | JavaScript error: resource://gre/modules/WebProgressChild.jsm, line 106: NS_ERROR_UNEXPECTED:
13:43:29     INFO - GECKO(1881) | JavaScript error: resource://gre/modules/WebProgressChild.jsm, line 106: NS_ERROR_UNEXPECTED:
13:43:29     INFO - GECKO(1881) | JavaScript error: resource://gre/modules/WebProgressChild.jsm, line 106: NS_ERROR_UNEXPECTED:
13:43:29     INFO - GECKO(1881) | JavaScript error: resource://gre/modules/WebProgressChild.jsm, line 106: NS_ERROR_UNEXPECTED:
13:43:29     INFO - GECKO(1881) | [Child 1902, Unnamed thread 116d33410] WARNING: FileDescriptorSet destroyed with unconsumed descriptors: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/file_descriptor_set_posix.cc, line 22
13:43:29     INFO - GECKO(1881) | [Child 1902, Unnamed thread 116d33410] WARNING: FileDescriptorSet destroyed with unconsumed descriptors: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/file_descriptor_set_posix.cc, line 22
13:43:29     INFO - GECKO(1881) | REPLAYING 1904 /var/folders/sj/5tdfp2md3435zt681kh36bjh00000x/T/Recording557062
13:43:29     INFO - GECKO(1881) | REPLAYING 1905 /var/folders/sj/5tdfp2md3435zt681kh36bjh00000x/T/Recording557062
13:43:35     INFO - GECKO(1881) | REPLAYING 1906 /var/folders/sj/5tdfp2md3435zt681kh36bjh00000x/T/Recording557062
13:43:40     INFO - GECKO(1881) | REPLAYING 1907 /var/folders/sj/5tdfp2md3435zt681kh36bjh00000x/T/Recording557062
13:43:45     INFO - GECKO(1881) | REPLAYING 1908 /var/folders/sj/5tdfp2md3435zt681kh36bjh00000x/T/Recording557062
13:43:50     INFO - GECKO(1881) | REPLAYING 1909 /var/folders/sj/5tdfp2md3435zt681kh36bjh00000x/T/Recording557062
13:43:55     INFO - GECKO(1881) | REPLAYING 1910 /var/folders/sj/5tdfp2md3435zt681kh36bjh00000x/T/Recording557062
14:00:35     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/Users/cltbld/tasks/task_1533760302/build/venv/bin/python', '-u', '/Users/cltbld/tasks/task_1533760302/build/tests/mochitest/runtests.py', '--total-chunks', '8', '--this-chunk', '4', '--appname=/Users/cltbld/tasks/task_1533760302/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://queue.taskcluster.net/v1/task/ErPDaitWQqOOL7OndsZU3Q/artifacts/public/build/target.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--quiet', '--log-raw=/Users/cltbld/tasks/task_1533760302/build/blobber_upload_dir/mochitest-devtools-chrome-chunked_raw.log', '--log-errorsummary=/Users/cltbld/tasks/task_1533760302/build/blobber_upload_dir/mochitest-devtools-chrome-chunked_errorsummary.log', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/Users/cltbld/tasks/task_1533760302/build', '--log-raw=-', '--flavor=browser', '--subsuite=devtools', '--chunk-by-runtime']
14:00:35    ERROR - timed out after 1000 seconds of no output
14:00:35    ERROR - Return code: -15
14:00:35    ERROR - No suite end message was emitted by this harness.
14:00:35     INFO - TinderboxPrint: mochitest-mochitest-devtools-chrome-chunked<br/>81/0/0
14:00:35    ERROR - # TBPL FAILURE #
14:00:35  WARNING - setting return code to 2
14:00:35    ERROR - The mochitest suite: mochitest-devtools-chrome-chunked ran with return status: FAILURE
14:00:35     INFO - Running post-action listener: _package_coverage_data
14:00:35     INFO - Running post-action listener: _resource_record_post_action
14:00:35     INFO - Running post-action listener: process_java_coverage_data
14:00:35     INFO - [mozharness: 2018-08-08 21:00:35.634330Z] Finished run-tests step (success)
14:00:35     INFO - Running post-run listener: _resource_record_post_run

Comment 7

[Alex Gaynor [:Alex_Gaynor]]

Taking a look.

FYI you pasted the failure log for browser_dbg_rr_breakpoints-01.js, when you meant to post browser_dbg-toggling-tools.js. (This threw me for a loop for a few minutes)

Comment 8

[Alex Gaynor [:Alex_Gaynor]]

Brian, browser_dbg_rr_breakpoints-01.js seems to be consistently failing under the macOS opt builds, but not debug, and it doesn't reproduce locally either. I can't imagine why this change would break this test -- if this change broke anything, I'd expect it to be "spawning all content processes, all the time". Is there anything that I ought to know in trying to track this down?

The fact that it fails under opt, but not debug, makes me wonder if there isn't a race condition in the test that this patch triggers with some tiny timing difference.

Comment 9

[Brian Hackett [Laid off!]]

(In reply to Alex Gaynor [:Alex_Gaynor] from comment #8)
> Brian, browser_dbg_rr_breakpoints-01.js seems to be consistently failing
> under the macOS opt builds, but not debug, and it doesn't reproduce locally
> either. I can't imagine why this change would break this test -- if this
> change broke anything, I'd expect it to be "spawning all content processes,
> all the time". Is there anything that I ought to know in trying to track
> this down?
> 
> The fact that it fails under opt, but not debug, makes me wonder if there
> isn't a race condition in the test that this patch triggers with some tiny
> timing difference.

This test only runs on opt builds (there are some issues on debug builds at the moment), which I think explains why you're not seeing failures on debug builds.

I tried running the test locally on an opt build with the patch applied, and do see a failure.  The problem is that the patch is adding a call to CGSShutdownServerConnections() that runs when recording or replaying a tab.  The record/replay system redirects calls to system APIs like this so that we can avoid interacting with the system and get consistent behavior while replaying.  We don't have a redirection for CGSShutdownServerConnections; I'll add one soon, but until then it might be best to workaround this problem by wrapping the call to CGSShutdownServerConnections in an 'if (!recordreplay::IsRecordingOrReplaying())' test.

Comment 10

[Alex Gaynor [:Alex_Gaynor]]

Ahhhh! Thank you, will take a shot at that.

For the future, is there a good way for me to have discovered that myself? This is pretty subtly and it seems like you recognized it right away :-)

Comment 11

[Brian Hackett [Laid off!]]

(In reply to Alex Gaynor [:Alex_Gaynor] from comment #10)
> Ahhhh! Thank you, will take a shot at that.
> 
> For the future, is there a good way for me to have discovered that myself?
> This is pretty subtly and it seems like you recognized it right away :-)

After bug 1481009 lands, failures like this should produce stack dumps in treeherder logs, which will show that we crashed inside the call to CGSShutdownServerConnections.  I'll also experiment with printing some explanatory text whenever we crash while replaying and see if that shows up in the logs as well.

Comment 12

[Alex Gaynor [:Alex_Gaynor]]

Sounds great, that would have been a huge help. Thanks!

Comment 13

[Haik Aftandilian [:haik]]

(In reply to Brian Hackett (:bhackett) from comment #9)
> I'll add one soon, but until then it might be best to workaround this
> problem by wrapping the call to CGSShutdownServerConnections in an 'if
> (!recordreplay::IsRecordingOrReplaying())' test.

Brian, is there an exisitng explanation of when/how we need to use recordreplay::IsRecordingOrReplaying()?

Comment 14

[Brian Hackett [Laid off!]]

(In reply to Haik Aftandilian [:haik] from comment #13)
> (In reply to Brian Hackett (:bhackett) from comment #9)
> > I'll add one soon, but until then it might be best to workaround this
> > problem by wrapping the call to CGSShutdownServerConnections in an 'if
> > (!recordreplay::IsRecordingOrReplaying())' test.
> 
> Brian, is there an exisitng explanation of when/how we need to use
> recordreplay::IsRecordingOrReplaying()?

Hi, I just added an appendix 'Impacts on Gecko Development' to the web replay MDN page (https://developer.mozilla.org/en-US/docs/Mozilla/Projects/WebReplay) which describes how to address the ways in which Web Replay can be broken by other Gecko changes.

I also just filed bug 1482668 to add a redirection for CGSShutdownServerConnections.  When that is fixed there won't be a need for a workaround here, and the patch should be fine as is.

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/114f05d1f4a4
shutdown connections to the windowserver in content processes; r=haik

Comment 16

[Daniel Varga [:dvarga]]

https://hg.mozilla.org/mozilla-central/rev/114f05d1f4a4

Comment 17

[jiri.pospisil]

I'm still seeing this on the latest Nightly (64.0a1 (2018-10-13) (64-bit)). After I start the browser, everything seems fine. However, after a few minutes one after another the content processes become "Not responding" according to Activity Monitor. The browser seems to work fine though.

Activity monitor: https://i.imgur.com/tXEIdaF.png
A sample of one the "Not responding" processes: https://gist.github.com/jiripospisil/c8312c73f4173064ada2c48d4ffdf68a
about:support: https://gist.github.com/jiripospisil/324015fab7333abd2a81b82742a990a9

Comment 18

[Haik Aftandilian [:haik]]

(In reply to jiri.pospisil from comment #17)
> I'm still seeing this on the latest Nightly (64.0a1 (2018-10-13) (64-bit)).
> After I start the browser, everything seems fine. However, after a few
> minutes one after another the content processes become "Not responding"
> according to Activity Monitor. The browser seems to work fine though.
> 
> Activity monitor: https://i.imgur.com/tXEIdaF.png
> A sample of one the "Not responding" processes:
> https://gist.github.com/jiripospisil/c8312c73f4173064ada2c48d4ffdf68a
> about:support:
> https://gist.github.com/jiripospisil/324015fab7333abd2a81b82742a990a9

Thanks for the report. Would you mind filing a new bug for this? This appears to be a regression introduced by my fix for bug 1431441 with the same symptoms as this bug.

Comment 19

[jiri.pospisil]

(In reply to Haik Aftandilian [:haik] from comment #18)
> (In reply to jiri.pospisil from comment #17)
> > I'm still seeing this on the latest Nightly (64.0a1 (2018-10-13) (64-bit)).
> > After I start the browser, everything seems fine. However, after a few
> > minutes one after another the content processes become "Not responding"
> > according to Activity Monitor. The browser seems to work fine though.
> > 
> > Activity monitor: https://i.imgur.com/tXEIdaF.png
> > A sample of one the "Not responding" processes:
> > https://gist.github.com/jiripospisil/c8312c73f4173064ada2c48d4ffdf68a
> > about:support:
> > https://gist.github.com/jiripospisil/324015fab7333abd2a81b82742a990a9
> 
> Thanks for the report. Would you mind filing a new bug for this? This
> appears to be a regression introduced by my fix for bug 1431441 with the
> same symptoms as this bug.

Sure, here you go https://bugzilla.mozilla.org/show_bug.cgi?id=1498845

Comment 20

[Haik Aftandilian [:haik]]

Thank you for the report. This should be resolved by the backout of bug 1431441:

https://hg.mozilla.org/integration/autoland/rev/556f31a5e2230d5d06c23b5316d2231a74713251

And then I'll close this bug. The fix should be available in Nightly within the next 24 hours.