Closed Bug 1483444 Opened 6 years ago Closed 6 years ago

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

Categories

(Firefox :: General, defect, P5)

Product:
Firefox
Component:
General
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 63
Tracking Flags:
Tracking Status
firefox63 --- fixed

People

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

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Bug 1483444: Skip browser_startup_content in verify mode. r=Felipe
46 bytes, text/x-phabricator-request
Felipe
: review+
Details | Review 
Filed by: aiakab [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=194013166&repo=mozilla-central

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

02:51:19     INFO - TEST-START | browser/base/content/test/performance/browser_startup_content.js
02:51:19     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_content.js | should have no unexpected components loaded on content process startup - 
02:51:19     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_content.js | all components whitelist entries should have been used - 
02:51:19     INFO - TEST-INFO | started process screenshot
02:51:19     INFO - TEST-INFO | screenshot: exit 0
02:51:19     INFO - Buffered messages logged at 02:51:19
02:51:19     INFO - Entering test bound 
02:51:19     INFO - Buffered messages finished
02:51:19     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_content.js | should have no unexpected modules loaded on content process startup - Got 3, expected 0
02:51:19     INFO - Stack trace:
02:51:19     INFO - chrome://mochikit/content/browser-test.js:test_is:1308
02:51:19     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_content.js:null:152
02:51:19     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1106
02:51:19     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
02:51:19     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:994
02:51:19     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
02:51:19     INFO - Not taking screenshot here: see the one that was previously logged
02:51:19     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_content.js | Unexpected modules loaded during content process startup: resource://gre/actors/BrowserChild.jsm - 
02:51:19     INFO - Stack trace:
02:51:19     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_content.js:null:156
02:51:19     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1106
02:51:19     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
02:51:19     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:994
02:51:19     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
02:51:19     INFO - Stack that loaded resource://gre/actors/BrowserChild.jsm:
02:51:19     INFO - 
02:51:19     INFO - 0 getActor() ["resource://gre/modules/ActorManagerChild.jsm":68]
02:51:19     INFO - 1 receiveMessage() ["resource://gre/modules/ActorManagerChild.jsm":91]
02:51:19     INFO - 
02:51:19     INFO - Not taking screenshot here: see the one that was previously logged
02:51:19     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_content.js | Unexpected modules loaded during content process startup: resource://gre/actors/UnselectedTabHoverChild.jsm - 
02:51:19     INFO - Stack trace:
02:51:19     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_content.js:null:156
02:51:19     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1106
02:51:19     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
02:51:19     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:994
02:51:19     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
02:51:19     INFO - Stack that loaded resource://gre/actors/UnselectedTabHoverChild.jsm:
02:51:19     INFO - 
02:51:19     INFO - 0 getActor() ["resource://gre/modules/ActorManagerChild.jsm":68]
02:51:19     INFO - 1 handleActorEvent() ["resource://gre/modules/ActorManagerChild.jsm":83]
02:51:19     INFO - 2 handleActorEvent() ["self-hosted":1030]
02:51:19     INFO - 
02:51:19     INFO - Not taking screenshot here: see the one that was previously logged
02:51:19     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_content.js | Unexpected modules loaded during content process startup: resource://gre/actors/WebNavigationChild.jsm - 
02:51:19     INFO - Stack trace:
02:51:19     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_content.js:null:156
02:51:19     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1106
02:51:19     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
02:51:19     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:994
02:51:19     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
02:51:19     INFO - Stack that loaded resource://gre/actors/WebNavigationChild.jsm:
02:51:19     INFO - 
02:51:19     INFO - 0 getActor() ["resource://gre/modules/ActorManagerChild.jsm":68]
02:51:19     INFO - 1 receiveMessage() ["resource://gre/modules/ActorManagerChild.jsm":91]
02:51:19     INFO - 
02:51:19     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_content.js | all modules whitelist entries should have been used - 
02:51:19     INFO - Leaving test bound
Product: Chat Core → Firefox
Version: trunk → unspecified
This seems caused by the patches from bug 1472491.
Blocks: 1472491
Flags: needinfo?(kmaglione+bmo)
This is because TV runs the test multiple times, and these modules get loaded relatively early in content process startup, but not immediately. We should probably just skip this test in verify mode.
Assignee: nobody → kmaglione+bmo
Flags: needinfo?(kmaglione+bmo)
Verify mode runs tests multiple times. In the case of browser_startup_content.js,
this gives extra modules a chance to load before subsequent runs, which leads
to failures.

Since there's no particular reason to run this test in verify mode, the
obvious solution is to just disable it.
Comment on attachment 9001346 [details]
Bug 1483444: Skip browser_startup_content in verify mode. r=Felipe

:Felipe Gomes (needinfo me!) has approved the revision.
Attachment #9001346 - Flags: review+
https://hg.mozilla.org/integration/mozilla-inbound/rev/96e45af1d9de74ecc146b97cac13aecfa9a54867
Bug 1483444: Skip browser_startup_content in verify mode. r=Felipe DONTBUILD
Come to think of it, browser_startup_content.js creates a new process each time, so the fact that it runs multiple times shouldn't affect the result in that way.

I think what this is showing is just that these modules are, in fact, intermittently loaded.

There's a section for intermittently loaded modules in browser_startup_content. Should we move these modules there to investigate, and re-enable the test on test-verify so that it can catch more intermittent loads?
Flags: needinfo?(kmaglione+bmo)
(In reply to :Felipe Gomes (needinfo me!) from comment #6)
> Come to think of it, browser_startup_content.js creates a new process each
> time, so the fact that it runs multiple times shouldn't affect the result in
> that way.

If that's the case, then this is probably due to chaos mode forcing the check to run later than usual.

But I'm not entirely convinced it is the case. It doesn't look like the forceNewProcess hack will actually always force us to use a new process unless the pre-allocated process manager is disabled.
Flags: needinfo?(kmaglione+bmo)
Yup. Confirmed. The preallocated process manager causes the content process to be re-used.
https://hg.mozilla.org/mozilla-central/rev/96e45af1d9de
Status: NEW → RESOLVED
Closed: 6 years ago
status-firefox63: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 63
(In reply to Kris Maglione [:kmag] from comment #8)
> Yup. Confirmed. The preallocated process manager causes the content process
> to be re-used.

I filed bug 1486568 to track that. In the meantime, what do you think about adding the modules originally reported here (BrowserChild.jsm, UnselectedTabHoverChild.jsm and WebNavigationChild.jsm) to the optionally-loaded list [1], and re-enable this test on test-verify?

I was looking into the failures reported in comment 11 and turns out they aren't actually about these modules, they are for LinkHandlerChild.jsm, so it seems likely that bug 1480319 introduced a new real intermittent issue that is being reported to this bug, and since test-verify is not running this test, it wasn't caught earlier.
Flags: needinfo?(kmaglione+bmo)
I think that's a bad idea. The only time any of those modules should ever be loaded in time for those checks is if we reuse a process. Making them optionally-loaded would allow people to introduce regressions which load them earlier.

The same goes for LinkHandlerChild. That should only ever be loaded when a <link> element is inserted, or when we finish parsing a <head> element. Again, those should only ever happen early enough for these checks if we reuse a process, so we don't want to add it to the optional list either.

Given that I don't think TV adds any value, that seems like a pretty bad trade-off.
Flags: needinfo?(kmaglione+bmo)
(In reply to Kris Maglione [:kmag] from comment #13)

> Given that I don't think TV adds any value, that seems like a pretty bad
> trade-off.

TV helps to catch intermittent failures quickly, and given that startup (both of the parent process and of content processes) tends to not happen in a deterministic order, intermittent failures are pretty likely (and we do actually have intermittent failures, as shown by comment 11). So I think TV has a lot of value in this case.
(In reply to Kris Maglione [:kmag] from comment #13)
> I think that's a bad idea. The only time any of those modules should ever be
> loaded in time for those checks is if we reuse a process. Making them
> optionally-loaded would allow people to introduce regressions which load
> them earlier.
> 
> The same goes for LinkHandlerChild. That should only ever be loaded when a
> <link> element is inserted, or when we finish parsing a <head> element.
> Again, those should only ever happen early enough for these checks if we
> reuse a process, so we don't want to add it to the optional list either.
> 
> Given that I don't think TV adds any value, that seems like a pretty bad
> trade-off.

Ok, I agree that adding those modules to the accepted intermittent list is not a good idea, so I won't go in that direction. However, I believe TV is very useful to help avoid some real intermittent failures.

I submitted a patch to bug 1486568 and I verified that, with the patch, this test works properly on test-verify. In that case, are you fine with re-enabling it on TV once bug 1486568 lands?
Flags: needinfo?(kmaglione+bmo)
(In reply to :Felipe Gomes (needinfo me!) from comment #15)
> I submitted a patch to bug 1486568 and I verified that, with the patch, this
> test works properly on test-verify. In that case, are you fine with
> re-enabling it on TV once bug 1486568 lands?

Yup.
Flags: needinfo?(kmaglione+bmo)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: