1350736 - Slow initialization of content.jsm's root scope

Status: RESOLVED FIXED

(Add-on SDK Graveyard :: General, enhancement)

Description

[(no longer active)]

This is a profile of opening a new window in a fresh profile.  Running the root scope of content.jsm takes a whooping 74ms.  :-(

Kris, do you mind taking a look at this one also?  As far as I can tell, this is all the overhead of this line <http://searchfox.org/mozilla-central/rev/7419b368156a6efa24777b21b0e5706be89a9c2f/addon-sdk/source/lib/framescript/content.jsm#18>.

Comment 1

[(no longer active)]

(Note that the only add-on I have enabled in the Gecko Profiler add-on.)

Comment 2

[(no longer active)]

Oh, forgot the most important thing, the link to the profile! https://perfht.ml/2nq9yYg

Comment 3

[(no longer active)]

And right after it in the profile there is a similar one for l10n-html.js: https://perfht.ml/2nq0EtD followed by tab-events.js: https://perfht.ml/2nqiyfH

Comment 4

[Kris Maglione [:kmag]]

Hm. Well, if that's where all of the overhead is, then it comes from loader.js more than content.jsm. Which isn't entirely surprising.

We can probably get rid of all of the object and prototype freezing there. The modules that it loaded were never actually sandboxed, so it didn't ever serve the purposes it claimed.

There's also bug 1314861, which should help a lot more with the content process overhead.

Comment 5

[Kris Maglione [:kmag]]

Ah, I probably should have looked at the profile before I commented. So, most of the overhead is actually from loading the child.js (the profiler stack is kind of deceptive). So bug 1314861 should probably help a lot.

Comment 6

[Kris Maglione [:kmag]]

(In reply to :Ehsan Akhgari (busy) from comment #3)
> And right after it in the profile there is a similar one for l10n-html.js:
> https://perfht.ml/2nq0EtD

That would be https://reviewboard.mozilla.org/r/90302/diff/1#index_header

> followed by tab-events.js: https://perfht.ml/2nqiyfH

and https://reviewboard.mozilla.org/r/90306/diff/1#index_header

So I guess I need to stop putting off getting back to those patches.

Comment 7

[(no longer active)]

Thank you!!

Comment 8

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

Kris - can we close this bug?

Comment 9

[Kris Maglione [:kmag]]

I'd like Ehsan to confirm that this is no longer an issue first.

Comment 10

[(no longer active)]

Sorry for the long delay, I had switched to a new machine and wanted to go back to my previous machine in order to retest this.

Here is a profile on this same machine on a local build on the latest m-c: https://perfht.ml/2oNEeol

Now 46ms is spent in content.jsm.  So I would say while things are better there is still quite a lot of room for improvement.  33ms is from executing the top-level of child.js.

Can we lazify the loading of some more of the modules being loaded here?

Comment 11

[Kris Maglione [:kmag]]

(In reply to :Ehsan Akhgari (super long backlog, slow to respond) from comment #10)
> Can we lazify the loading of some more of the modules being loaded here?

Unfortunately, no. :( All of the dozens of modules that are still loaded at this point are used pretty much immediately. There's probably not much more we can do at this point until the SDK is gone, unless someone has a few days to throw at massively refactoring a lot of SDK code (I don't).

The only other thing I can think of that might help at this point is enabling the content process script cache after bug 1359653 lands. But it looks like all of the SDK modules that load in the content process currently load after I was planning on freezing cache updates, so it would probably require some special casing.

Comment 12

[Kris Maglione [:kmag]]

Actually, I take that back. They seem to sometimes load before before the first tab begins loading, in which cases we wind up saving about 10-15ms loading content.jsm. It's just not entirely predictable.

Comment 13

[(no longer active)]

(In reply to Kris Maglione [:kmag] from comment #12)
> Actually, I take that back. They seem to sometimes load before before the
> first tab begins loading, in which cases we wind up saving about 10-15ms
> loading content.jsm. It's just not entirely predictable.

Hmm, is content.jsm loaded from <https://searchfox.org/mozilla-central/rev/3dc6ceb42746ab40f1441e1e659ffb8f62ae78e3/addon-sdk/source/lib/framescript/FrameScriptManager.jsm#22>?  If yes, then that seems to be triggered from <https://searchfox.org/mozilla-central/rev/3dc6ceb42746ab40f1441e1e659ffb8f62ae78e3/addon-sdk/source/lib/sdk/remote/parent.js#60> (well really from the require() call above it by a few lines.)  If I have all of this right, hwe can move the loaderID stuff into parent.js directly.  That of course leaves the question of when to actually leave the rest of the code in content.jsm which is harder to answer since AFAICT there is no exported symbol from this JSM that is related to any of the other code...

I have to admit that after reading this code I tend to think that I must be missing something crucial about this setup!

Comment 14

[Kris Maglione [:kmag]]

content.jsm is basically just a stub that lets the parent process load arbitrary modules into the child process. I'm not actually sure why the profiler labels most of what happens there as happening in the content.jsm root scope, since most of it happens when the parent sends a 'sdk/remote/process/load' message, or some other module calls registerContentFrame.

Comment 15

[(no longer active)]

OK, I see, thanks!

So I'm kind of lost on what to do with this bug...  Should we keep it open?  If yes, what more work should happen here?

Comment 16

[Kris Maglione [:kmag]]

Well, it looks like the follow-up to bug 1359653 will improve things in the general case by 25%-ish, so it might make sense to keep it open for that.

Otherwise, unless there's someone who can work on this, we should probably close it as WONTFIX.

Comment 17

[(no longer active)]

Kris, do you think we can close this one now?

Comment 18

[Kris Maglione [:kmag]]

Yeah, we may as well. It's as fixed as it's going to get at this point.