1470280 - Increase process count to 8 on Nightly

Status: RESOLVED FIXED

(Core :: DOM: Content Processes, enhancement, P2)

Description

[Eric Rahm [:erahm]]

We'd like to test out bumping the process count up to 8 on Windows Nightly. This will be nightly only.

Initial measurements with ATSY [1] show ~40MB overhead per process while still using less memory than Chrome.

[1] https://github.com/EricRahm/atsy

Comment 1

[Eric Rahm [:erahm]]

I did two sets of 5 runs of awsy: 
  - dom.ipc.processCount = 4
    https://treeherder.mozilla.org/#/jobs?repo=try&revision=e09b7cd25fd4153920f864730a5c9f9e8d8a0589
  - dom.ipc.processCount = 8:
    https://treeherder.mozilla.org/#/jobs?repo=try&revision=7330b89b717566da9e078c03213085e6b012ed8e

Explicit measurement
====================

64-bit build on Windows 10
--------------------------

We clearly regress on the tabs open measures for explicit on Win64 [1] which is expected. The numbers indicate roughly:
  - 34.50MB per process overhead for Explicit Memory After tabs open [+30s, forced GC]
  - 65.75MB per process overhead for Explicit Memory After tabs open [+30s]
  - 64.25MB per process overhead for Explicit Memory After tabs open

Startup is unchanged as expected, tabs closed is improved for some measures, but I wouldn't read too much into that.

32-bit build on Windows 7
-------------------------

The regression for explicit isn't as bad on Win32 [2].

Resident [3] measurement
========================

64-bit build on Windows 10
--------------------------
We clearly regress on the tabs open measures for explicit on Win64 [4] which is expected. The numbers indicate roughly:
  - 37.74MB per process overhead for Resident Memory After tabs open [+30s, forced GC]
  - 68.50MB per process overhead for Resident Memory After tabs open [+30s]
  - 66.50MB per process overhead for Resident Memory After tabs open

This is pretty much in line with explicit. Startup is unchanged as expected, tabs closed is improved for some measures, but I wouldn't read too much into that.

32-bit build on Windows 7
-------------------------

The regression for resident is worse on Win32 [5]. In past measurements we've confirmed that process overhead in general is higher on Windows 7 so this isn't terribly surprising -- I believe this is due to differences in ASLR implementations, but I'm having a hard time finding proof of that right now. The numbers indicate roughly:
  - 65.25MB per process overhead for Explicit Memory After tabs open [+30s, forced GC]
  - 93.75MB per process overhead for Explicit Memory After tabs open [+30s]
  - 93.25MB per process overhead for Explicit Memory After tabs open

It's not clear to me if a 64-bit build on Windows 7 would have the same larger regression.

[1] https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=e09b7cd25fd4&newProject=try&newRevision=7330b89b717566da9e078c03213085e6b012ed8e&originalSignature=2bd1b01bbca5d06e029f2ef7c1732f7295b71cc6&newSignature=2bd1b01bbca5d06e029f2ef7c1732f7295b71cc6&framework=4
[2] https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=e09b7cd25fd4&newProject=try&newRevision=7330b89b717566da9e078c03213085e6b012ed8e&originalSignature=4f283ca6168f05e0e67c3a64677379b8a6d76717&newSignature=4f283ca6168f05e0e67c3a64677379b8a6d76717&framework=4
[3] "Resident" = RSS_of_parent + sum(USS_of_children)
[4] https://treeherder.mozilla.org/perf.html#/comparesubtest?framework=4&newProject=try&newRevision=7330b89b717566da9e078c03213085e6b012ed8e&newSignature=c5bf2e43033c90a9bb6e510d438274900fe867f4&originalProject=try&originalRevision=e09b7cd25fd4&originalSignature=c5bf2e43033c90a9bb6e510d438274900fe867f4
[5] https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=try&originalRevision=e09b7cd25fd4&newProject=try&newRevision=7330b89b717566da9e078c03213085e6b012ed8e&originalSignature=8964a3148c9dc161842d9d5e582b1af2d58e6a98&newSignature=8964a3148c9dc161842d9d5e582b1af2d58e6a98&framework=4

Comment 2

[Eric Rahm [:erahm]]

Attachment: Increase process count to 8 on Windows Nightly

Comment 3

[Blake Kaplan (:mrbkap) (inactive)]

Comment on attachment 8986941 [details] [diff] [review]
Increase process count to 8 on Windows Nightly

Review of attachment 8986941 [details] [diff] [review]:
-----------------------------------------------------------------

Before I stamp this, I would like to make sure that we're taking bug 1399962 into account. On Nightly, our users may be (overall) on better computers so this will be a net positive for them, but we should probably be a bit careful doing this.

Comment 4

[Eric Rahm [:erahm]]

(In reply to Blake Kaplan (:mrbkap) from comment #3)
> Comment on attachment 8986941 [details] [diff] [review]
> Increase process count to 8 on Windows Nightly
> 
> Review of attachment 8986941 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Before I stamp this, I would like to make sure that we're taking bug 1399962
> into account. On Nightly, our users may be (overall) on better computers so
> this will be a net positive for them, but we should probably be a bit
> careful doing this.

It looks like bug 1399962 is going to take a while to resolve itself. What do you think about limiting this to only systems with >= 4 logical cpus? I'm okay with backing this out in a few weeks, but it would be pretty useful to see what issues arise as we prepare for drastically increasing the process count for site isolation work.

Comment 5

[:Felipe Gomes (needinfo for replies!)]

I just read the backscroll on IRC. Here are a couple of thoughts. Feel free to ignore them if they throw things in a different direction.

- There's a way to do "read-only" prefs, which is reading the pref from the default branch. I think we should use it for the "internal" pref that was discussed.

We just need to check if Shield is able to handle it properly (just in case we want to do a shield study on this), but I believe the answer is yes.


- On naming grounds, I think it'd be nicer if we repurpose the dom.ipc.processCount one to be the internal one, and add a more friendly-name pref to be the user-controlled one that will have 0/-1 as its value. ("maxContentProcesses" or something like that)

Though that has the downside of confusing everyone who has already customized their dom.ipc.processCount pref

- Please ensure that the about:preferences code remains working.. The logic there IIRC is a bit convoluted, but I believe this work will make it simpler.

Comment 6

[Blake Kaplan (:mrbkap) (inactive)]

(In reply to :Felipe Gomes (needinfo me!) from comment #5)
> Though that has the downside of confusing everyone who has already
> customized their dom.ipc.processCount pref

This was my worry. I don't want to break people unnecessarily and dom.ipc.processCount has a long history already. If we do change its meaning, we'll have to go through all of the tests that set it and update them as well.

Comment 7

[:Felipe Gomes (needinfo for replies!)]

That's a good point.. so, let's ignore that part!

Comment 8

[Andrew Overholt [:overholt]]

Taking a stab at a better component here.

Comment 9

[Eric Rahm [:erahm]]

Attachment: Increase process count to 8 on Windows Nightly

Blake, is this more what you were thinking?

Comment 10

[Eric Rahm [:erahm]]

Unfortunately setting 'dom.ipc.processCount' to -1 results in the 'Content process limit' field of about:preferences to default to a blank entry. If I select the drop down the correct value is listed as default (4 on mac). Presumably this is because it's linked to the pref in the main.xul file [1].

[1] https://searchfox.org/mozilla-central/rev/4074ba403219b7accdf00220b20dc492bfd4d83e/browser/components/preferences/in-content/main.xul#587

Comment 11

[Blake Kaplan (:mrbkap) (inactive)]

(In reply to Eric Rahm [:erahm] (please no mozreview requests) from comment #10)
> Unfortunately setting 'dom.ipc.processCount' to -1 results in the 'Content
> process limit' field of about:preferences to default to a blank entry. If I
> select the drop down the correct value is listed as default (4 on mac).
> Presumably this is because it's linked to the pref in the main.xul file [1].

mconley, can you help with this? How hard would it be to allow elements with preference="" to, instead of simply reading the pref, provide a getter?

Comment 12

[Blake Kaplan (:mrbkap) (inactive)]

Comment on attachment 8988940 [details] [diff] [review]
Increase process count to 8 on Windows Nightly

Review of attachment 8988940 [details] [diff] [review]:
-----------------------------------------------------------------

This is what I was thinking of. Hopefully we can just fix main.xul.

Comment 13

[Mike Conley (:mconley) (:⚙️)]

What you're doing in your latest patch is _probably_ fine, but what I think is more common is using onsynctopreference and onsyncfrompreference - see

https://developer.mozilla.org/en-US/docs/Mozilla/Preferences/Preferences_system/New_attributes#onsyncfrompreference.2Fonsynctopreference

Essentially, these are optional translation functions that you can use to translate the UI preference values to what actually is being stored in the prefs table.

Comment 14

[Eric Rahm [:erahm]]

We've discussed this in a few fission related meetings and would like to bump up to 8 sooner than later, we're also going to want this on all platforms.

Given the direction of fission we'd also like to go ahead and remove the UI for changing the amount of processes in about:preferences' performance section. I'll file a follow up for that.

Comment 15

[Eric Rahm [:erahm]]

Attachment: Increase process count to 8 on Nightly

This increases the default amount of content processes on nightly to 8. It
is nightly only and will not ride the trains.

Felipe, can you review this or redirect to the right person?

Comment 16

[Eric Rahm [:erahm]]

Attachment: Increase process count to 8 on Nightly

Updated to fix the prefs UI and its tests.

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/d5375325488f
Increase process count to 8 on Nightly. r=felipe

Comment 18

[Eric Rahm [:erahm]]

Before landing I saw similar regressions [1] to comment 1, nothing unexpected. Just FYI to sheriffs, we know this will regress explicit and resident by ~5% (OSX resident ~10%). Having a bug on file for the regression when it comes in will still be useful, I just wanted to note we expect it.

This is going to be nightly-only for now and we'll potentially backout if there are stability issues next week.

[1] https://treeherder.mozilla.org/perf.html#/compare?originalProject=try&originalRevision=674404f96dbe&newProject=try&newRevision=6ce8cd422d3384509407b9ef156dd2a202b2c247&framework=4

Comment 19

[Andreea Pavel [:apavel]]

(In reply to Eric Rahm [:erahm] from comment #18)
> Before landing I saw similar regressions [1] to comment 1, nothing
> unexpected. Just FYI to sheriffs, we know this will regress explicit and
> resident by ~5% (OSX resident ~10%). Having a bug on file for the regression
> when it comes in will still be useful, I just wanted to note we expect it.
> 
> This is going to be nightly-only for now and we'll potentially backout if
> there are stability issues next week.
> 
> [1]
> https://treeherder.mozilla.org/perf.html#/
> compare?originalProject=try&originalRevision=674404f96dbe&newProject=try&newR
> evision=6ce8cd422d3384509407b9ef156dd2a202b2c247&framework=4

Unfortunately, since you did not ni/cc us, or ping us on #sheriffs, i did not see your message so i backed out for failing OS X bc at browser/base/content/test/performance/browser_preferences_usage.js

Push that started the failures: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&resultStatus=testfailed,busted,exception&classifiedState=unclassified&selectedJob=203715363&revision=d5375325488f449c45dd032bc8167ebebca07497

Failure logs: https://treeherder.mozilla.org/logviewer.html#?job_id=203715796&repo=mozilla-inbound&lineNumber=1245
and
https://treeherder.mozilla.org/logviewer.html#?job_id=203719620&repo=mozilla-inbound&lineNumber=2177

Backout: https://hg.mozilla.org/integration/mozilla-inbound/rev/82b90238ee320a3b44e424646f42f278d0516993

Comment 20

[Eric Rahm [:erahm]]

Attachment: Part 1: Make browser_preferences_usage.js less brittle

browser_preferences_usage.js hardcodes a max value of 15 accesses which doesn't scale well as we increase the number of processes. Instead we'll base the max on a multiplier of the default process count which should avoid bustage in the future but still catch egregious accesses.

Kris, it looks like you're familiar with this test, can you take a look?

Comment 21

[Andreea Pavel [:apavel]]

Eric, this increased the failure rate for other failure, on windows and linux e.g:

Win intermittent failure:
https://treeherder.mozilla.org/logviewer.html#?job_id=203739088&repo=mozilla-inbound&lineNumber=2311.

Linux perma-failure:
https://treeherder.mozilla.org/logviewer.html#?job_id=203728185&repo=mozilla-inbound&lineNumber=2275

and Bug 1472506.

Comment 22

[Kris Maglione [:kmag]]

Comment on attachment 9014947 [details] [diff] [review]
Part 1: Make browser_preferences_usage.js less brittle

Review of attachment 9014947 [details] [diff] [review]:
-----------------------------------------------------------------

This makes me a bit nervous. I see why dom.ipc.* preferences should be accessed more when we have more processes, but I'm not sure a blanket increase makes sense. Maybe just increase the max for preferences which start with "dom.ipc.*"?

Comment 23

[Kris Maglione [:kmag]]

Comment on attachment 9014947 [details] [diff] [review]
Part 1: Make browser_preferences_usage.js less brittle

Review of attachment 9014947 [details] [diff] [review]:
-----------------------------------------------------------------

This makes me a bit nervous. I see why dom.ipc.* preferences should be accessed more when we have more processes, but I'm not sure a blanket increase makes sense. Maybe just increase the max for preferences which start with "dom.ipc.*"?

Comment 24

[Eric Rahm [:erahm]]

(In reply to Kris Maglione [:kmag] from comment #23)
> Comment on attachment 9014947 [details] [diff] [review]
> Part 1: Make browser_preferences_usage.js less brittle
> 
> Review of attachment 9014947 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> This makes me a bit nervous. I see why dom.ipc.* preferences should be
> accessed more when we have more processes, but I'm not sure a blanket
> increase makes sense. Maybe just increase the max for preferences which
> start with "dom.ipc.*"?

It's more than just 'dom.ipc.*', it also includes a few random sandbox prefs. 15 is pretty arbitrary already, this just bumps up to 32 and slightly less arbitrary.

Comment 25

[Kris Maglione [:kmag]]

Comment on attachment 9014947 [details] [diff] [review]
Part 1: Make browser_preferences_usage.js less brittle

># HG changeset patch
># User Eric Rahm <[e-mail]>
># Date 1538774938 25200
>#      Fri Oct 05 14:28:58 2018 -0700
># Node ID 8b388d8a37266bc3d9316636a495feb6146d3de5
># Parent  62a73eefbaac08eb73951548547eeb2f0847fc9a
>Bug 1470280 - Part 1: Make browser_preferences_usage.js less brittle. r=kmag
>
>browser_preferences_usage.js hardcodes a max value of 15 accesses which doesn't scale well as we increase the number of processes. Instead we'll base the max on a multiplier of the default process count which should avoid bustage in the future but still catch egregious accesses.
>
>diff --git a/browser/base/content/test/performance/browser_preferences_usage.js b/browser/base/content/test/performance/browser_preferences_usage.js
>--- a/browser/base/content/test/performance/browser_preferences_usage.js
>+++ b/browser/base/content/test/performance/browser_preferences_usage.js
>@@ -1,6 +1,8 @@
> /* Any copyright is dedicated to the Public Domain.
>    http://creativecommons.org/publicdomain/zero/1.0/ */
> 
>+const DEFAULT_PROCESS_COUNT = Services.prefs.getDefaultBranch(null).getIntPref("dom.ipc.processCount");
>+
> /**
>  * A test that checks whether any preference getter from the given list
>  * of stats was called more often than the max parameter.
>@@ -120,7 +122,10 @@ add_task(async function startup() {
> 
> // This opens 10 tabs and checks pref getters.
> add_task(async function open_10_tabs() {
>-  let max = 15;
>+  // This is somewhat arbitrary. When we had a default of 4 content processes
>+  // the value was 15. We need to scale it as we increase the number of
>+  // content processes so we approximate with 4 * process_count.
>+  const max = 4 * DEFAULT_PROCESS_COUNT;
> 
>   let whitelist = {
>     "layout.css.dpi": {
>@@ -146,10 +151,6 @@ add_task(async function open_10_tabs() {
>       min: 10,
>       max: 18,
>     },
>-    "dom.ipc.processCount": {
>-      min: 10,
>-      max: 15,
>-    },
>     "browser.startup.record": {
>       max: 20,
>     },

Comment 26

[Andreea Pavel [:apavel]]

There's also this new failure: https://treeherder.mozilla.org/logviewer.html#?job_id=203747522&repo=mozilla-inbound&lineNumber=6947


21:53:12     INFO - TEST-START | dom/base/test/browser_force_process_selector.js
21:53:12     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:12     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:12     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:12     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:12     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:12     INFO - GECKO(10092) | [Child 9152, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:12     INFO - GECKO(10092) | [Child 9152, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:12     INFO - GECKO(10092) | [Child 5264, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:12     INFO - GECKO(10092) | [Child 5264, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:12     INFO - GECKO(10092) | [Child 924, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:12     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:12     INFO - GECKO(10092) | [Child 10208, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:57     INFO - TEST-INFO | started process screenshot
21:53:57     INFO - TEST-INFO | screenshot: exit 0
21:53:57     INFO - Buffered messages logged at 21:53:12
21:53:57     INFO - Entering test bound test
21:53:57     INFO - TEST-PASS | dom/base/test/browser_force_process_selector.js | new tab is in its own process - 
21:53:57     INFO - Buffered messages logged at 21:53:13
21:53:57     INFO - TEST-PASS | dom/base/test/browser_force_process_selector.js | new tab is in its own process - 
21:53:57     INFO - TEST-PASS | dom/base/test/browser_force_process_selector.js | new tab is in its own process - 
21:53:57     INFO - TEST-PASS | dom/base/test/browser_force_process_selector.js | new tab is in its own process - 
21:53:57     INFO - Buffered messages logged at 21:53:14
21:53:57     INFO - TEST-PASS | dom/base/test/browser_force_process_selector.js | new tab is in its own process - 
21:53:57     INFO - Buffered messages finished
21:53:57     INFO - TEST-UNEXPECTED-FAIL | dom/base/test/browser_force_process_selector.js | Test timed out - 
21:53:57     INFO - GECKO(10092) | MEMORY STAT | vsize 1721MB | vsizeMaxContiguous 132267215MB | residentFast 245MB | heapAllocated 85MB
21:53:57     INFO - TEST-OK | dom/base/test/browser_force_process_selector.js | took 45059ms
21:53:57     INFO - Not taking screenshot here: see the one that was previously logged
21:53:57     INFO - TEST-UNEXPECTED-FAIL | dom/base/test/browser_force_process_selector.js | Found a tab after previous test timed out: about:blank - 
21:53:57     INFO - Not taking screenshot here: see the one that was previously logged
21:53:57     INFO - TEST-UNEXPECTED-FAIL | dom/base/test/browser_force_process_selector.js | Found a tab after previous test timed out: about:blank - 
21:53:57     INFO - Not taking screenshot here: see the one that was previously logged
21:53:57     INFO - TEST-UNEXPECTED-FAIL | dom/base/test/browser_force_process_selector.js | Found a tab after previous test timed out: about:blank - 
21:53:57     INFO - Not taking screenshot here: see the one that was previously logged
21:53:57     INFO - TEST-UNEXPECTED-FAIL | dom/base/test/browser_force_process_selector.js | Found a tab after previous test timed out: about:blank - 
21:53:57     INFO - Not taking screenshot here: see the one that was previously logged
21:53:57     INFO - TEST-UNEXPECTED-FAIL | dom/base/test/browser_force_process_selector.js | Found a tab after previous test timed out: about:blank - 
21:53:57     INFO - Not taking screenshot here: see the one that was previously logged
21:53:57     INFO - TEST-UNEXPECTED-FAIL | dom/base/test/browser_force_process_selector.js | Found a tab after previous test timed out: about:blank - 
21:53:57     INFO - checking window state
21:53:57     INFO - TEST-START | dom/base/test/browser_inputStream_structuredClone.js
21:53:58     INFO - GECKO(10092) | MEMORY STAT | vsize 1813MB | vsizeMaxContiguous 132267112MB | residentFast 348MB | heapAllocated 194MB
21:53:58     INFO - TEST-OK | dom/base/test/browser_inputStream_structuredClone.js | took 591ms
21:53:58     INFO - checking window state
21:53:58     INFO - TEST-START | dom/base/test/browser_messagemanager_loadprocessscript.js
21:53:58     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:58     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:58     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:58     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:58     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:58     INFO - GECKO(10092) | [Child 10064, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:58     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: file z:/build/build/src/ipc/chromium/src/base/process_util_win.cc, line 188
21:53:58     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: file z:/build/build/src/ipc/chromium/src/base/process_util_win.cc, line 188
21:53:58     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: file z:/build/build/src/ipc/chromium/src/base/process_util_win.cc, line 188
21:53:58     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: file z:/build/build/src/ipc/chromium/src/base/process_util_win.cc, line 188
21:53:58     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: file z:/build/build/src/ipc/chromium/src/base/process_util_win.cc, line 188
21:53:58     INFO - Not taking screenshot here: see the one that was previously logged
21:53:58     INFO - Buffered messages logged at 21:53:58
21:53:58     INFO - Entering test bound 
21:53:58     INFO - Leaving test bound 
21:53:58     INFO - Entering test bound 
21:53:58     INFO - Buffered messages finished
21:53:58     INFO - TEST-UNEXPECTED-FAIL | dom/base/test/browser_force_process_selector.js | Uncaught exception received from previously timed out test - at chrome://mochitests/content/browser/dom/base/test/browser_force_process_selector.js:14 - TypeError: browser.frameLoader is null; can't access its "tabParent" property
21:53:58     INFO - Stack trace:
21:53:58     INFO - spawnNewAndTest/<@chrome://mochitests/content/browser/dom/base/test/browser_force_process_selector.js:14:11
21:53:58     INFO - async*withNewTab@resource://testing-common/BrowserTestUtils.jsm:111:24
21:53:58     INFO - async*spawnNewAndTest@chrome://mochitests/content/browser/dom/base/test/browser_force_process_selector.js:9:9
21:53:58     INFO - async*spawnNewAndTest/<@chrome://mochitests/content/browser/dom/base/test/browser_force_process_selector.js:19:15
21:53:58     INFO - async*withNewTab@resource://testing-common/BrowserTestUtils.jsm:111:24
21:53:58     INFO - async*spawnNewAndTest@chrome://mochitests/content/browser/dom/base/test/browser_force_process_selector.js:9:9
21:53:58     INFO - async*spawnNewAndTest/<@chrome://mochitests/content/browser/dom/base/test/browser_force_process_selector.js:19:15
21:53:58     INFO - async*withNewTab@resource://testing-common/BrowserTestUtils.jsm:111:24
21:53:58     INFO - async*spawnNewAndTest@chrome://mochitests/content/browser/dom/base/test/browser_force_process_selector.js:9:9
21:53:58     INFO - async*spawnNewAndTest/<@chrome://mochitests/content/browser/dom/base/test/browser_force_process_selector.js:19:15
21:53:58     INFO - async*withNewTab@resource://testing-common/BrowserTestUtils.jsm:111:24
21:53:58     INFO - async*spawnNewAndTest@chrome://mochitests/content/browser/dom/base/test/browser_force_process_selector.js:9:9
21:53:58     INFO - async*spawnNewAndTest/<@chrome://mochitests/content/browser/dom/base/test/browser_force_process_selector.js:19:15
21:53:58     INFO - async*withNewTab@resource://testing-common/BrowserTestUtils.jsm:111:24
21:53:58     INFO - async*spawnNewAndTest@chrome://mochitests/content/browser/dom/base/test/browser_force_process_selector.js:9:9
21:53:58     INFO - async*spawnNewAndTest/<@chrome://mochitests/content/browser/dom/base/test/browser_force_process_selector.js:19:15
21:53:58     INFO - async*withNewTab@resource://testing-common/BrowserTestUtils.jsm:111:24
21:53:58     INFO - async*spawnNewAndTest@chrome://mochitests/content/browser/dom/base/test/browser_force_process_selector.js:9:9
21:53:58     INFO - async*test@chrome://mochitests/content/browser/dom/base/test/browser_force_process_selector.js:42:9
21:53:58     INFO - Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1093:34
21:53:58     INFO - async*Tester_execTest@chrome://mochikit/content/browser-test.js:1084:16
21:53:58     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:986:9
21:53:58     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
21:53:59     INFO - TEST-PASS | dom/base/test/browser_messagemanager_loadprocessscript.js | Should get back to the base number of processes at this point (4 or 5) - 
21:53:59     INFO - Leaving test bound 
21:53:59     INFO - Entering test bound 
21:53:59     INFO - TEST-PASS | dom/base/test/browser_messagemanager_loadprocessscript.js | Saw process finished - 
21:53:59     INFO - TEST-PASS | dom/base/test/browser_messagemanager_loadprocessscript.js | Saw process finished - 
21:53:59     INFO - TEST-PASS | dom/base/test/browser_messagemanager_loadprocessscript.js | Saw process finished - 
21:53:59     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:59     INFO - TEST-PASS | dom/base/test/browser_messagemanager_loadprocessscript.js | Saw process finished - 
21:53:59     INFO - GECKO(10092) | [Parent 8328, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
21:53:59     INFO - Leaving test bound 
21:53:59     INFO - Entering test bound

Comment 27

[Eric Rahm [:erahm]]

(In reply to Andreea Pavel [:apavel] from comment #21)
> Eric, this increased the failure rate for other failure, on windows and
> linux e.g:
> 
> Win intermittent failure:
> https://treeherder.mozilla.org/logviewer.html#?job_id=203739088&repo=mozilla-
> inbound&lineNumber=2311.

This is some sort of reflow test, I think we can accept it being more frequent and ask whoever understands it to look into it.

> Linux perma-failure:
> https://treeherder.mozilla.org/logviewer.html#?job_id=203728185&repo=mozilla-
> inbound&lineNumber=2275

This is browser_preferences_usage and attachment 9014947 [details] [diff] [review] fixes it. 

> and Bug 1472506.

I don't see this one, but I am seeing:

> https://treeherder.mozilla.org/logviewer.html#?job_id=203747522&repo=mozilla-inbound&lineNumber=6940

Which is dom/base/test/browser_force_process_selector.js. It seems to timeout waiting for the 6th process, previously it only tested 5 (now it tests 11) so this might be a latent issue.

Comment 28

[Andreea Pavel [:apavel]]

Sorry for the spam Eric :D

For Bug 1472506 : https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&resultStatus=testfailed,busted,exception&classifiedState=classified&fromchange=e8aec0dccbb8213dd292d7331f01307969cdff9a&searchStr=os,x,10.10,opt,mochitests,with,e10s,test-macosx64%2Fopt-mochitest-browser-chrome-e10s-2,m-e10s(bc2)&selectedJob=203719620

Le me know if there are any other details i can provide.

Comment 29

[Eric Rahm [:erahm]]

(In reply to Andreea Pavel [:apavel] from comment #28)
> Sorry for the spam Eric :D
> 
> For Bug 1472506 :
> https://treeherder.mozilla.org/#/jobs?repo=mozilla-
> inbound&resultStatus=testfailed,busted,
> exception&classifiedState=classified&fromchange=e8aec0dccbb8213dd292d7331f013
> 07969cdff9a&searchStr=os,x,10.10,opt,mochitests,with,e10s,test-
> macosx64%2Fopt-mochitest-browser-chrome-e10s-2,m-
> e10s(bc2)&selectedJob=203719620
> 
> Le me know if there are any other details i can provide.

Thanks, the details have been really helpful!

Comment 30

[Eric Rahm [:erahm]]

I can repro dom/base/test/browser_force_process_selector.js locally on linux (it's intermittent) with:

> ./mach mochitest --run-until-failure --headless dom/base/test/browser_force_process_selector.js

I confirmed via `htop` the processes *are* launched which implies the `processCreated` [1] topic is never observed. Logging confirms this is the case.

[1] https://searchfox.org/mozilla-central/rev/807a37c670c093b6e5201841a7c5315ba67ba8d5/dom/base/test/browser_force_process_selector.js#8,13

Comment 31

[Eric Rahm [:erahm]]

Attachment: Part 2: Just use osPid to check for new process

The 'ipc:content-created' topic doesn't always seem to be propagated to the
browser_force_process_selector.js test. It appears it's not necessary to
actually wait for it, so lets just remove that.

Mike, can you take a look at this? The test started failing when I bumped the
default process count. Removing the wait for the 'content-created' event seems
to fix things. It's possible there's an underlying issue I'm papering over in
how the test is setup or in the test utils, I'm happy to file a followup for
someone more well versed in these tests if you think it's necessary.

Comment 32

[Eric Rahm [:erahm]]

Attachment: Part 3: Use the default process count in browser_ext_slow_script.js

This updates the test to use a multiple of the default process count rather
than hardcoding 8.

Kris, can you take a look at this? It's not super clear to me what's going on,
but I think the test depends on using a value either greater than the default
process count *or* just different than the default.

Comment 33

[Kris Maglione [:kmag]]

Comment on attachment 9015094 [details] [diff] [review]
Part 3: Use the default process count in browser_ext_slow_script.js

Review of attachment 9015094 [details] [diff] [review]:
-----------------------------------------------------------------

(In reply to Eric Rahm [:erahm] from comment #32)
> Kris, can you take a look at this? It's not super clear to me what's going on,
> but I think the test depends on using a value either greater than the default
> process count *or* just different than the default.

It requires using a value higher than the current number of processes, so that
we get a new process. We can probably just use the forceNewProcess flag in
BrowserTestUtils.openNewForegroundTab now, but this is no worse than the current
code.

Comment 34

[Eric Rahm [:erahm]]

bc on linux is looking pretty good now:

> https://treeherder.mozilla.org/#/jobs?repo=try&revision=97a58621c41979f9dcf1d7dd84d2c4e69d9d9bc7

A full test run looks pretty good too:

> https://treeherder.mozilla.org/#/jobs?repo=try&revision=c6ebcecc7566157a871143ff1d4e80d6eb62d619

One exception is that 'browser/base/content/test/tabcrashed/browser_noPermanentKey.js' on windows and mac debug builds seems to be permafail now. We already disabled it for linux and linux64 in bug 1383315. I think we should probably just go ahead and disable on windows and mac as well.

I ran talos in that run as well, there weren't any high confidence regressions or improvements yet.

Comment 35

[Eric Rahm [:erahm]]

(In reply to Eric Rahm [:erahm] from comment #34)

> One exception is that
> 'browser/base/content/test/tabcrashed/browser_noPermanentKey.js' on windows
> and mac debug builds seems to be permafail now. We already disabled it for
> linux and linux64 in bug 1383315. I think we should probably just go ahead
> and disable on windows and mac as well.

Patch is up in bug 1383315 to disable on windows and mac.

Comment 36

[Mike Conley (:mconley) (:⚙️)]

Comment on attachment 9015093 [details] [diff] [review]
Part 2: Just use osPid to check for new process

Review of attachment 9015093 [details] [diff] [review]:
-----------------------------------------------------------------

Wacky. Yeah, let's definitely get that follow-up filed. Do we know if it's firing and just not being seen by the test?

Comment 37

[Eric Rahm [:erahm]]

(In reply to Mike Conley (:mconley) (:⚙️) from comment #36)
> Comment on attachment 9015093 [details] [diff] [review]
> Part 2: Just use osPid to check for new process
> 
> Review of attachment 9015093 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Wacky. Yeah, let's definitely get that follow-up filed. Do we know if it's
> firing and just not being seen by the test?

Will do, when I was printf debugging I verified that the IPC code *is* firing the event.

Comment 38

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/60699c2387f6
Part 1: Make browser_preferences_usage.js less brittle. r=kmag
https://hg.mozilla.org/integration/mozilla-inbound/rev/fe7ccd9fee76
Part 2: Just use osPid to check for new process. r=mconley
https://hg.mozilla.org/integration/mozilla-inbound/rev/403c3d0daf6a
Part 3: Use the default process count in browser_ext_slow_script.js. r=kmag
https://hg.mozilla.org/integration/mozilla-inbound/rev/72e7ef77480d
Part 4: Increase process count to 8 on Nightly. r=felipe

Comment 39

[Raul Gurzau (:RaulG)]

https://hg.mozilla.org/mozilla-central/rev/60699c2387f6
https://hg.mozilla.org/mozilla-central/rev/fe7ccd9fee76
https://hg.mozilla.org/mozilla-central/rev/403c3d0daf6a
https://hg.mozilla.org/mozilla-central/rev/72e7ef77480d

Comment 40

[Dorel Luca [:dluca]]

Backed out 4 changesets (bug 1470280) for browser-chrome failure in layout/xul/test/browser_bug703210.js. a=backout

Log:
https://treeherder.mozilla.org/logviewer.html#?job_id=204421916&repo=mozilla-central&lineNumber=4589

NFO - TEST-PASS | layout/xul/test/browser_bug703210.js | tooltip is hidden - 
[task 2018-10-10T05:49:36.844Z] 05:49:36     INFO - Buffered messages finished
[task 2018-10-10T05:49:36.846Z] 05:49:36     INFO - TEST-UNEXPECTED-FAIL | layout/xul/test/browser_bug703210.js | Test timed out - 
[task 2018-10-10T05:49:36.847Z] 05:49:36     INFO - GECKO(8609) | MEMORY STAT | vsize 605MB | residentFast 262MB | heapAllocated 71MB
[task 2018-10-10T05:49:36.849Z] 05:49:36     INFO - TEST-OK | layout/xul/test/browser_bug703210.js | took 45157ms
[task 2018-10-10T05:49:36.850Z] 05:49:36     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-10-10T05:49:36.851Z] 05:49:36     INFO - TEST-UNEXPECTED-FAIL | layout/xul/test/browser_bug703210.js | Found a tab after previous test timed out: data:text/html,<html onmousemove='event.stopPropagation()' onmouseenter='event.stopPropagation()' onmouseleave='event.stopPropagation()' onmouseover='event.stopPropagation()' onmouseout='event.stopPropagation()'><p id="p1" title="tooltip is here">This paragraph has a tooltip.</p><p id="p2">This paragraph doesn't have tooltip.</p></html> - 
[task 2018-10-10T05:49:36.853Z] 05:49:36     INFO - checking window state
[task 2018-10-10T05:49:38.009Z] 05:49:38     INFO - GECKO(8609) | Completed ShutdownLeaks collections in process 8794
[task 2018-10-10T05:49:38.018Z] 05:49:38     INFO - GECKO(8609) | Completed ShutdownLeaks collections in process 8759
[task 2018-10-10T05:49:38.034Z] 05:49:38     INFO - GECKO(8609) | Completed ShutdownLeaks collections in process 8803
[task 2018-10-10T05:49:38.036Z] 05:49:38     INFO - GECKO(8609) | Completed ShutdownLeaks collections in process 8890
[task 2018-10-10T05:49:38.055Z] 05:49:38     INFO - GECKO(8609) | Completed ShutdownLeaks collections in process 8709
[task 2018-10-10T05:49:38.074Z] 05:49:38     INFO - GECKO(8609) | Completed ShutdownLeaks collections in process 8845
[task 2018-10-10T05:49:38.078Z] 05:49:38     INFO - GECKO(8609) | Completed ShutdownLeaks collections in process 8858
[task 2018-10-10T05:49:38.083Z] 05:49:38     INFO - GECKO(8609) | Completed ShutdownLeaks collections in process 8688
[task 2018-10-10T05:49:38.426Z] 05:49:38     INFO - GECKO(8609) | Completed ShutdownLeaks collections in process 8609
[task 2018-10-10T05:49:38.426Z] 05:49:38     INFO - TEST-START | Shutdown
[task 2018-10-10T05:49:38.427Z] 05:49:38     INFO - Browser Chrome Test Summary
[task 2018-10-10T05:49:38.427Z] 05:49:38     INFO - Passed:  7
[task 2018-10-10T05:49:38.429Z] 05:49:38     INFO - Failed:  2
[task 2018-10-10T05:49:38.430Z] 05:49:38     INFO - Todo:    0
[task 2018-10-10T05:49:38.435Z] 05:49:38     INFO - Mode:    e10s
[task 2018-10-10T05:49:38.436Z] 05:49:38     INFO - *** End BrowserChrome Test Results ***
[task 2018-10-10T05:49:38.908Z] 05:49:38     INFO - GECKO(8609) | 1539150578905	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
[task 2018-10-10T05:49:38.910Z] 05:49:38     INFO - GECKO(8609) | 1539150578905	Marionette	INFO	Stopped listening on port 2828
[task 2018-10-10T05:49:38.914Z] 05:49:38     INFO - GECKO(8609) | 1539150578905	Marionette	DEBUG	Remote service is inactive
[task 2018-10-10T05:49:39.264Z] 05:49:39     INFO - TEST-INFO | Main app process: exit 0
[task 2018-10-10T05:49:39.265Z] 05:49:39     INFO - runtests.py | Application ran for: 0:00:53.644445
[task 2018-10-10T05:49:39.266Z] 05:49:39     INFO - zombiecheck | Reading PID log: /tmp/tmp208KbJpidlog
[task 2018-10-10T05:49:39.266Z] 05:49:39     INFO - ==> process 8609 launched child process 8632
[task 2018-10-10T05:49:39.267Z] 05:49:39     INFO - ==> process 8609 launched child process 8688
[task 2018-10-10T05:49:39.267Z] 05:49:39     INFO - ==> process 8609 launched child process 8709
[task 2018-10-10T05:49:39.268Z] 05:49:39     INFO - ==> process 8609 launched child process 8759
[task 2018-10-10T05:49:39.269Z] 05:49:39     INFO - ==> process 8609 launched child process 8794
[task 2018-10-10T05:49:39.270Z] 05:49:39     INFO - ==> process 8609 launched child process 8803
[task 2018-10-10T05:49:39.271Z] 05:49:39     INFO - ==> process 8609 launched child process 8845
[task 2018-10-10T05:49:39.272Z] 05:49:39     INFO - ==> process 8609 launched child process 8858
[task 2018-10-10T05:49:39.273Z] 05:49:39     INFO - ==> process 8609 launched child process 8890
[task 2018-10-10T05:49:39.273Z] 05:49:39     INFO - ==> process 8609 launched child process 8912
[task 2018-10-10T05:49:39.275Z] 05:49:39     INFO - zombiecheck | Checking for orphan process with PID: 8912
[task 2018-10-10T05:49:39.283Z] 05:49:39     INFO - zombiecheck | Checking for orphan process with PID: 8803
[task 2018-10-10T05:49:39.284Z] 05:49:39     INFO - zombiecheck | Checking for orphan process with PID: 8709
[task 2018-10-10T05:49:39.284Z] 05:49:39     INFO - zombiecheck | Checking for orphan process with PID: 8890
[task 2018-10-10T05:49:39.286Z] 05:49:39     INFO - zombiecheck | Checking for orphan process with PID: 8845
[task 2018-10-10T05:49:39.286Z] 05:49:39     INFO - zombiecheck | Checking for orphan process with PID: 8688
[task 2018-10-10T05:49:39.286Z] 05:49:39     INFO - zombiecheck | Checking for orphan process with PID: 8759
[task 2018-10-10T05:49:39.287Z] 05:49:39     INFO - zombiecheck | Checking for orphan process with PID: 8632
[task 2018-10-10T05:49:39.287Z] 05:49:39     INFO - zombiecheck | Checking for orphan process with PID: 8794
[task 2018-10-10T05:49:39.288Z] 05:49:39     INFO - zombiecheck | Checking for orphan process with PID: 8858
[task 2018-10-10T05:49:39.289Z] 05:49:39     INFO - Stopping web server
[task 2018-10-10T05:49:39.290Z] 05:49:39     INFO - Stopping web socket server
[task 2018-10-10T05:49:39.306Z] 05:49:39     INFO - Stopping ssltunnel
[task 2018-10-10T05:49:39.314Z] 05:49:39  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2018-10-10T05:49:39.315Z] 05:49:39     INFO - runtests.py | Running tests: end.
[task 2018-10-10T05:49:39.337Z] 05:49:39     INFO - Buffered messages finished
[task 2018-10-10T05:49:39.338Z] 05:49:39     INFO - Running manifest: security/manager/ssl/tests/mochitest/browser/browser.ini
[task 2018-10-10T05:49:39.338Z] 05:49:39     INFO - The following extra prefs will be set:
[task 2018-10-10T05:49:39.339Z] 05:49:39     INFO -   dom.animations-api.core.enabled=true
[task 2018-10-10T05:49:39.340Z] 05:49:39     INFO -   dom.animations-api.timelines.enabled=true
[task 2018-10-10T05:49:39.377Z] 05:49:39     INFO -  Setting pipeline to PAUSED ...
[task 2018-10-10T05:49:39.377Z] 05:49:39     INFO -  Pipeline is PREROLLING ...
[task 2018-10-10T05:49:39.381Z] 05:49:39     INFO -  Pipeline is PREROLLED ...
[task 2018-10-10T05:49:39.381Z] 05:49:39     INFO -  Setting pipeline to PLAYING ...
[task 2018-10-10T05:49:39.381Z] 05:49:39     INFO -  New clock: GstSystemClock
[task 2018-10-10T05:49:39.419Z] 05:49:39     INFO -  Got EOS from element "pipeline0".
[task 2018-10-10T05:49:39.419Z] 05:49:39     INFO -  Execution ended after 0:00:00.033208652
[task 2018-10-10T05:49:39.419Z] 05:49:39     INFO -  Setting pipeline to PAUSED ...
[task 2018-10-10T05:49:39.420Z] 05:49:39     INFO -  Setting pipeline to READY ...
[task 2018-10-10T05:49:39.420Z] 05:49:39     INFO -  (gst-launch-1.0:8939): GStreamer-CRITICAL **: gst_object_unref: assertion '((GObject *) object)->ref_count > 0' failed
[task 2018-10-10T05:49:39.420Z] 05:49:39     INFO -  Setting pipeline to NULL ...
[task 2018-10-10T05:49:39.420Z] 05:49:39     INFO -  Freeing pipeline ...
[task 2018-10-10T05:49:39.702Z] 05:49:39     INFO -  pk12util: PKCS12 IMPORT SUCCESSFUL
[task 2018-10-10T05:49:39.751Z] 05:49:39     INFO - MochitestServer : launching [u'/builds/worker/workspace/build/tests/bin/xpcshell', '-g', '/builds/worker/workspace/build/application/firefox', '-f', '/builds/worker/workspace/build/tests/bin/components/httpd.js', '-e', "const _PROFILE_PATH = '/tmp/tmpxXhKyk.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', '/builds/worker/workspace/build/tests/mochitest/server.js']
[task 2018-10-10T05:49:39.751Z] 05:49:39     INFO - runtests.py | Server pid: 8961
[task 2018-10-10T05:49:39.772Z] 05:49:39     INFO - runtests.py | Websocket server pid: 8964
[task 2018-10-10T05:49:39.792Z] 05:49:39     INFO - runtests.py | SSL tunnel pid: 8968
[task 2018-10-10T05:49:39.894Z] 05:49:39     INFO - runtests.py | Running with e10s: True
[task 2018-10-10T05:49:39.894Z] 05:49:39     INFO - runtests.py | Running with serviceworker_e10s: False
[task 2018-10-10T05:49:39.895Z] 05:49:39     INFO - runtests.py | Running tests: start.
[task 2018-10-10T05:49:39.895Z] 05:49:39     INFO - 
[task 2018-10-10T05:49:39.915Z] 05:49:39     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmpxXhKyk.mozrunner
[task 2018-10-10T05:49:39.934Z] 05:49:39     INFO - runtests.py | Application pid: 8988
[task 2018-10-10T05:49:39.936Z] 05:49:39     INFO - TEST-INFO | started process GECKO(8988)
[task 2018-10-10T05:49:40.901Z] 05:49:40     INFO - GECKO(8988) | 1539150580896	Marionette	DEBUG	Received observer notification profile-after-change
[task 2018-10-10T05:49:40.970Z] 05:49:40     INFO - GECKO(8988) | 1539150580964	Marionette	DEBUG	Received observer notification command-line-startup
[task 2018-10-10T05:49:40.972Z] 05:49:40     INFO - GECKO(8988) | 1539150580965	Marionette	DEBUG	Received observer notification nsPref:changed
[task 2018-10-10T05:49:40.972Z] 05:49:40     INFO - GECKO(8988) | 1539150580965	Marionette	DEBUG	Init aborted (running=false, enabled=true, finalUIStartup=false)
[task 2018-10-10T05:49:41.317Z] 05:49:41     INFO - GECKO(8988) | 1539150581311	Marionette	DEBUG	Received observer notification toplevel-window-ready
[task 2018-10-10T05:49:42.530Z] 05:49:42     INFO - GECKO(8988) | 1539150582515	Marionette	DEBUG	Received observer notification sessionstore-windows-restored
[task 2018-10-10T05:49:42.532Z] 05:49:42     INFO - GECKO(8988) | 1539150582515	Marionette	DEBUG	Waiting for delayed startup...
[task 2018-10-10T05:49:42.971Z] 05:49:42     INFO - GECKO(8988) | 1539150582967	Marionette	DEBUG	Waiting for startup tests...
[task 2018-10-10T05:49:43.040Z] 05:49:43     INFO - GECKO(8988) | 1539150583034	Marionette	INFO	Listening on port 2828
[task 2018-10-10T05:49:43.042Z] 05:49:43     INFO - GECKO(8988) | 1539150583034	Marionette	DEBUG	Remote service is active
[task 2018-10-10T05:49:43.058Z] 05:49:43     INFO - GECKO(8988) | 1539150583053	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:57036
[task 2018-10-10T05:49:43.075Z] 05:49:43     INFO - GECKO(8988) | 1539150583065	Marionette	DEBUG	Closed connection 0
[task 2018-10-10T05:49:43.076Z] 05:49:43     INFO - GECKO(8988) | 1539150583066	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:57038
[task 2018-10-10T05:49:43.097Z] 05:49:43     INFO - GECKO(8988) | 1539150583093	Marionette	TRACE	1 -> [0,1,"WebDriver:NewSession",{}]
[task 2018-10-10T05:49:43.245Z] 05:49:43     INFO - GECKO(8988) | 1539150583241	Marionette	DEBUG	[4294967297] Frame script loaded
[task 2018-10-10T05:49:43.266Z] 05:49:43     INFO - GECKO(8988) | 1539150583263	Marionette	DEBUG	[4294967297] Frame script registered
[task 2018-10-10T05:49:43.287Z] 05:49:43     INFO - GECKO(8988) | 1539150583282	Marionette	TRACE	1 <- [1,1,null,{"sessionId":"2088ec03-70be-4480-8e92-f30129fb17fb","capabilities":{"browserName":"firefox","browserVersion":"64.0a ... ssID":8988,"moz:profile":"/tmp/tmpxXhKyk.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2018-10-10T05:49:43.370Z] 05:49:43     INFO - GECKO(8988) | 1539150583367	Marionette	TRACE	1 -> [0,2,"Addon:Install",{"path":"/tmp/tmphnjayp.zip","temporary":false}]
[task 2018-10-10T05:49:43.496Z] 05:49:43     INFO - GECKO(8988) | 1539150583490	Marionette	TRACE	1 <- [1,2,null,{"value":"[e-mail]"}]
[task 2018-10-10T05:49:43.544Z] 05:49:43     INFO - GECKO(8988) | 1539150583539	Marionette	TRACE	1 -> [0,3,"Addon:Install",{"path":"/tmp/tmpZ5ssZV.zip","temporary":false}]
[task 2018-10-10T05:49:43.633Z] 05:49:43     INFO - GECKO(8988) | 1539150583628	Marionette	TRACE	1 <- [1,3,null,{"value":"[e-mail]"}]
[task 2018-10-10T05:49:43.634Z] 05:49:43     INFO - GECKO(8988) | 1539150583630	Marionette	TRACE	1 -> [0,4,"Marionette:GetContext",{}]
[task 2018-10-10T05:49:43.636Z] 05:49:43     INFO - GECKO(8988) | 1539150583631	Marionette	TRACE	1 <- [1,4,null,{"value":"content"}]
[task 2018-10-10T05:49:43.638Z] 05:49:43     INFO - GECKO(8988) | 1539150583633	Marionette	TRACE	1 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-10-10T05:49:43.643Z] 05:49:43     INFO - GECKO(8988) | 1539150583637	Marionette	TRACE	1 <- [1,5,null,{"value":null}]
[task 2018-10-10T05:49:43.646Z] 05:49:43     INFO - GECKO(8988) | 1539150583641	Marionette	TRACE	1 -> [0,6,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":[{"testUrl":"about:blank","flavor":"browser-chr ...  new CustomEvent(\"mochitest-load\", {\"detail\": [flavor, url]});\nwin.dispatchEvent(ev);","sandbox":"default","line":1754}]
[task 2018-10-10T05:49:43.667Z] 05:49:43     INFO - GECKO(8988) | 1539150583663	Marionette	TRACE	1 <- [1,6,null,{"value":null}]
[task 2018-10-10T05:49:43.716Z] 05:49:43     INFO - GECKO(8988) | 1539150583710	Marionette	TRACE	1 -> [0,7,"Marionette:SetContext",{"value":"content"}]
[task 2018-10-10T05:49:43.717Z] 05:49:43     INFO - GECKO(8988) | 1539150583711	Marionette	TRACE	1 <- [1,7,null,{"value":null}]
[task 2018-10-10T05:49:43.721Z] 05:49:43     INFO - GECKO(8988) | 1539150583715	Marionette	TRACE	1 -> [0,8,"WebDriver:DeleteSession",{}]
[task 2018-10-10T05:49:43.722Z] 05:49:43     INFO - GECKO(8988) | 1539150583718	Marionette	TRACE	1 <- [1,8,null,{"value":null}]
[task 2018-10-10T05:49:43.724Z] 05:49:43     INFO - runtests.py | Waiting for browser...
[task 2018-10-10T05:49:43.727Z] 05:49:43     INFO - GECKO(8988) | 1539150583723	Marionette	DEBUG	Closed connection 1
[task 2018-10-10T05:49:43.867Z] 05:49:43     INFO - *** Start BrowserChrome Test Results ***
[task 2018-10-10T05:49:43.908Z] 05:49:43     INFO - checking window state
[task 2018-10-10T05:49:43.952Z] 05:49:43     INFO - TEST-START | security/manager/ssl/tests/mochitest/browser/browser_bug627234_perwindowpb.js
[task 2018-10-10T05:49:46.479Z] 05:49:46     INFO - GECKO(8988) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2018-10-10T05:49:46.481Z] 05:49:46     INFO - GECKO(8988) | MEMORY STAT | vsize 609MB | residentFast 268MB | heapAllocated 101MB
[task 2018-10-10T05:49:46.482Z] 05:49:46     INFO - TEST-OK | security/manager/ssl/tests/mochitest/browser/browser_bug627234_perwindowpb.js | took 2521ms

Backout:
https://hg.mozilla.org/mozilla-central/rev/2d2dee08739f0293e1ac9e815a9acb80621c3bc4

Comment 41

[Dorel Luca [:dluca]]

As soon as it landed on inbound this bug started to go on a exception loop, which later turned into failures BC16 failures.

Started here:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&group_state=expanded&searchStr=linux,x64,asan,mochitests,with,e10s,test-linux64-asan%2Fopt-mochitest-browser-chrome-e10s-16,m-e10s(bc16)&revision=72e7ef77480d0845ceabb5d3747a5523db6bda9d


Log:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&group_state=expanded&searchStr=linux,x64,asan,mochitests,with,e10s,test-linux64-asan%2Fopt-mochitest-browser-chrome-e10s-16,m-e10s(bc16)&revision=72e7ef77480d0845ceabb5d3747a5523db6bda9d

Comment 42

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Failure log for comment 41 (not for the exception): https://treeherder.mozilla.org/logviewer.html#?job_id=204425459&repo=mozilla-inbound

Comment 43

[Eliza Balazs [:ebalazs_]]

Also this push: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&resultStatus=testfailed,busted,exception,retry,usercancel,running,pending,runnable&searchStr=windows,7,opt,mochitests,with,e10s,test-windows7-32%2Fopt-mochitest-browser-chrome-e10s-5,m-e10s(bc5)&selectedJob=204461491&revision=72e7ef77480d0845ceabb5d3747a5523db6bda9d

that was backed out, caused this perma failure https://treeherder.mozilla.org/logviewer.html#?job_id=204461491&repo=mozilla-inbound&lineNumber=2289

erahm: Please have a look at this as well. Thanks!

Comment 44

[Eric Rahm [:erahm]]

(In reply to Dorel Luca [:dluca] from comment #40)
> Backed out 4 changesets (bug 1470280) for browser-chrome failure in
> layout/xul/test/browser_bug703210.js. a=backout

This appears to be a known intermittent, I'm going to fully disabling on linux in bug 138242.

Comment 45

[Eric Rahm [:erahm]]

(In reply to Dorel Luca [:dluca] from comment #41)
> As soon as it landed on inbound this bug started to go on a exception loop,
> which later turned into failures BC16 failures.

This is pretty surprising, I'm not sure how this could break one of the test machines. I'll see if I can repro on try, it seems to be limited in scope to asan builds.

Comment 46

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/0e3213694920
Part 1: Make browser_preferences_usage.js less brittle. r=kmag
https://hg.mozilla.org/integration/mozilla-inbound/rev/084f2ef96e42
Part 2: Just use osPid to check for new process. r=mconley
https://hg.mozilla.org/integration/mozilla-inbound/rev/b9f693881356
Part 3: Use the default process count in browser_ext_slow_script.js. r=kmag
https://hg.mozilla.org/integration/mozilla-inbound/rev/b9b91fd9b3f0
Part 4: Increase process count to 8 on Nightly. r=felipe

Comment 47

[Tiberius Oros[:tiberius_oros]]

https://hg.mozilla.org/mozilla-central/rev/0e3213694920
https://hg.mozilla.org/mozilla-central/rev/084f2ef96e42
https://hg.mozilla.org/mozilla-central/rev/b9f693881356
https://hg.mozilla.org/mozilla-central/rev/b9b91fd9b3f0

Comment 48

[Robert AB]

Default number of content processes should be dependent on the PC resources and the average number of pages opened by the user. 

If computer has a lot of RAM, then 8 content processes are OK. But some users have only 4 GB RAM or less and they are opening just few pages. In this case default number of processes should be 1-2.

Comment 49

[Kris Maglione [:kmag]]

(In reply to Robert Ab from comment #48)
> Default number of content processes should be dependent on the PC resources
> and the average number of pages opened by the user. 

The only factor in determining the number of content processes in the near future will be the number of origins loaded at a time, regardless of system resources. Scaling the default maximum number of processes is the first step towards enabling that, and therefore will not depend on any other factors.