Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

PackFileCacheStrategy is slow when saving cache for a large project #12418

Closed
randing89 opened this issue Jan 13, 2021 · 12 comments
Closed

PackFileCacheStrategy is slow when saving cache for a large project #12418

randing89 opened this issue Jan 13, 2021 · 12 comments

Comments

@randing89
Copy link

randing89 commented Jan 13, 2021

Bug report

What is the current behavior?

PackFileCacheStrategy took 7 minutes from finishing building to saving the cache file to the disk.
Is there any way to improve performance?

Also, this problem is causing a slow rebuild. If a change is made before the cache is saved Webpack will do a full rebuild instead of incremental.

webpack 5.13.0 compiled with 3 warnings in 106066 ms
ℹ 「wdm」: Compiled with warnings.
    [webpack.cache.PackFileCacheStrategy] Pack got invalid because of write to: ResolverCachePlugin|normal|dependencyType=|esm|path=|/Users/rading/src/confluence-frontend/packages/confluence-frontend-server|request=|./src/index
    [webpack.cache.PackFileCacheStrategy] Storing pack...
    [webpack.cache.PackFileCacheStrategy] Capturing build dependencies... (/Users/rading/src/confluence-frontend/packages/confluence-frontend-server/webpack.config.js, /Users/rading/src/confluence-frontend/node_modules/webpack/lib/, /Users/rading/src/confluence-frontend/node_modules/babel-loader/lib/index.js, /Users/rading/src/confluence-frontend/node_modules/style-loader/index.js, /Users/rading/src/confluence-frontend/node_modules/css-loader/dist/cjs.js, /Users/rading/src/confluence-frontend/node_modules/isomorphic-style-loader/lib/index.js, /Users/rading/src/confluence-frontend/node_modules/url-loader/dist/cjs.js)
<t> [webpack.cache.PackFileCacheStrategy] resolve build dependencies: 402900.067223 ms
<t> [webpack.cache.PackFileCacheStrategy] snapshot build dependencies: 5203.678816 ms
    [webpack.cache.PackFileCacheStrategy] Captured build dependencies
    [webpack.cache.PackFileCacheStrategy] 90675 fresh items in cache
<w> [webpack.cache.PackFileCacheStrategy] Serializing big strings (120kiB) impacts deserialization performance (consider using Buffer instead and decode when needed)
<w> [webpack.cache.PackFileCacheStrategy] Serializing big strings (1142kiB) impacts deserialization performance (consider using Buffer instead and decode when needed)
<t> [webpack.cache.PackFileCacheStrategy] store pack: 34535.317653 ms
    [webpack.cache.PackFileCacheStrategy] Stored pack

If the current behavior is a bug, please provide the steps to reproduce.

Delete the cache file and start Webpack build.

What is the expected behavior?

Webpack spend reasonable time to generate the cache.

Other relevant information:
webpack version: 5.13.0
Node.js version: v14.15.1
Operating System: 10.15.7

@alexander-akait
Copy link
Member

alexander-akait commented Jan 13, 2021

Firstly - do not ignore the issue template and provide more information about your configuration and project

@alexander-akait
Copy link
Member

Also, you have bad plugin:

<w> [webpack.cache.PackFileCacheStrategy] Serializing big strings (120kiB) impacts deserialization performance (consider using Buffer instead and decode when needed)
<w> [webpack.cache.PackFileCacheStrategy] Serializing big strings (1142kiB) impacts deserialization performance (consider using Buffer instead and decode when needed)

double check your version

@randing89
Copy link
Author

@alexander-akait Thanks for replying I have updated the description. I have commented out most of the plugins trying to scope the issue the only one left is DefinePlugin. I have pasted the config in the description.

@randing89
Copy link
Author

randing89 commented Jan 13, 2021

Looks like Webpack is spending most of the time resolving the build dependency. I removed the plugin usages in webpack.config.js when testing but I didn't remove the required statements.

After adding some log in webpack/lib/FileSystemInfo I can see it walk through tons of files.

@alexander-akait
Copy link
Member

Should help #12419

@alexander-akait
Copy link
Member

@randing89 Anyway can your provide logs?

@randing89
Copy link
Author

randing89 commented Jan 13, 2021

@alexander-akait
I added a console log here https://github.com/webpack/webpack/blob/master/lib/FileSystemInfo.js#L1113
The number in the front is the timestamp. You can see it is going over a lot of files.
Some of them take a second or two to finish.
logs.txt

I am running webpack with 2.2 GHz 6-Core Intel Core i7 MBP. The CPU is very busy even after the Stored pack for some reason.
image

Update:
I logged the timing of this function https://github.com/webpack/webpack/blob/master/lib/FileSystemInfo.js#L1121-L1130
It takes seconds to resolve. Is it normal? with-resolve-duration.txt

@sokra
Copy link
Member

sokra commented Jan 14, 2021

It takes seconds to resolve. Is it normal?

Difficult to say. I guess would be that's a measurement problem. The high number of parallel operations may makes measuring a single operation difficult. Could you try to set the concurrency to 1 when measuring it. It's the last argument of asyncLib.queue in resolveBuildDependencies (currently 50).

I also made some fixes the build dependencies tracking, so could you please try again with the latest release.

Setting this configuration might also give more information infrastructureLogging.debug: /PackFileCacheStrategy/.

@randing89
Copy link
Author

@sokra Tried again with 5.14.0 with following changes

diff --git a/node_modules/webpack/lib/FileSystemInfo.js b/node_modules/webpack/lib/FileSystemInfo.js
index 590929c..cf2e01b 100644
--- a/node_modules/webpack/lib/FileSystemInfo.js
+++ b/node_modules/webpack/lib/FileSystemInfo.js
@@ -11,6 +11,7 @@ const AsyncQueue = require("./util/AsyncQueue");
 const createHash = require("./util/createHash");
 const { join, dirname, relative } = require("./util/fs");
 const makeSerializable = require("./util/makeSerializable");
+const { performance } = require('perf_hooks');
 
 /** @typedef {import("./WebpackError")} WebpackError */
 /** @typedef {import("./logging/Logger").Logger} Logger */
@@ -1117,7 +1118,8 @@ class FileSystemInfo {
 					const key = `f\n${context}\n${path}`;
 					if (resolveResults.has(key)) {
 						return callback();
-					}
+          }
+          const start = performance.now();
 					resolve(
 						context,
 						path,
@@ -1127,6 +1129,7 @@ class FileSystemInfo {
 							missingDependencies: resolveMissing
 						},
 						(err, result) => {
+              console.log(`resolve ${path} in ${(performance.now() - start) >> 0}`)
 							if (expected) {
 								if (result === expected) {
 									resolveResults.set(key, result);
@@ -1373,7 +1376,7 @@ class FileSystemInfo {
 					}
 				}
 			},
-			50
+			1
 		);
 		queue.drain = () => {
 			callback(null, {

After changing 50 to 1 the build takes even more time:
concurrent-1.txt

@sokra
Copy link
Member

sokra commented Jan 14, 2021

That doesn't make a lot of sense to me. Why should it take multiple seconds to resolve a file?? The same resolving process happens during the build a lot, and doesn't cause issues...

Could you try on a different computer? Could you try to disable antivirus software?

@randing89
Copy link
Author

randing89 commented Jan 15, 2021

@sokra I dug into the code a little bit more. It turns out the readFile in https://github.com/webpack/enhanced-resolve/blob/master/lib/CachedInputFileSystem.js#L430 was taking a few seconds to read every package.json file when running resolveBuildDependencies. Just to ruling out my machine's issue, I changed it to the sync version which immediately reduced the time down to 0~1ms.

After another few hours of digging around, I found removing watchOptions.ignored and changing watchOptions.poll to watchOptions.watch = true fixed the problem

    watchOptions: {
      ignored: /node_modules\//,
      poll: 1000,
    },

I guess the ignored is making dev sever to watch too many files causing I/O starvation?

Here is the log after the fix.

<t> [webpack.cache.PackFileCacheStrategy] resolve build dependencies: 4761.931206 ms
<t> [webpack.cache.PackFileCacheStrategy] snapshot build dependencies: 117.821732 ms
    [webpack.cache.PackFileCacheStrategy] Captured build dependencies
    [webpack.cache.PackFileCacheStrategy] 80885 fresh items in cache
<w> [webpack.cache.PackFileCacheStrategy] Serializing big strings (1142kiB) impacts deserialization performance (consider using Buffer instead and decode when needed)

@matzeeable
Copy link

Hi @sokra !

I stumbled over a similar issue with my update from webpack@5.12.2 to webpack@5.37.0 and perhaps the following can help you to "debug" this.

  • All our node_modules folders in our monorepo are symlinked to /tmp (needed to provide hot cache in our CI image)
  • Running multiple webpack (3x) production builds in parallel with concurrently
[00:00:17.271] [real-commerce-wp-client] [info] [webpackbar] Compiling Real-commerce-wp-client
[00:00:17.515] [real-commerce-wp-client] <t> [webpack.cache.PackFileCacheStrategy] restore cache container: 285.495537 ms
[00:00:18.183] [real-commerce-wp-client]     [webpack.cache.PackFileCacheStrategy/webpack.FileSystemInfo] /tmp/builds/devowlio/devowl-wp/node_modules/bufferutil invalidated because hashes differ (missing != bufferutil@4.0.3)
[00:00:18.183] [real-commerce-wp-client]     [webpack.cache.PackFileCacheStrategy] Restored pack from /builds/devowlio/devowl-wp/plugins/real-commerce-wp-client/node_modules_cache/webpack/default-production.pack, but build dependencies have changed.
[00:00:18.183] [real-commerce-wp-client]     [webpack.cache.PackFileCacheStrategy] resolving of build dependencies is invalid, will re-resolve build dependencies
[00:00:18.211] [real-commerce-wp-client]     [webpack.cache.PackFileCacheStrategy/webpack.FileSystemInfo] /tmp/builds/devowlio/devowl-wp/node_modules/utf-8-validate invalidated because hashes differ (missing != utf-8-validate@5.0.5)
[00:00:18.211] [real-commerce-wp-client]     [webpack.cache.PackFileCacheStrategy/webpack.FileSystemInfo] /tmp/builds/devowlio/devowl-wp/node_modules/node-gyp-build invalidated because hashes differ (missing != node-gyp-build@4.2.3)
[00:00:37.262] [real-commerce-wp-client]     [webpack.cache.PackFileCacheStrategy] Restored pack from /builds/devowlio/devowl-wp/plugins/real-commerce-wp-client/node_modules_cache/webpack/default-production.pack, but resolving of build dependencies errored: Error: Can't resolve 'bufferutil/index' in '/tmp/builds/devowlio/devowl-wp/node_modules/ws/lib'.
[00:00:37.263] [real-commerce-wp-client]     [webpack.cache.PackFileCacheStrategy] Error: Can't resolve 'bufferutil/index' in '/tmp/builds/devowlio/devowl-wp/node_modules/ws/lib'
[00:00:37.263] [real-commerce-wp-client]         at finishWithoutResolve (/tmp/builds/devowlio/devowl-wp/node_modules/enhanced-resolve/lib/Resolver.js:293:18)
[00:00:37.263] [real-commerce-wp-client]         at /tmp/builds/devowlio/devowl-wp/node_modules/enhanced-resolve/lib/Resolver.js:362:15
[00:00:37.263] [real-commerce-wp-client]         at /tmp/builds/devowlio/devowl-wp/node_modules/enhanced-resolve/lib/Resolver.js:410:5
[00:00:37.263] [real-commerce-wp-client]         at eval (eval at create (/tmp/builds/devowlio/devowl-wp/node_modules/tapable/lib/HookCodeFactory.js:33:10), <anonymous>:15:1)
[00:00:37.263] [real-commerce-wp-client]         at /tmp/builds/devowlio/devowl-wp/node_modules/enhanced-resolve/lib/Resolver.js:410:5
[00:00:37.263] [real-commerce-wp-client]         at eval (eval at create (/tmp/builds/devowlio/devowl-wp/node_modules/tapable/lib/HookCodeFactory.js:33:10), <anonymous>:27:1)
[00:00:37.269] [real-commerce-wp-client]         at /tmp/builds/devowlio/devowl-wp/node_modules/enhanced-resolve/lib/DescriptionFilePlugin.js:87:43
[00:00:37.269] [real-commerce-wp-client]         at /tmp/builds/devowlio/devowl-wp/node_modules/enhanced-resolve/lib/Resolver.js:410:5
[00:00:37.269] [real-commerce-wp-client]         at eval (eval at create (/tmp/builds/devowlio/devowl-wp/node_modules/tapable/lib/HookCodeFactory.js:33:10), <anonymous>:15:1)
[00:00:37.269] [real-commerce-wp-client]         at /tmp/builds/devowlio/devowl-wp/node_modules/enhanced-resolve/lib/Resolver.js:410:5
[00:00:37.269] [real-commerce-wp-client] <t> [webpack.cache.PackFileCacheStrategy] check build dependencies: 19753.680409 ms

For some other projects we also hit times of 296 seconds (check build dependencies: 296405.667806 ms). This issue happened definitely between webpack@5.12.2 and webpack@5.37.0 cause 5.12.2 resolved build dependencies in seconds.

I changed it to the sync version which immediately reduced the time down to 0~1ms.

@randing89 What exactly did you change here?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

5 participants