Closed Bug 1365187 Opened 8 years ago Closed 7 years ago

Loading a large module graph takes a very long time

Categories

(Core :: JavaScript Engine, defect, P3)

Product:
Core
Component:
JavaScript Engine
Version:
54 Branch
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla59
Tracking Flags:
Tracking Status
firefox59 --- fixed

People

(Reporter: gil, Assigned: jonco)

References

Details

(Keywords: triage-deferred)

Attachments

(2 files, 2 obsolete files)

bug1365187-simplify-module-map-interface
4.79 KB, patch
jonco
: review+
Details | Diff | Splinter Review
bug1365187-visited-set v2
22.01 KB, patch
smaug
: review+
Details | Diff | Splinter Review
User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/58.0.3029.110 Safari/537.36 Steps to reproduce: Steps to reproduce the problem: 1. Create the following HTML: ``` <!DOCTYPE html> <body> <h1 id="output">It doesn't work...</h1> <script> console.time('benchmark') </script> <script type="module"> import _ from './node_modules/lodash-es/lodash.default.js' const $ = document.querySelector.bind(document) $('#output').textContent = _.toUpper('it works') console.timeEnd('benchmark') </script> </body> ``` 2. To make it work, you need to `npm install lodash-es@4.17.4` 3. Now serve the file from a web server. 4. lodash imports tens of modules, but the network fetching itself only takes a few seconds. 4. It takes about 18 seconds to see "IT WORKS". Most of the time, as seen in the "Performance" tab in devtools, is the browser sitting idle. 5. A blog post describing this in detail can be found in https://hackernoon.com/native-es-modules-ready-for-prime-time-87c64d294d3c 6. A github repo that implements the above steps (and more), can be found in https://github.com/giltayar/esm-with-http2. Just `npm install && npm run build` and then open `http://localhost:3000/es6-modules.html`. Actual results: It takes about 30 seconds to see "IT WORKS", and the browser is unresposive at that time. Expected results: Loading the module and seeing "IT WORKS" in less than a second, given that the network fetching, on localhost, should take 10s of milliseconds.
Flags: needinfo?(gandalf)
Thanks for the CC! I'm not the right person to triage this (although, per bug 568953 and bug 1240072 seems like it should be Core::Javascript Engine)
Component: Untriaged → JavaScript Engine
Flags: needinfo?(gandalf)
Product: Firefox → Core
Flags: needinfo?(jcoppeard)
I've reproduced this. The test loads 641 modules and takes around 10 seconds.
I'm not really familiar with lodash, but it seems that lodash-es is generated in a form where every method is in a separate module. That's probably make sense if you're going to bundle your modules because you may be able to only include methods that are actually used. But it doesn't make as much sense if you're serving your modules over the web as they then have to be transferred individually over http. (for more info see: https://www.npmjs.com/package/lodash-es and https://lodash.com/custom-builds)
(In reply to Jon Coppeard (:jonco) from comment #2) > I've reproduced this. The test loads 641 modules and takes around 10 > seconds. On my computer it's around 30 seconds, but given that most of the time is CPU time, then it probably heavily depends on the strength of the CPU. The point is that loading those files _bundled_ takes tens of milliseconds, and not because of network time. So something is eating up CPU.
(In reply to Jon Coppeard (:jonco) from comment #3) > I'm not really familiar with lodash, but it seems that lodash-es is > generated in a form where every method is in a separate module. That's > probably make sense if you're going to bundle your modules because you may > be able to only include methods that are actually used. But it doesn't make > as much sense if you're serving your modules over the web as they then have > to be transferred individually over http. > > (for more info see: https://www.npmjs.com/package/lodash-es and > https://lodash.com/custom-builds) That's true, but as I said in an earlier comment, the time it takes is not network time (I checked). The whole point of this exercise for me was to see how I can optimize the network part (using http/2 and push mode), but I can't get to that if the parsing and loading time is *so* big. I believe the goal should be for the parsing and execution of these modules to take around the time it takes to parse and executing the same amount of code when it is bundled (and that time is measured in milliseconds). And this is not an edge case. In the current world of frontend using npm packages - applications *do* use hundreds of small modules.
(In reply to gil from comment #5) I'm not suggesting that this is not a bug or unworthy of investigation. How are you measuring network time out of interest?
(In reply to Jon Coppeard (:jonco) from comment #6) > (In reply to gil from comment #5) > I'm not suggesting that this is not a bug or unworthy of investigation. > > How are you measuring network time out of interest? I just looked at the Network tab.
What is happening is that the script loader is creating a module load request for every module import found via every path from the root module in the module graph (not just for every imported module). For this particular module graph this creates ~360000 import requests. It's implemented like this because it's following the algorithm given in the spec, but it should be possible to do something equivalent that doesn't have this behaviour.
Currently when we go to fetch a dependency of a module we create a new module load request, fetch the module, then recursively fetch its dependencies in the same way. If the module is currently being fetched then we wait for that fetch to finish, but we still go on to fetch its dependencies (which will already have been fetched). This is wasteful and traverses all paths from the root module to all leaves in the module dependency graph. Instead we can check whether the module is currently fetching and if so wait for it and its dependencies to finish loading. We don't need to attempt to load it's dependencies after this point. The patch changes ScriptLoader::StartFetchingModuleDependencies to do this.
Assignee: nobody → jcoppeard
Flags: needinfo?(jcoppeard)
Attachment #8870064 - Flags: review?(bugs)
Attachment #8870064 - Flags: review?(bugs) → review+
Pushed by jcoppeard@mozilla.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/1a261952f14a When fetching a dependent module wait for any ongoing fetch of the module and its dependents to finish rather than creating a new load request r=smaug
Backed out for frequent Win7 test_linkErrorInCommon2.html failures. https://hg.mozilla.org/mozilla-central/rev/96e18bec9fc8 https://treeherder.mozilla.org/logviewer.html#?job_id=101350016&repo=mozilla-inbound TEST-START | dom/base/test/jsmodules/test_linkErrorInCommon2.html GECKO(3516) | JavaScript error: , line 0: attempt to re-instantiate module after failure GECKO(3516) | JavaScript error: chrome://mochitests/content/chrome/dom/base/test/jsmodules/module_missingImport.js, line 0: TypeError: Resolved module not found in map: ./module_simple1.js TEST-INFO | started process screenshot TEST-INFO | screenshot: exit 0 Buffered messages logged at 14:21:49 TEST-PASS | dom/base/test/jsmodules/test_linkErrorInCommon2.html | Check no modules were executed Buffered messages finished TEST-UNEXPECTED-FAIL | dom/base/test/jsmodules/test_linkErrorInCommon2.html | Check that an error was reported testError@chrome://mochitests/content/chrome/dom/base/test/jsmodules/test_linkErrorInCommon2.html:20:5 onload@chrome://mochitests/content/chrome/dom/base/test/jsmodules/test_linkErrorInCommon2.html:1:1 GECKO(3516) | MEMORY STAT | vsize 788MB | vsizeMaxContiguous 890MB | residentFast 231MB | heapAllocated 87MB TEST-OK | dom/base/test/jsmodules/test_linkErrorInCommon2.html | took 84ms
Status: UNCONFIRMED → ASSIGNED
Ever confirmed: true
Depends on: 1374239
Keywords: triage-deferred
Priority: -- → P3
es modules makes ff 58.0b7 crash. every time. It worked fine with version 55. Tell me if you want example.
(In reply to capocyril from comment #13) Yes please do provide a test case if you're seeing crashes (and possibly file a new bug).
Summary: Loading tens of ES Modules in parallel makes JS interpreter stall for more than 10 seconds → Loading a large module graph takes a very long time
Attachment #8870064 - Attachment is obsolete: true
The spec algorithm was updated to one that, although equivalent, does not have this behaviour: https://github.com/whatwg/html/pull/2971
Blocks: modules-0
Correction: es modules makes ff 58.0b7 crash. almost every time on localhost http://localhost:8080/ with my setup. Sometimes it works I don't know why. There are no errors. It seems to work when served from a normal https server. It worked fine with version ff v55. I HAVE TO USE OPERA for now for dev. Hypothesis: Race condition or not https ? Also make it possible to serve from file:/// PS: How to edit a previous comment ?
(In reply to capocyril from comment #16) Thanks for letting us know. Please can you file a new bug and include a test case, and if possible details of the crash?
Flags: needinfo?(capocyril)
Patch to simplify the module map interface to use URLs rather than load requests. This was part of the previous patch on this bug. Carrying r+.
Attachment #8935757 - Flags: review+
Attached patch bug1365187-visited-set (obsolete) — — Splinter Review
Patch to update the module loader to use the new algorithm in the spec to avoid requesting the same module more than once when loading a module graph. Originally this used a ancestor list and avoided re-requesting any ancestor module to the one being considered. This doesn't prevent a previously loaded module from being requested on a different path through the graph. The STR in this bug show how this can result in an N^2 blowup in requested modules. The new approach maintains a visited set that applies to the whole graph and doesn't request the same module more than once. Note that requesting a module more than once doesn't mean we actually issue more than one fetch - it just causes more internal bookkeeping.
Attachment #8935778 - Flags: review?(bugs)
Comment on attachment 8935778 [details] [diff] [review] bug1365187-visited-set >- ModuleLoadRequest(nsIScriptElement* aElement, >+ // Create a top-level module load request. >+ ModuleLoadRequest(nsIURI *aURI, >+ nsIScriptElement* aElement, > ValidJSVersion aValidJSVersion, > CORSMode aCORSMode, > const SRIMetadata& aIntegrity, > ScriptLoader* aLoader); > >+ // Create a module load request for an imported module. >+ ModuleLoadRequest(nsIURI *aURI, Nit, * goes with the type. Here and in the ctor above. >+ // Set of module URLs visited while fetching the module graph this request is >+ // part of. >+ nsTHashtable<nsURIHashKey>* mVisitedSet; Hmm, lifetime management of this is rather worrisome. As you note somewhere, we probably need to make this refcounted. > void > ModuleScript::SetErrorToRethrow(const JS::Value& aError) > { > MOZ_ASSERT(!aError.isUndefined()); > MOZ_ASSERT(!HasErrorToRethrow()); > > mErrorToRethrow = aError; >+ HoldJSObjects(this); I don't understand this call. Why/how is this related to this bug? Some clarifications and mVisitedSet handling fixed, then I'd r+, but I think I should re-read this, so r- still.
Attachment #8935778 - Flags: review?(bugs) → review-
Sorry I should have fixed that before requesting review. I updated the patch to reference count the set. I removed the HoldJSObject part, that should have been in a different bug.
Attachment #8935778 - Attachment is obsolete: true
Attachment #8936492 - Flags: review?(bugs)
Attachment #8936492 - Flags: review?(bugs) → review+
Pushed by jcoppeard@mozilla.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/ebcc9ceb0842 Simplify module map interface r=smaug https://hg.mozilla.org/integration/mozilla-inbound/rev/9eca4461d079 Keep track of which modules in a graph have been fetched using a visited set r=smaug
https://hg.mozilla.org/mozilla-central/rev/ebcc9ceb0842 https://hg.mozilla.org/mozilla-central/rev/9eca4461d079
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
status-firefox59: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla59
The bug I was experiencing is no longer there with version 59.0b2 ! However I see that <script nomodule> are downloaded (not executed) in the network tab (F12)
Flags: needinfo?(capocyril)
(In reply to capocyril from comment #26) Good to hear that. The problem with <script nomodule> is bug 1382020.
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: