Avoid running resolve/nodeResolve every time require is called

RESOLVED FIXED in Firefox 50

Status

defect
RESOLVED FIXED
4 years ago
3 years ago

People

(Reporter: drew, Assigned: rpl)

Tracking

unspecified
mozilla50

Firefox Tracking Flags

(firefox50 fixed)

Details

Attachments

(2 attachments)

Reporter

Description

4 years ago
Posted file jpm_slow.zip
User Agent: Mozilla/5.0 (Windows NT 6.3; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0
Build ID: 20150513174244

Steps to reproduce:

1) Unzip the attached jpm_slow.zip file to a directory.

2) From that directory, run "cfx xpi" to build an xpi via cfx.

3) Install the xpi, click its action button, and note the number of milliseconds it took that gets alerted (it simply adds 100 context menu items).

4) Remove the cfx-built xpi, and do the same with jpm.


Actual results:

The jpm-built xpi performs the task of creating 100 context menu items far slower than the cfx-built xpi (over double the time in my experience thus far).


Expected results:

I would expect the jpm-built xpi to achieve the same performance as the cfx-built xpi.  This is a simple, contrived example, but I'm not sure if it's indicative of a bigger problem.
Flags: needinfo?(wmccloskey)
Reporter

Comment 1

3 years ago
Any movement on this?  Now that AMO has stopped accepting extensions built with cfx, we have no choice but to switch to jpm.  This definitely worries me a little bit.
Finally looked into this. There's about a 4x performance difference for me. One part of the issue is that we run this code each time we make a menu item:
https://dxr.mozilla.org/mozilla-central/source/addon-sdk/source/lib/sdk/context-menu.js#71
So we have to do |require| once per menu item.

The add-on generated by cfx has a completely different bootstrap.js file than the one generated by jpm. It looks like our module loader has two modes, and the mode is determined by this isNative flag. In the slow jpm version, we use nodeResolve:
https://dxr.mozilla.org/mozilla-central/source/addon-sdk/source/lib/toolkit/loader.js#431

In the fast cfx version, we use ordinary resolve:
https://dxr.mozilla.org/mozilla-central/source/addon-sdk/source/lib/toolkit/loader.js#406

So the module loading done by cfx is just a lot faster than that with jpm. I don't really understand this code at all, but it seems like it's maybe worth trying to speed up. Dave, could you maybe try to give some more insight on what's going on and whether it's worth fixing? If so, perhaps Luca could work on it.
Flags: needinfo?(wmccloskey) → needinfo?(dtownsend)
(In reply to Bill McCloskey (:billm) from comment #2)
> Finally looked into this. There's about a 4x performance difference for me.
> One part of the issue is that we run this code each time we make a menu item:
> https://dxr.mozilla.org/mozilla-central/source/addon-sdk/source/lib/sdk/
> context-menu.js#71
> So we have to do |require| once per menu item.

That seems like an easy fix, though I think we cache the result of requires so that hopefully isn't causing too much time.

> The add-on generated by cfx has a completely different bootstrap.js file
> than the one generated by jpm. It looks like our module loader has two
> modes, and the mode is determined by this isNative flag. In the slow jpm
> version, we use nodeResolve:
> https://dxr.mozilla.org/mozilla-central/source/addon-sdk/source/lib/toolkit/
> loader.js#431
> 
> In the fast cfx version, we use ordinary resolve:
> https://dxr.mozilla.org/mozilla-central/source/addon-sdk/source/lib/toolkit/
> loader.js#406
> 
> So the module loading done by cfx is just a lot faster than that with jpm. I
> don't really understand this code at all, but it seems like it's maybe worth
> trying to speed up. Dave, could you maybe try to give some more insight on
> what's going on and whether it's worth fixing? If so, perhaps Luca could
> work on it.

So from memory the native loader has all kinds of special smarts to try to behave like node so we can use npm modules in SDK add-ons. This unfortunately means that for a given require it does all kinds of things like checking if <module>/index.js, <module>/package.json, <module>.js node_modules/<module>/package.json etc... exist. It also does it in a horribly inefficient manner by trying to open those files rather than just checking their presence (which since we're in a ZIP file is just a hash lookup). I suspect that that is where a lot of the cost comes in. I tried to tackle some of this in bug 1036625 but got pushback at the time. It might be worth luca picking that back up and seeing if it still works and helps.
Flags: needinfo?(dtownsend)
(In reply to Dave Townsend [:mossop] from comment #3)
> (In reply to Bill McCloskey (:billm) from comment #2)
> > Finally looked into this. There's about a 4x performance difference for me.
> > One part of the issue is that we run this code each time we make a menu item:
> > https://dxr.mozilla.org/mozilla-central/source/addon-sdk/source/lib/sdk/
> > context-menu.js#71
> > So we have to do |require| once per menu item.
> 
> That seems like an easy fix, though I think we cache the result of requires
> so that hopefully isn't causing too much time.

For whatever reason we're not caching here. When I move the require statement so that it only happens once for the module, the entire regression goes away. Maybe we should just try to fix that here?
(In reply to Bill McCloskey (:billm) from comment #4)
> (In reply to Dave Townsend [:mossop] from comment #3)
> > (In reply to Bill McCloskey (:billm) from comment #2)
> > > Finally looked into this. There's about a 4x performance difference for me.
> > > One part of the issue is that we run this code each time we make a menu item:
> > > https://dxr.mozilla.org/mozilla-central/source/addon-sdk/source/lib/sdk/
> > > context-menu.js#71
> > > So we have to do |require| once per menu item.
> > 
> > That seems like an easy fix, though I think we cache the result of requires
> > so that hopefully isn't causing too much time.
> 
> For whatever reason we're not caching here. When I move the require
> statement so that it only happens once for the module, the entire regression
> goes away. Maybe we should just try to fix that here?

rs=me, I have no idea why I did it that way in the first place.
(In reply to Bill McCloskey (:billm) from comment #4)
> For whatever reason we're not caching here. When I move the require
> statement so that it only happens once for the module, the entire regression
> goes away. Maybe we should just try to fix that here?

Sorry, I was very unclear. What I meant is "Should we try to fix the fact that there's no cache?" I'm fine fixing the uuid import, but that will only fix one call site. I'm worried that there are other places in the SDK that do the same thing.
Flags: needinfo?(dtownsend)
(In reply to Bill McCloskey (:billm) from comment #6)
> (In reply to Bill McCloskey (:billm) from comment #4)
> > For whatever reason we're not caching here. When I move the require
> > statement so that it only happens once for the module, the entire regression
> > goes away. Maybe we should just try to fix that here?
> 
> Sorry, I was very unclear. What I meant is "Should we try to fix the fact
> that there's no cache?" I'm fine fixing the uuid import, but that will only
> fix one call site. I'm worried that there are other places in the SDK that
> do the same thing.

Oh, yes absolutely.
Flags: needinfo?(dtownsend)
I checked in a specific fix for context menus. Luca, do you think you could work on the more general problem that calling require() resolves the module name to a file URI each time rather than caching it?
Flags: needinfo?(lgreco)
Keywords: leave-open
Summary: JavaScript performance of jpm-built extension is worse than identical cfx-built extension → Avoid running resolve/nodeResolve every time require is called
Assignee

Comment 11

3 years ago
(In reply to Bill McCloskey (:billm) from comment #9)
> I checked in a specific fix for context menus. Luca, do you think you could
> work on the more general problem that calling require() resolves the module
> name to a file URI each time rather than caching it?

Sure, I was already looking around the loader for other issues related to the Addon-SDK.

Looking into it (and I'm not removing the needinfo assigned to me as a remainder).
Assignee

Updated

3 years ago
Attachment #8757976 - Flags: review?(gkrizsanits)
Assignee

Comment 13

3 years ago
The proposed patch caches the resolved path (based on a key string computed from both the "id" and the "requirer" strings).

I tried to get an estimate of how much it reduces the resolutions (by producing a temporary log with dump with and without the resolver cache), and by running it on the test-loader.js test case the result is a reduction of the full resolutions of about a 30%.

I'm not sure about which kind of test I can create to test that the resolver cache is there, but in the meantime I've pushed it on try to verify how all the existent tests behave with the resolver cache enabled:

- https://treeherder.mozilla.org/#/jobs?repo=try&revision=2dfaa047d45e
Flags: needinfo?(lgreco)
Assignee

Updated

3 years ago
Assignee: nobody → lgreco
Status: UNCONFIRMED → ASSIGNED
Ever confirmed: true
Comment on attachment 8757976 [details]
Bug 1170258 - Add cache of node style module resolutions.

https://reviewboard.mozilla.org/r/56330/#review53650

::: addon-sdk/source/lib/toolkit/loader.js:436
(Diff revision 1)
>  // algorithm.
>  // `id` should already be resolved relatively at this point.
>  // http://nodejs.org/api/modules.html#modules_all_together
>  const nodeResolve = iced(function nodeResolve(id, requirer, { rootURI }) {
>    // Resolve again
>    id = Loader.resolve(id, requirer);

What's the role of this resolve? Couldn't we just avoid this one as well if we do the caching here instead?
Attachment #8757976 - Flags: review?(gkrizsanits)
Comment on attachment 8757976 [details]
Bug 1170258 - Add cache of node style module resolutions.

https://reviewboard.mozilla.org/r/56330/#review53894

Actually, never mind, I looked into it and it's perfect as it is.
Attachment #8757976 - Flags: review+
Assignee

Comment 16

3 years ago
Comment on attachment 8757976 [details]
Bug 1170258 - Add cache of node style module resolutions.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/56330/diff/1-2/
Attachment #8757976 - Attachment description: MozReview Request: Bug 1170258 - Add cache of node style module resolutions. → Bug 1170258 - Add cache of node style module resolutions.
Assignee

Comment 17

3 years ago
As briefly discussed over irc, The above is an updated version of this patch which wrap the entire nodeResolve function with a caching helper function (mostly because the change itself looks cleaner: https://reviewboard.mozilla.org/r/56328/diff/2/).
Assignee

Comment 18

3 years ago
Try build of the last version of the patch:

- https://treeherder.mozilla.org/#/jobs?repo=try&revision=fa6cd928fbd4
Assignee

Updated

3 years ago

Comment 19

3 years ago
Pushed by cbook@mozilla.com:
https://hg.mozilla.org/integration/fx-team/rev/85420596281e
Add cache of node style module resolutions. r=gkrizsanits
Keywords: checkin-needed

Comment 20

3 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/85420596281e
Status: ASSIGNED → RESOLVED
Last Resolved: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla50
You need to log in before you can comment on or make changes to this bug.