Rollup cache seems to be ignored with dynamic imports

[frenautvh]

• Rollup Version: 1.14.2
• Operating System (or Browser): macOS Mojave 10.14.2
• Node Version: 12.3.1

How Do We Reproduce?

I created a small repository to illustrate the issue : https://github.com/frenautvh/rollup-dynamic-import-test. There are two branches on this repo, one is named "static-import" and the other is named "dynamic-import". As their name suggest, they use static and dynamic imports respectively on a relatively big list (x1000) of small javascript files.

Running the build on each one of theses branches with "npm install && npm run build" will launch a rollup build using the JS rollup api, and when the first build is finished, a second build is triggered, using the cache of the previous build.

Expected Behavior

Cached build should be faster. In both cases, i expect the second build to be faster, because the second build is using the cache from the first one.

Actual Behavior

On my laptop :

• static import
  • first build : 1594 ms
  • second build (with cache) : 142 ms
• dynamic import
  • first build : 3866 ms
  • second build (with cache): 4577 ms

In the case of dynamic imports, the second build is as slow as the first one.

Discussion

I know that dynamic import are resolved at runtime but i don't get why it's so slow here. It doesn't make sense to me because the imported files are not touched/modified, so it should be cached, right? Any input on how rollup handle dynamic imports internally?

Thanks for the help guys

[lukastaegert]

Thanks for the issue. This took me some time to figure out. As it turns out, caching was working nearly perfectly for dynamic imports in that the AST and transformations were cached. What was not cached were the resolved ids of dynamic imports. And apparently, resolving ids is more expensive than everything else! Fix at #2908.

[lukastaegert]

By the way, if you add rollup-plugin-node-resolve to your example, even the first run becomes substantially faster (because node-resolve has very sophisticated caching thanks to @keithamus)! E.g. on my machine

• dynamic without node-resolve
  • first build: 1686 ms
  • second build: 1467 ms (without fix)
  • second build: 214 ms (with fix)
• dynamic with node-resolve
  • first build: 682 ms
  • second build: 313 ms (without fix)
  • second build: 229 ms (with fix)

[jleveugle]

Hello @lukastaegert,

Thank you for the fix, release and tips about rollup-plugin-node-resolve. We already use it on our project, but for this issue, with @frenautvh, we wanted to have the minimum of elements to isolate the issue about dynamic imports and help you. It's why we don't use it here ^.^

By the way, taking a look at the build with --perfflag and without your fix, rollup-plugin-node-resolve takes a lot of time between each build (in our case, several minutes). I think this issue can be linked to #2716. I don't know if @ashubham has a lot of dynamic imports in his case, but I think his issue looks like the one we had with @frenautvh.

See you for next issue! (or maybe a PR with the issue? :D)

[jleveugle]

Hello,

I took @frenautvh 's example and I bump my dependency to rollup@^1.14.6.

On my laptop, it looks better but the results are a little less efficient. It always take a long time to re-use the cache on branch dynamic-import. Strange no ? :(

static import without rollup-plugin-node-resolve

➜  rollup-dynamic-import-test git:(static-import) ✗ npm run build

> rollup-dynamic-import-test@1.0.0 build /Users/joffrey/Work/github/frenault/rollup-dynamic-import-test
> node rollup-build.js

Generated an empty bundle
build 2088
Generated an empty bundle
build with cache 196

dynamic import without rollup-plugin-node-resolve

➜  rollup-dynamic-import-test git:(dynamic-import) ✗ npm run build

> rollup-dynamic-import-test@1.0.0 build /Users/joffrey/Work/github/frenault/rollup-dynamic-import-test
> node rollup-build.js

build 4262
build with cache 2319

static import with rollup-plugin-node-resolve

➜  rollup-dynamic-import-test git:(static-import) ✗ npm run build

> rollup-dynamic-import-test@1.0.0 build /Users/joffrey/Work/github/frenault/rollup-dynamic-import-test
> node rollup-build.js

Generated an empty bundle
build 645
Generated an empty bundle
build with cache 185

dynamic import with rollup-plugin-node-resolve

➜  rollup-dynamic-import-test git:(dynamic-import) ✗ npm run build

> rollup-dynamic-import-test@1.0.0 build /Users/joffrey/Work/github/frenault/rollup-dynamic-import-test
> node rollup-build.js

build 2758
build with cache 2260

Without rollup-plugin-node-resolve, timing are divided by 2 with your fix.

But with rollup-plugin-node-resolve, timings are very similar. Any idea about what can take time? (writing chunks maybe?)

Thanks for the help!

[lukastaegert]

With the perf option and bundle.getTimings() you can get more info where the time was spent, might be interesting.

[jleveugle]

Indeed, sry ^.^

I added the perf flag and displayed bundle.getTimings().

Here, the result:

Dynamic import without rollup-plugin-node-resolve

➜  rollup-dynamic-import-test git:(dynamic-import) ✗ npm run build

> rollup-dynamic-import-test@1.0.0 build /Users/jleveugle/Work/github/frenautvh/rollup-dynamic-import-test
> node rollup-build.js

{ '# BUILD': [ 1973.308174, 31089696, 41341200 ],
  '## parse modules': [ 1849.078553, 25181728, 35448304 ],
  'load modules': [ 143558.72511100015, 2172635752, 37055016 ],
  'generate ast': [ 107.86543500000005, -2497864, 37950560 ],
  'analyse ast': [ 81.46695899999992, 13266496, 37959016 ],
  '## analyse dependency graph': [ 31.455389, -3929024, 31519976 ],
  '## mark included statements': [ 52.841097, 7081480, 38602352 ],
  'treeshaking pass 1': [ 46.858381, 6275720, 37814856 ],
  'treeshaking pass 2': [ 5.078083, 786072, 38601864 ],
  '## generate chunks': [ 38.690691, 2712736, 41315736 ],
  '# GENERATE': [ 331.68928, 6977376, 48662240 ],
  'render modules': [ 148.81822799999992, 3073440, 51229456 ],
  'render format': [ 41.07953799999993, 7360840, 57482528 ] }
build 3901
{ '# BUILD': [ 345.306824, 23453344, 66821616 ],
  '## parse modules': [ 256.249514, 9366024, 52736936 ],
  'load modules': [ 34788.389578999995, -5091221944, 49738376 ],
  'generate ast': [ 13.072623000000016, 218944, 60947240 ],
  'analyse ast': [ 63.637850000000036, 14794552, 60955128 ],
  '## analyse dependency graph': [ 15.455808, 5567416, 58304608 ],
  '## mark included statements': [ 33.588155, 5898056, 64202920 ],
  'treeshaking pass 1': [ 29.341847, 5208672, 63516040 ],
  'treeshaking pass 2': [ 4.107456, 686280, 64202576 ],
  '## generate chunks': [ 39.840196, 2607592, 66810768 ],
  '# GENERATE': [ 381.868055, 2054296, 69168536 ],
  'render modules': [ 152.56116100000014, 23840, 72200464 ],
  'render format': [ 53.24022300000001, -6008264, 73241528 ] }
build with cache 2422

Dynamic import with rollup-plugin-node-resolve

➜  rollup-dynamic-import-test git:(dynamic-import) ✗ npm run build

> rollup-dynamic-import-test@1.0.0 build /Users/jleveugle/Work/github/frenautvh/rollup-dynamic-import-test
> node rollup-build.js

{ '# BUILD': [ 1421.371706, 34672240, 45863400 ],
  '## parse modules': [ 1206.06147, 29177328, 40383376 ],
  '- plugin 0 (node-resolve) - resolveId': [ 73.40362100000011, 7766128, 41114296 ],
  '- plugin 0 (node-resolve) - resolveId (async)': [ 506817.36729199975, 6026729832, 45826736 ],
  'load modules': [ 378.3685309999999, 4642016, 45837584 ],
  'generate ast': [ 154.993475, -6063720, 45846856 ],
  'analyse ast': [ 122.60671900000007, 13067728, 45855232 ],
  '## analyse dependency graph': [ 21.44869, 6043064, 46427232 ],
  '## mark included statements': [ 91.913108, -3566440, 42861712 ],
  'treeshaking pass 1': [ 78.748528, -4740320, 41705640 ],
  'treeshaking pass 2': [ 12.091023, 1154560, 42861224 ],
  '## generate chunks': [ 100.663389, 2975408, 45837752 ],
  '# GENERATE': [ 428.02719, 9047664, 55255352 ],
  'render modules': [ 186.09175300000004, 3283024, 58160408 ],
  'render format': [ 66.04753100000003, -5663400, 64302480 ] }
build 3438
{ '# BUILD': [ 340.197014, 24026592, 69278400 ],
  '## parse modules': [ 240.209151, 9917552, 55172184 ],
  '- plugin 0 (node-resolve) - resolveId': [ 0.184324, 18864, 45282696 ],
  '- plugin 0 (node-resolve) - resolveId (async)': [ 1.653873, 197256, 45480408 ],
  'load modules': [ 32381.54176800002, -5387740904, 51667832 ],
  'generate ast': [ 14.187654000000006, 218208, 62078696 ],
  'analyse ast': [ 79.43936199999992, 15673256, 62076016 ],
  '## analyse dependency graph': [ 15.196554, 5551152, 60723672 ],
  '## mark included statements': [ 30.059245, 5803784, 66527728 ],
  'treeshaking pass 1': [ 25.827304, 5112864, 65839264 ],
  'treeshaking pass 2': [ 4.126049, 687760, 66527384 ],
  '## generate chunks': [ 54.559441, 2739368, 69267368 ],
  '# GENERATE': [ 367.266181, 5625664, 75196776 ],
  'render modules': [ 160.24064500000023, 13520664, 73482432 ],
  'render format': [ 52.064028999999934, 7046208, 75605544 ] }
build with cache 2250

static import without rollup-plugin-node-resolve

➜  rollup-dynamic-import-test git:(static-import) ✗ npm run build

> rollup-dynamic-import-test@1.0.0 build /Users/jleveugle/Work/github/frenautvh/rollup-dynamic-import-test
> node rollup-build.js

Generated an empty bundle
{ '# BUILD': [ 1885.5669619999999, 21195432, 32334112 ],
  '## parse modules': [ 1846.040454, 14051232, 25204584 ],
  'load modules': [ 235111.16000700017, -1898751360, 20220640 ],
  'generate ast': [ 64.61063799999997, 5709880, 34346648 ],
  'analyse ast': [ 58.767525999999954, 6375456, 34354952 ],
  '## analyse dependency graph': [ 8.06147, 1901216, 27106496 ],
  '## mark included statements': [ 3.055317, 695440, 27802664 ],
  'treeshaking pass 1': [ 1.594441, 430784, 27802344 ],
  '## generate chunks': [ 26.999249, 4513368, 32316816 ],
  '# GENERATE': [ 42.213407, 190640, 32876544 ],
  'render modules': [ 38.175732, -165064, 32568824 ],
  'render format': [ 1.209945, 233720, 32836360 ] }
build 1976
Generated an empty bundle
{ '# BUILD': [ 189.805161, 10844704, 31545448 ],
  '## parse modules': [ 162.863176, 13751368, 34454848 ],
  'load modules': [ 32331.57776300001, 2385133496, 31451032 ],
  'generate ast': [ 7.648510999999993, 148872, 35335392 ],
  'analyse ast': [ 51.011121000000074, -2168192, 35332712 ],
  '## analyse dependency graph': [ 4.037756, 1791224, 36246272 ],
  '## mark included statements': [ 1.594161, 667016, 36913488 ],
  'treeshaking pass 1': [ 1.087529, 425032, 36913216 ],
  '## generate chunks': [ 21.217347, -5371016, 31542672 ],
  '# GENERATE': [ 27.606713, 9967360, 41812512 ],
  'render modules': [ 26.510042, 9697712, 41562872 ],
  'render format': [ 0.672203, 221488, 41794264 ] }
build with cache 223

static import with rollup-plugin-node-resolve

➜  rollup-dynamic-import-test git:(static-import) ✗ npm run build

> rollup-dynamic-import-test@1.0.0 build /Users/jleveugle/Work/github/frenautvh/rollup-dynamic-import-test
> node rollup-build.js

Generated an empty bundle
{ '# BUILD': [ 1204.581104, 23006656, 34166824 ],
  '## parse modules': [ 1170.6303130000001, 27266216, 38441272 ],
  '- plugin 0 (node-resolve) - resolveId': [ 71.23123900000003, 15441792, 34921984 ],
  '- plugin 0 (node-resolve) - resolveId (async)': [ 570372.8861279999, -3576950696, 38225176 ],
  'load modules': [ 394.519556, 4521240, 38232784 ],
  'generate ast': [ 121.67195400000011, 5582392, 38242016 ],
  'analyse ast': [ 102.56335499999989, 6404064, 38250064 ],
  '## analyse dependency graph': [ 6.645045, 1902360, 40344424 ],
  '## mark included statements': [ 9.028147, -10711056, 29634352 ],
  'treeshaking pass 1': [ 1.520907, 430712, 29633800 ],
  '## generate chunks': [ 17.226779, 4513656, 34149112 ],
  '# GENERATE': [ 50.906212, -675768, 33843648 ],
  'render modules': [ 46.726616, -1052592, 33518560 ],
  'render format': [ 1.155417, 233752, 33786456 ] }
build 1291
Generated an empty bundle
{ '# BUILD': [ 247.150621, 11453272, 45646248 ],
  '## parse modules': [ 210.240613, 13981504, 48177384 ],
  '- plugin 0 (node-resolve) - resolveId': [ 0.226958, 18304, 34222744 ],
  '- plugin 0 (node-resolve) - resolveId (async)': [ 1.533781, 184704, 34407984 ],
  'load modules': [ 28006.460649000015, 2554896864, 45518928 ],
  'generate ast': [ 10.739744000000002, 162560, 47468120 ],
  'analyse ast': [ 78.16715399999987, -2382544, 47476256 ],
  '## analyse dependency graph': [ 17.495515, -7318112, 40859536 ],
  '## mark included statements': [ 2.124296, 690520, 41550256 ],
  'treeshaking pass 1': [ 1.080161, 424968, 41549984 ],
  '## generate chunks': [ 17.079771, 4092720, 45643288 ],
  '# GENERATE': [ 39.137499, -181952, 45762040 ],
  'render modules': [ 38.127875, -449880, 45508808 ],
  'render format': [ 0.649088, 218368, 45732080 ] }
build with cache 313

The # GENERATE step takes more time for dynamic imports (3x ~ 10x more time than static imports). Except that, I don't notice anything else.

Something should jump out?

Thanks!

[lukastaegert]

The longer generate is more files being written. Unfortunately, many numbers are unreliable because they cover async calls that may overlap but in general, nearly all time is lost when resolving and loading files, so resolution might still be a big issue.