1301392 - [e10s]slower startup when e10s is enabled with add-ons installed (or not)

Status: RESOLVED INCOMPLETE

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

Description

[Julien L.]

User Agent: Mozilla/5.0 (Windows NT 6.3; Win64; x64; rv:51.0) Gecko/20100101 Firefox/51.0
Build ID: 20160908030434

Steps to reproduce:

I simply launch nightly 51 with e10s enabled.


Actual results:

Firefox window appears then there is a blank "waiting" page. 
After that about:home loads correctly.
If there is one ore more e10s-compatible add-ons installed, the waiting time is longer.


Expected results:

The about:home page should appears quickly as if e10s was disabled.

Comment 1

[Julien L.]

Do you have telemetry data or health reports that show that delay during the startup of nightly 51?

Comment 2

[alex_mayorga]

¡Hola Julien!

Please provide a profile for this bug as detailed at https://developer.mozilla.org/en-US/docs/Mozilla/Performance/Reporting_a_Performance_Problem

¡Gracias!
Alex

Comment 3

[Julien L.]

OK so here come the profiles...

with e10s enabled and only geckoprofiler add-on :

https://cleopatra.io/#report=b99b80cbd6d71ac090f8154e3562f62566b0316d

with e10s enabled and 4 add-ons (geckoprofiler, fireftp, ublock origin 

and gtranslate, compatibles with e10s):

https://cleopatra.io/#report=67cd655a26d27c3c16e06c17e112bfafe1707119

with e10s disabled and only geckoprofiler add-on :

https://cleopatra.io/#report=ad359b29b191ebe0a34c854ccf332690c35532d7

with e10s disabled and the same 4 add-ons :

https://cleopatra.io/#report=c30723b14fa73c96c484d36a650f6a5ec79c6d4c

Comment 4

[Julien L.]

But I guess we could have better results if we could compare health reports of users who use firefox 48/49 and e10s and users who don't use e10s for these versions of FF.
Because that issue is also with version 48 for me.

Comment 5

[alex_mayorga]

¡Hola Benoit!

Could you please check out the profiles at https://bugzilla.mozilla.org/show_bug.cgi?id=1301392#c3 ?

Does anything jump at you that resembles a bug? If so, could you please mark it NEW and pick a component for https://bugzilla.mozilla.org/show_bug.cgi?id=1301392 ?

¡Gracias!
Alex

Comment 6

[Benoit Girard (:BenWa)]

The profile don't capture the startup. The timeline should start at '0' otherwise it's not profiling the startup.

To get a startup profile hit the 'Firefox Restart' button which will re-open firefox and open 2 taps, the first will be the startup profile, the second the shutdown profile which is not relevant for this.

Also include the about:telemetry Simple Measurements for each profile you attach. This will help narrow down which phase got more expensive to help when looking through the profiles.

Comment 7

[Julien L.]

Attachment: e10s_disabled.txt

with e10s disabled and only geckoprofiler add-on :

https://cleopatra.io/#report=924f0278e90f4d1febb041a44189b0857820f3aa

Comment 8

[Julien L.]

Attachment: e10s_disabled_4_addons.txt

with e10s disabled and the same 4 add-ons :

https://cleopatra.io/#report=fa7e7a13ff3d82d90ec92a2a856dc1016ed6a0bb

Comment 9

[Julien L.]

Attachment: e10s_enabled.txt

with e10s enabled and only geckoprofiler add-on :

https://cleopatra.io/#report=cc7ca7875269e535761e2cae73e7b11b7d501dba

Comment 10

[Julien L.]

Attachment: e10s_enabled_4_addons.txt

with e10s enabled and 4 add-ons (geckoprofiler, fireftp, ublock origin 

and gtranslate, compatibles with e10s):

https://cleopatra.io/#report=2f52b0b215a889a6da3bd15bdef506eab9e8f940

Comment 11

[Julien L.]

Does Geckoprofiler measure the loading time between the appearance of the main FF window and about:home? Because the problem is here. As I said there's a blank waiting page before about:home appears when e10s is enabled...

Comment 12

[Benoit Girard (:BenWa)]

There's several markers that can be used as guides (but it's best to confirm with the code to get their exact definition). For instance in your last profile if I'm reading this right your firstLoadURI happened at 3.5 seconds, you got a loading spinner at 4.8 seconds and the page was shown at 5.8 seconds.

Comment 13

[Benoit Girard (:BenWa)]

The content process spends over 2 seconds on startup asking the parent process a few things. If this can be avoided we should be able to bring up about:home a lot faster.

mconley maybe could have a better look at this. I'm not sure who would own the startup sequence in the e10s team.

Comment 14

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

The e10s team is in the process of dissolving, since all Gecko hackers are now technically on the e10s team (we should all now be working to support it, fix it, etc).

I do believe I recall hearing ddurst's interest in start-up performance work, so I'm going to redirect.

Comment 15

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

Note that having the child synchronously ask for things soon after it starts is an anti-pattern we should avoid where possible. The more we can pass to the child (perhaps through command line arguments?) the better.

Comment 16

[David Durst [:ddurst]]

We don't have any dedicated work on this right now, but I'll happily flag this for our team.

Comment 17

[Julien L.]

Hi,
so what's new about this bug?
There is no changes since a month now...
Is it still really unconfirmed?
Thanks :)

Comment 18

[Alex Thayer [:alexical] (she/her)]

As far as I can tell there's two ways we can tackle this:

1: Remove all sync calls originating from the content process that occur before the first non-blank paint. This is probably a good thing to do no matter what, but it's going to take a bit of work. I've outlined below the sync calls that I was able to log on my machine (Windows). Some of them should be trivial to turn into command line arguments, but for some of them we might need some sort of streamlined system for the parent process to create canned responses for larger sync IPC requests (either using shared memory or some other mechanism). And for a few other sync requests, we might need larger and more creative refactorings, since they are intended to notify the parent process of more complex things, or get answers to questions which can't have canned answers.

2: Just defer loading addons until the content process is done loading. I'm not sure what the best way to define "done loading" is - the first non-blank paint? The first DOMContentLoaded? I would appreciate guidance on this. In any case, we would simply remove the extension startup call from the initialization of the parent process, and move it into an async message handler which would receive a message sent by the content process once it is done, however we define that. Behaviorally, this is similar to what happens when e10s is disabled, since we just block until we're done loading about:home. I've tested loading extensions with a simple delay of a few seconds, and it seems to remove the perceived startup delay.

Anyway, more detail on the sync events I found is below:

The Gecko profiler addon doesn't capture the whole startup of the child process, so there's some a few seconds of blocking calls here which help explain the discrepancy between the child process's start time in the 4 addon profile as compared with the gecko-profiler-only profile. However, I think I've got a decent list together of all the blocking calls, at least on Windows.

PCrashReporterConstructor
http://searchfox.org/mozilla-central/rev/225ab0637ed51b8b3f9f4ee2f9c339a37a65b626/dom/ipc/ContentChild.cpp#600

We use this to send information to the parent about us. It seems we are associating a process type with the main thread ID of the child process. We shouldn't need to do this, since at least on Windows we can get the main thread ID of the child process from lpProcessInformation in CreateProcess (https://msdn.microsoft.com/en-us/library/windows/desktop/ms682425(v=vs.85).aspx).

GetProcessAttributes
http://searchfox.org/mozilla-central/rev/225ab0637ed51b8b3f9f4ee2f9c339a37a65b626/dom/ipc/ContentChild.cpp#604

We *should* be able to pass these in as command line arguments, though I'm not positive. The ID is just a value that increments every time we create a new one - nothing magically provided to us by the OS or anything, so I don't see why we couldn't just pass it right in.

ReadPrefsArray
http://searchfox.org/mozilla-central/rev/225ab0637ed51b8b3f9f4ee2f9c339a37a65b626/modules/libpref/Preferences.cpp#563

Somewhat tricky. We could of course serialize it as command line arguments, but it's fairly large. AFAIK we're limited to 8191 characters on Windows, which I think we would exceed(?) We could throw it into a file, or shared memory - I don't know how prefs are handled and if that's at all more sensible than just loading the prefs again ourselves?

GetXPCOMProcessAttributes
http://searchfox.org/mozilla-central/rev/225ab0637ed51b8b3f9f4ee2f9c339a37a65b626/dom/ipc/ContentChild.cpp#994

This also just seems like stuff we should be able to pass as command line arguments. Nothing too complicated that I can see here.

GetGfxVars
http://searchfox.org/mozilla-central/rev/225ab0637ed51b8b3f9f4ee2f9c339a37a65b626/gfx/config/gfxVars.cpp#34

Pretty much the same thing as ReadPrefsArray above.

GetGraphicsFeatureStatus
http://searchfox.org/mozilla-central/rev/225ab0637ed51b8b3f9f4ee2f9c339a37a65b626/widget/GfxInfoBase.cpp#612

I suspect this is going to be one of the more difficult ones to deal with? It's checking to see whether a particular graphics feature is supported on your hardware. We could hardcode a few ones which we know we'll be checkin on startup to be passed in as command line arguments.

GetGraphicsDeviceInitData
http://searchfox.org/mozilla-central/rev/225ab0637ed51b8b3f9f4ee2f9c339a37a65b626/gfx/thebes/gfxPlatform.cpp#2530

This is another one that I suspect we could serialize in some form or another, but again it's probably somewhat large?

PScreenManagerConstructor
http://searchfox.org/mozilla-central/rev/225ab0637ed51b8b3f9f4ee2f9c339a37a65b626/widget/nsScreenManagerProxy.cpp#32

As far as I can tell this isn't doing... anything at all? Not sure. The Recv is in generated code and it just sends IPC_OK(). (http://searchfox.org/mozilla-central/source/__GENERATED__/ipc/ipdl/PContentParent.cpp#156). Haven't tested removing it (theory: this just ensures that the ScreenManager is constructed on the parents' end, for the following call to work?)

GetPrimaryScreen
http://searchfox.org/mozilla-central/rev/225ab0637ed51b8b3f9f4ee2f9c339a37a65b626/widget/nsScreenManagerProxy.cpp#68

This gets a ScreenDetails object with details on your primary display. Again we could pass it in command line arguments, but it's somewhat large.

ScreenRefresh
http://searchfox.org/mozilla-central/rev/225ab0637ed51b8b3f9f4ee2f9c339a37a65b626/widget/ScreenProxy.cpp#155

This seems to just ensure that the data we just got in GetPrimaryScreen is up-to-date. Probably could be skipped in our case.

ReadPermissions
http://searchfox.org/mozilla-central/rev/225ab0637ed51b8b3f9f4ee2f9c339a37a65b626/extensions/cookie/nsPermissionManager.cpp#2914

Again, same story as a number of the ones above. Large array of things which we could serialize in some manner and provide on child process creation.

PLayerTransactionConstructor
(multiple locations, unsure which we're observing)

Not sure what this does - would need to do a bit more research.

AsyncPanZoomEnabled
http://searchfox.org/mozilla-central/rev/225ab0637ed51b8b3f9f4ee2f9c339a37a65b626/gfx/layers/ipc/CompositorBridgeChild.cpp#1095

Returns a simple boolean - this could probably be a command line argument.

ClipboardHasType
http://searchfox.org/mozilla-central/rev/225ab0637ed51b8b3f9f4ee2f9c339a37a65b626/widget/nsClipboardProxy.cpp#145

This seems to come from TextEditor::CanPaste. We're basically just checking if there's any text/unicode data in the clipboard right now. Kind of a strange thing to pass in as a command line argument, but I doubt it would change fast enough for any users to care...?

NotifyIMEFocus
http://searchfox.org/mozilla-central/rev/225ab0637ed51b8b3f9f4ee2f9c339a37a65b626/widget/PuppetWidget.cpp#808

Not 100% sure what this is doing. IME (Input Method Editor) turns user keystrokes into, for instance, Chinese characters, since they can't all be represented on a keyboard. I suspect that since IME might need to run before the keystrokes even get to our process, we need to inform the parent process which interfaces with the IME application so that it can let the IME application know it should start intercepting key strokes?

There's a couple more coming from Javascript that I observed: one coming from pdf.js regarding what's registered as our pdf handler, and one coming from content-sessionStore.js when we do a session restore. The latter seems moderately complicated to resolve.


Anyway, I just figured this is useful information. My two cents is that loading extensions should probably be defered until after first page load, as that's a) fairly intuitive, and b) much simpler to fix. Thoughts?

Comment 19

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

I do know that there's effort to reduce those synchronous messages from content to parent in bug 1303096 - there's currently a patch in review there. We should revisit this when that bug is fixed to see if there's more work we can do.

Comment 20

[Alex Thayer [:alexical] (she/her)]

Thought I'd post a new log of sync waiting times now that that patch landed (this is with three add-ons installed):

21:56:05.394000 - (from main process) creating child process (23 ms waiting for first sync message)
21:56:05.417000 - PContent::Msg_PCrashReporterConstructor  (25 ms waiting)
21:56:05.442000 - end PContent::Msg_PCrashReporterConstructor  (0 ms until next sync message)
21:56:05.442000 - PContent::Msg_GetGfxInfoFeatureStatus  (11 ms waiting)
21:56:05.453000 - end PContent::Msg_GetGfxInfoFeatureStatus  (97 ms until next sync message)
21:56:05.550000 - PContent::Msg_GetGfxVars  (29 ms waiting)
21:56:05.579000 - end PContent::Msg_GetGfxVars  (1 ms until next sync message)
21:56:05.580000 - PContent::Msg_GetGraphicsDeviceInitData  (160 ms waiting)
21:56:05.740000 - end PContent::Msg_GetGraphicsDeviceInitData  (16 ms until next sync message)
21:56:05.756000 - PContent::Msg_PScreenManagerConstructor  (13 ms waiting)
21:56:05.769000 - end PContent::Msg_PScreenManagerConstructor  (0 ms until next sync message)
21:56:05.769000 - PScreenManager::Msg_GetPrimaryScreen  (35 ms waiting)
21:56:05.804000 - end PScreenManager::Msg_GetPrimaryScreen  (0 ms until next sync message)
21:56:05.804000 - PScreenManager::Msg_ScreenRefresh  (19 ms waiting)
21:56:05.823000 - end PScreenManager::Msg_ScreenRefresh  (16 ms until next sync message)
21:56:05.839000 - PCompositorBridge::Msg_GetCompositorOptions  (0 ms waiting)
21:56:05.839000 - end PCompositorBridge::Msg_GetCompositorOptions  (0 ms until next sync message)
21:56:05.839000 - PCompositorBridge::Msg_PLayerTransactionConstructor  (0 ms waiting)
21:56:05.839000 - end PCompositorBridge::Msg_PLayerTransactionConstructor  (18 ms until next sync message)
21:56:05.857000 - PContent::Msg_ReadPermissions  (75 ms waiting)
21:56:05.932000 - end PContent::Msg_ReadPermissions  (84 ms until next sync message)
21:56:06.016000 - PContent::Msg_SyncMessage  (142 ms waiting)
21:56:06.158000 - end PContent::Msg_SyncMessage  (37 ms until next sync message)
21:56:06.195000 - PContent::Msg_ClipboardHasType  (11 ms waiting)
21:56:06.206000 - end PContent::Msg_ClipboardHasType  (1 ms until next sync message)
21:56:06.207000 - PBrowser::Msg_NotifyIMEFocus  (4 ms waiting)
21:56:06.211000 - end PBrowser::Msg_NotifyIMEFocus

Total waiting: 524 ms
Total time overall: 817 ms

Additionally it seems like this is relevant for the thread on dev-platform going around about content process start time. Prior to that patch most of the time between process start and GetXPCOMProcessAttributes was also sync calls.

Thoughts, mconley? I'm not 100% sure in my methodology, but it seems fairly simple. I basically just added special logging calls on process creation and around sync message sending.

Comment 21

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

(In reply to Doug Thayer [:dthayer] from comment #20)
> Thoughts, mconley? I'm not 100% sure in my methodology, but it seems fairly
> simple. I basically just added special logging calls on process creation and
> around sync message sending.

I think this is an excellent approach. Instrumenting > guessing, and the data is already quite interesting. It looks like this is for a window of time where a content process both started, and it began loading some page. Assuming we're trying to optimize for "getting to the point where it's starting to load stuff", I'd want to know exactly where that threshold is. Perhaps before the PScreenManagerConstructor message?

If it's shown in Telemetry that this patch is driving down the content processes "first load URI", I think that's sufficient proof that getting rid of these sync messages is having a positive impact on our users, and we should see how many more things we can fold into the same technique (for example, the graphics and permissions data).

Comment 22

[Alex Thayer [:alexical] (she/her)]

I'm a bit fuzzy, and unfortunately I don't have this reflected in the data above, but what I was using when I initially did this exploration was the first non-blank paint marker, since what was reported was the blank white page that sat around for about a second while waiting for about:home to actually display. IIRC the NotifyIMEFocus message was consistently the last message before the non-blank paint marker, so I believe all of these are relevant.

I can take a bit more time to dive in later when I'm blocked on other things though. :)

Comment 23

[Alex Thayer [:alexical] (she/her)]

One more little note: we should be careful about taking the times shown in that log as a guide for prioritization, since the calls themselves are not what's expensive. It's likely that the calls which take > 100ms to run are just taking that long because they are unfortunate enough to occur at a time where the parent process is too busy for too long. Accordingly, if we were to get rid of the "GetGraphicsDeviceInitData" call, then the "PScreenManagerConstructor" call would probably just take ~160 ms longer.

This isn't to say that we shouldn't get rid of these calls, just that they're probably all equally contributing to the slowness, so whichever calls are easiest to get rid of, regardless of what their time looks like in that log, should probably be prioritized.

Comment 24

[Alex Thayer [:alexical] (she/her)]

Here's a new log with a marker on the first LoadURI and the first non-blank paint:

1486613797860 creating child process
(25 ms...)
1486613797885 sync message PContent::Msg_PCrashReporterConstructor
(19 ms...)
1486613797904 sync message PContent::Msg_GetGfxInfoFeatureStatus
(0 ms...)
1486613797904 sync message end PContent::Msg_PCrashReporterConstructor
(11 ms...)
1486613797915 sync message end PContent::Msg_GetGfxInfoFeatureStatus
(103 ms...)
1486613798018 sync message PContent::Msg_GetGfxVars
(14 ms...)
1486613798032 sync message end PContent::Msg_GetGfxVars
(2 ms...)
1486613798034 sync message PContent::Msg_GetGraphicsDeviceInitData
(132 ms...)
1486613798166 sync message end PContent::Msg_GetGraphicsDeviceInitData
(15 ms...)
1486613798181 sync message end PContent::Msg_PScreenManagerConstructor
(0 ms...)
1486613798181 sync message PScreenManager::Msg_GetPrimaryScreen
(0 ms...)
1486613798181 sync message PContent::Msg_PScreenManagerConstructor
(1 ms...)
1486613798182 sync message end PScreenManager::Msg_GetPrimaryScreen
(0 ms...)
1486613798182 sync message PScreenManager::Msg_ScreenRefresh
(1 ms...)
1486613798183 sync message end PScreenManager::Msg_ScreenRefresh
(19 ms...)
1486613798202 sync message end PCompositorBridge::Msg_PLayerTransactionConstructor
(0 ms...)
1486613798202 sync message PCompositorBridge::Msg_GetCompositorOptions
(0 ms...)
1486613798202 sync message end PCompositorBridge::Msg_GetCompositorOptions
(0 ms...)
1486613798202 sync message PCompositorBridge::Msg_PLayerTransactionConstructor
(12 ms...)
1486613798214 sync message PContent::Msg_ReadPermissions
(1 ms...)
1486613798215 sync message end PContent::Msg_ReadPermissions
(65 ms...)
1486613798280 first load uri
(27 ms...)
1486613798307 sync message PContent::Msg_SyncMessage
(1 ms...)
1486613798308 sync message end PContent::Msg_SyncMessage
(43 ms...)
1486613798351 sync message PContent::Msg_ClipboardHasType
(11 ms...)
1486613798362 sync message end PContent::Msg_ClipboardHasType
(0 ms...)
1486613798362 sync message PBrowser::Msg_NotifyIMEFocus
(6 ms...)
1486613798368 sync message end PBrowser::Msg_NotifyIMEFocus
(8 ms...)
1486613798376 Non-blank paint after 87ms for URL about:home
(9 ms...)
1486613798385 sync message PLayerTransaction::Msg_Update
(1 ms...)
1486613798386 sync message end PLayerTransaction::Msg_Update
(4 ms...)
1486613798390 sync message PLayerTransaction::Msg_Update
(0 ms...)
1486613798390 sync message end PLayerTransaction::Msg_Update


ReadPermissions is the last call before LoadURI, and NotifyIMEFocus is the last call before the first non-blank paint, it seems.

Comment 25

[Julien L.]

Hi! :)
So to simplify, can you do another patch to accelerate the startup and avoid that blank waiting page that appears before about:home?
I made a test with nightly 54 a few days ago and there was no visual difference between nightly and release version (with zero add-ons installed).

Of course, on a high-end computer with SSD and lots of RAM, it's less noticeable.
Thanks for the work done anyway!

Comment 26

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

(In reply to Julien L. from comment #25)
> Hi! :)
> So to simplify, can you do another patch to accelerate the startup and avoid
> that blank waiting page that appears before about:home?

While trying to make content process start time faster, we're also attempting to side-step the issue a bit by pre-loading a content process so that it can be used instantly and on demand. That work is being tracked in bug 1341008, if you'd like to follow along.

Comment 27

[Alex Thayer [:alexical] (she/her)]

@mconley, I still think the fastest way to sidestep this particular issue is to delay loading add-ons until the content process sends an event saying it's okay to do so. I experimented with this on my machine a while back with good results. The simplest way to approximate this as a proof of concept is to just delay loading add-ons for ~500ms. If you disable e10s this seems to be the ordering of things anyway. Thoughts?

Comment 28

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

(In reply to Doug Thayer [:dthayer] from comment #27)
> @mconley, I still think the fastest way to sidestep this particular issue is
> to delay loading add-ons until the content process sends an event saying
> it's okay to do so. I experimented with this on my machine a while back with
> good results. The simplest way to approximate this as a proof of concept is
> to just delay loading add-ons for ~500ms. If you disable e10s this seems to
> be the ordering of things anyway. Thoughts?

That sounds like a good optimization to me, so long as we know when "okay to do so" is.

Hey kmag, do you know if such a thing can be done safely?

Comment 29

[Kris Maglione [:kmag]]

(In reply to Mike Conley (:mconley) (Catching up on reviews and needinfos) from comment #28)
> Hey kmag, do you know if such a thing can be done safely?

Short answer: No.

Long answer: Sort of, and I'm working on it.

The basic problem is that there are certain invariants that we have to maintain. In particular, we need to make sure that certain extension content scripts get a chance to run before any web content scripts in the same pages, and that web request and navigation listeners are dispatched for all relevant events.

There's still a lot that we can do to lazify startup, though. We've already started deferring initializing bindings until they're fist used. The next step is to defer actually loading code for APIs until they're first used.

Once bug 1333990 lands, and we can safely handle asynchronous loading of all content scripts, I'm planning to defer the initialization of more extension content process code, which should also allow us to defer some more of the main process initialization of extensions that use content scripts.

After that, we might be able to defer initialization of extensions without webRequest or webNavigation permissions until after final UI startup.

Bug 1317681 is tracking most of this work.

Comment 30

[Julien L.]

Since bug 1341008 is now fixed in nightly, the start-up time seems to be faster (visually), but if you disable e10s in the latest nightly, then restart FF, you can see that it's really faster than with e10s enabled.

Comment 31

[David Durst [:ddurst]]

kmag, is this something that we can pick back up?

Comment 32

[Kris Maglione [:kmag]]

It's not really valid anymore. The only non-WebExtensions we have now are system add-ons and Test Pilot add-ons. Some of them *do* slow down startup, but we control those extensions, and it's up to them to make sure they defer the things that can/should be deferred.

WebExtensions use a separate, asynchronous startup process. There's more to do for deferring initialization there when possible, but those are separate bugs (see bug 1363905).

Comment 33

[Sylvestre Ledru [:Sylvestre]]

Moving to p3 because no activity for at least 1 year(s).
See https://github.com/mozilla/bug-handling/blob/master/policy/triage-bugzilla.md#how-do-you-triage for more information