1472369 - Intermittent browser/base/content/test/performance/browser_startup_content.js | should have no unexpected components loaded on content process startup - Got 1, expected 0

Status: RESOLVED INCOMPLETE

(Core :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: dluca [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=185691429&repo=autoland

https://queue.taskcluster.net/v1/task/Y3oQINOxS-yPwl3AsaJEjw/runs/0/artifacts/public/logs/live_backing.log

TEST-START | browser/base/content/test/performance/browser_startup_content.js
23:44:28     INFO -  13 INFO Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 170}]
23:44:28     INFO -  14 INFO Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 170}]
23:44:29     INFO -  15 INFO TEST-PASS | browser/base/content/test/performance/browser_startup_content.js | should have no unexpected components loaded on content process startup -
23:44:29     INFO -  16 INFO TEST-PASS | browser/base/content/test/performance/browser_startup_content.js | all components whitelist entries should have been used -
23:44:29     INFO -  17 INFO TEST-PASS | browser/base/content/test/performance/browser_startup_content.js | should have no unexpected modules loaded on content process startup -
23:44:29     INFO -  18 INFO TEST-PASS | browser/base/content/test/performance/browser_startup_content.js | all modules whitelist entries should have been used -
23:44:29     INFO -  19 INFO Leaving test bound
23:44:29     INFO -  GECKO(4984) | MEMORY STAT | vsize 695MB | vsizeMaxContiguous 778MB | residentFast 211MB | heapAllocated 119MB
23:44:29     INFO -  20 INFO TEST-OK | browser/base/content/test/performance/browser_startup_content.js | took 351ms
23:44:29     INFO -  21 INFO checking window state
23:44:29     INFO -  22 INFO TEST-START | browser/base/content/test/performance/browser_startup_content.js
23:44:29     INFO -  TEST-INFO | started process screenshot
23:44:29     INFO -  TEST-INFO | screenshot: exit 0
23:44:29     INFO -  Buffered messages logged at 23:44:29
23:44:29     INFO -  23 INFO Entering test bound
23:44:29     INFO -  Buffered messages finished
23:44:29    ERROR -  24 INFO TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_content.js | should have no unexpected components loaded on content process startup - Got 1, expected 0
23:44:29     INFO -  Stack trace:
23:44:29     INFO -  chrome://mochikit/content/browser-test.js:test_is:1300
23:44:29     INFO -  chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_content.js:null:148
23:44:29     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest/<:1098
23:44:29     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest:1089
23:44:29     INFO -  chrome://mochikit/content/browser-test.js:nextTest/<:986
23:44:29     INFO -  chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
23:44:29     INFO -  Not taking screenshot here: see the one that was previously logged
23:44:29    ERROR -  25 INFO TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_content.js | Unexpected components loaded during content process startup: nsAsyncShutdown.js -
23:44:29     INFO -  Stack trace:
23:44:29     INFO -  chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_content.js:null:152
23:44:29     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest/<:1098
23:44:29     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest:1089
23:44:29     INFO -  chrome://mochikit/content/browser-test.js:nextTest/<:986
23:44:29     INFO -  chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
23:44:29     INFO -  26 INFO Stack that loaded nsAsyncShutdown.js:
23:44:29     INFO -  27 INFO JavaScript stack is empty
23:44:29     INFO -  28 INFO TEST-PASS | browser/base/content/test/performance/browser_startup_content.js | all components whitelist entries should have been used -
23:44:29     INFO -  29 INFO TEST-PASS | browser/base/content/test/performance/browser_startup_content.js | should have no unexpected modules loaded on content process startup -
23:44:29     INFO -  30 INFO TEST-PASS | browser/base/content/test/performance/browser_startup_content.js | all modules whitelist entries should have been used -
23:44:29     INFO -  31 INFO Leaving test bound
23:44:29     INFO -  GECKO(4984) | MEMORY STAT | vsize 696MB | vsizeMaxContiguous 778MB | residentFast 212MB | heapAllocated 120MB
23:44:29     INFO -  32 INFO TEST-OK | browser/base/content/test/performance/browser_startup_content.js | took 338ms
23:44:29     INFO -  33 INFO checking window state
23:44:30     INFO -  GECKO(4984) | Completed ShutdownLeaks collections in process 2372
23:44:30     INFO -  GECKO(4984) | Completed ShutdownLeaks collections in process 4280
23:44:30     INFO -  GECKO(4984) | Completed ShutdownLeaks collections in process 5676
23:44:30     INFO -  GECKO(4984) | Completed ShutdownLeaks collections in process 5524
23:44:30     INFO -  GECKO(4984) | Completed ShutdownLeaks collections in process 1484
23:44:30     INFO -  GECKO(4984) | Completed ShutdownLeaks collections in process 5616
23:44:31     INFO -  GECKO(4984) | Completed ShutdownLeaks collections in process 4984
23:44:31     INFO -  34 INFO TEST-START | Shutdown
23:44:31     INFO -  35 INFO Browser Chrome Test Summary
23:44:31     INFO -  36 INFO Passed:  11
23:44:31  WARNING -  37 INFO Failed:  2
23:44:31  WARNING -  One or more unittests failed.
23:44:31     INFO -  38 INFO Todo:    0
23:44:31     INFO -  39 INFO Mode:    e10s
23:44:31     INFO -  40 INFO *** End BrowserChrome Test Results ***
23:44:31     INFO -  GECKO(4984) | [Parent 4984, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
23:44:31     INFO -  GECKO(4984) | [Child 5676, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
23:44:31     INFO -  GECKO(4984) | [Child 5676, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
23:44:31     INFO -  GECKO(4984) | [Parent 4984, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
23:44:31     INFO -  GECKO(4984) | [Child 1484, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
23:44:31     INFO -  GECKO(4984) | [Parent 4984, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
23:44:31     INFO -  GECKO(4984) | [Child 2372, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
23:44:31     INFO -  GECKO(4984) | [Child 2372, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
23:44:31     INFO -  GECKO(4984) | [Parent 4984, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
23:44:31     INFO -  GECKO(4984) | [Child 4280, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
23:44:31     INFO -  GECKO(4984) | [Parent 4984, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
23:44:31     INFO -  GECKO(4984) | [Child 5616, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
23:44:31     INFO -  GECKO(4984) | [Parent 4984, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
23:44:31     INFO -  GECKO(4984) | [Parent 4984, Gecko_IOThread] WARNING: file z:/build/build/src/ipc/chromium/src/base/process_util_win.cc, line 188
23:44:31     INFO -  GECKO(4984) | 1530315871401	Marionette	DEBUG	Received observer notification xpcom-will-shutdown
23:44:31     INFO -  GECKO(4984) | 1530315871401	Marionette	INFO	Stopped listening on port 2828
23:44:31     INFO -  GECKO(4984) | 1530315871401	Marionette	DEBUG	Remote service is inactive
23:44:31     INFO -  TEST-INFO | Main app process: exit 0
23:44:31     INFO -  runtests.py | Application ran for: 0:00:06.130000
23:44:31     INFO -  zombiecheck | Reading PID log: c:\users\task_1530315328\appdata\local\temp\tmpbquervpidlog
23:44:31     INFO -  ==> process 4984 launched child process 5524 ("Z:\task_1530315328\build\application\firefox\firefox.exe" -contentproc --channel="4984.0.1040573059\772365978" -childID 1 -isForBrowser -prefsHandle 1728 -prefsLen 16301 -schedulerPrefs 0001,2 -parentBuildID 20180629213431 -greomni "Z:\task_1530315328\build\application\firefox\omni.ja" -appomni "Z:\task_1530315328\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1530315328\build\application\firefox\browser" - 4984 "\\.\pipe\gecko-crash-server-pipe.4984" 1704 tab)
23:44:31     INFO -  ==> process 4984 launched child process 5616 ("Z:\task_1530315328\build\application\firefox\firefox.exe" -contentproc --channel="4984.6.326595040\967479059" -childID 2 -isForBrowser -prefsHandle 2088 -prefsLen 16301 -schedulerPrefs 0001,2 -parentBuildID 20180629213431 -greomni "Z:\task_1530315328\build\application\firefox\omni.ja" -appomni "Z:\task_1530315328\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1530315328\build\application\firefox\browser" - 4984 "\\.\pipe\gecko-crash-server-pipe.4984" 2112 tab)
23:44:31     INFO -  ==> process 4984 launched child process 5676 ("Z:\task_1530315328\build\application\firefox\firefox.exe" -contentproc --channel="4984.12.347694803\1126775248" -childID 3 -isForBrowser -prefsHandle 2076 -prefsLen 17611 -schedulerPrefs 0001,2 -parentBuildID 20180629213431 -greomni "Z:\task_1530315328\build\application\firefox\omni.ja" -appomni "Z:\task_1530315328\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1530315328\build\application\firefox\browser" - 4984 "\\.\pipe\gecko-crash-server-pipe.4984" 2072 tab)
23:44:31     INFO -  ==> process 4984 launched child process 4280 ("Z:\task_1530315328\build\application\firefox\firefox.exe" -contentproc --channel="4984.18.1189630296\719076365" -childID 4 -isForBrowser -prefsHandle 3008 -prefsLen 22490 -schedulerPrefs 0001,2 -parentBuildID 20180629213431 -greomni "Z:\task_1530315328\build\application\firefox\omni.ja" -appomni "Z:\task_1530315328\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1530315328\build\application\firefox\browser" - 4984 "\\.\pipe\gecko-crash-server-pipe.4984" 3020 tab)
23:44:31     INFO -  ==> process 4984 launched child process 2372 ("Z:\task_1530315328\build\application\firefox\firefox.exe" -contentproc --channel="4984.24.405906995\1707626110" -childID 5 -isForBrowser -prefsHandle 3192 -prefsLen 22490 -schedulerPrefs 0001,2 -parentBuildID 20180629213431 -greomni "Z:\task_1530315328\build\application\firefox\omni.ja" -appomni "Z:\task_1530315328\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1530315328\build\application\firefox\browser" - 4984 "\\.\pipe\gecko-crash-server-pipe.4984" 3228 tab)
23:44:31     INFO -  ==> process 4984 launched child process 1484 ("Z:\task_1530315328\build\application\firefox\firefox.exe" -contentproc --channel="4984.30.62137906\39227477" -childID 6 -isForBrowser -prefsHandle 3184 -prefsLen 22490 -schedulerPrefs 0001,2 -parentBuildID 20180629213431 -greomni "Z:\task_1530315328\build\application\firefox\omni.ja" -appomni "Z:\task_1530315328\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1530315328\build\application\firefox\browser" - 4984 "\\.\pipe\gecko-crash-server-pipe.4984" 3364 tab)
23:44:31     INFO -  zombiecheck | Checking for orphan process with PID: 2372
23:44:31     INFO -  zombiecheck | Checking for orphan process with PID: 1484
23:44:31     INFO -  zombiecheck | Checking for orphan process with PID: 5676
23:44:31     INFO -  zombiecheck | Checking for orphan process with PID: 5616
23:44:31     INFO -  zombiecheck | Checking for orphan process with PID: 5524
23:44:31     INFO -  zombiecheck | Checking for orphan process with PID: 4280
23:44:31     INFO -  Stopping web server
23:44:31     INFO -  Stopping web socket server
23:44:31     INFO -  Stopping ssltunnel
23:44:31     INFO -  leakcheck | refcount logging is off, so leaks can't be detected!
23:44:31     INFO -  runtests.py | Running tests: end.
23:44:31     INFO -  Buffered messages finished
23:44:31     INFO -  TEST-INFO | checking window state
23:44:31     INFO -  Browser Chrome Test Summary
23:44:31     INFO -  	Passed: 11
23:44:31  WARNING -  	Failed: 2
23:44:31  WARNING -  One or more unittests failed.
23:44:31     INFO -  	Todo: 0
23:44:31     INFO -  	Mode: e10s
23:44:31     INFO -  *** End BrowserChrome Test Results ***
23:44:31     INFO -  Buffered messages finished
23:44:31     INFO -  SUITE-END | took 6s

Comment 1

[Intermittent Failures Robot]

7 failures in 718 pushes (0.01 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 4
* mozilla-central: 3

Platform breakdown:
* windows7-32: 6
* windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1472369&startday=2018-06-25&endday=2018-07-01&tree=trunk

Comment 2

[Intermittent Failures Robot]

22 failures in 120 pushes (0.183 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 17
* mozilla-central: 5

Platform breakdown:
* windows7-32: 9
* windows10-64: 6
* linux64: 3
* osx-10-10: 2
* windows7-32-nightly: 1
* windows10-64-nightly: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1472369&startday=2018-07-05&endday=2018-07-05&tree=trunk

Comment 3

[Stefan Hindli [:stefan_hindli]]

Over the last 7 days there are 32 failures present on this bug. These happen on linux64, osx-10-10, windows10-64, windows10-64-nightly, windows7-32, windows7-32-nightly.

Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#?job_id=186767185&repo=mozilla-inbound&lineNumber=1114

03:13:29     INFO -  Buffered messages finished
03:13:29    ERROR -  24 INFO TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_content.js | should have no unexpected components loaded on content process startup - Got 1, expected 0
03:13:29     INFO -  Stack trace:
03:13:29     INFO -  chrome://mochikit/content/browser-test.js:test_is:1300
03:13:29     INFO -  chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_content.js:null:147
03:13:29     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest/<:1098
03:13:29     INFO -  chrome://mochikit/content/browser-test.js:Tester_execTest:1089
03:13:29     INFO -  chrome://mochikit/content/browser-test.js:nextTest/<:986
03:13:29     INFO -  chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
03:13:29     INFO -  Not taking screenshot here: see the one that was previously logged
03:13:29    ERROR -  25 INFO TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_content.js | Unexpected components loaded during content process startup: nsAsyncShutdown.js -

Comment 4

[Intermittent Failures Robot]

20 failures in 118 pushes (0.169 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-central: 11
* autoland: 6
* mozilla-inbound: 3

Platform breakdown:
* windows10-64: 10
* windows7-32: 8
* windows7-32-nightly: 1
* windows10-64-nightly: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1472369&startday=2018-07-06&endday=2018-07-06&tree=trunk

Comment 5

[Intermittent Failures Robot]

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

This is the #12 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: 23
* mozilla-central: 20
* mozilla-inbound: 9

Platform breakdown:
* windows10-64: 23
* windows7-32: 19
* linux64: 4
* windows7-32-nightly: 2
* windows10-64-nightly: 2
* osx-10-10: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1472369&startday=2018-07-02&endday=2018-07-08&tree=trunk

Comment 6

[Marissa (Reese) Wood]

Kannan - Would you please take a look at this one and assign to the right person? Thank you!  Reese

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 2

Platform breakdown:
* windows7-32: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1472369&startday=2018-07-09&endday=2018-07-15&tree=trunk

Comment 8

[Kannan Vijayan [:djvj]]

Sorry for the late reply.  This bug is hard to assign because it seems like an issue with races/timing or improper initialization of global namespaces.  Typically these bugs relate to the frontend C++ or JS and the way that it interacts with the JS VM.  I don't think this bug is likely to be related to the underlying JS engine (but there's a small chance it could be).

I'd prefer if the browserchrome folks took a look at this and ensure that there isn't some issue there before digging in the JS engine.  Needinfoing mconley to get his thoughts.

Comment 9

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

Looks like the nsAsyncShutdown.js component was being loaded pretty early on by some native code.

That appears to have stopped now. This orange hasn't re-appeared in almost 2 weeks. I suspect the frame script lazification stuff kmag and felipe are doing for Fission helped here. I'm going to close this out as INCOMPLETE.