add cache.profile flag for more info about (de)serialization timings

declarations/WebpackOptions.d.ts

@@ -969,6 +969,10 @@ export interface FileCacheOptions {
 	 * Name for the cache. Different names will lead to different coexisting caches.
 	 */
 	name?: string;
+	/**
+	 * Track and log detailed timing information for individual cache items.
+	 */
+	profile?: boolean;
 	/**
 	 * When to store data to the filesystem. (pack: Store data when compiler is idle in a single file).
 	 */

lib/WebpackOptionsApply.js

@@ -569,6 +569,7 @@ class WebpackOptionsApply extends OptionsApply {
 									),
 									snapshot: options.snapshot,
 									maxAge: cacheOptions.maxAge,
+									profile: cacheOptions.profile,
 									allowCollectingMemory: cacheOptions.allowCollectingMemory
 								}),
 								cacheOptions.idleTimeout,

lib/cache/PackFileCacheStrategy.js

@@ -561,7 +561,40 @@ class PackContentItems {
 		this.map = map;
 	}
 
-	serialize({ write, snapshot, rollback, logger }) {
+	serialize({ write, snapshot, rollback, logger, profile }) {
+		if (profile) {
+			write(false);
+			for (const [key, value] of this.map) {
+				const s = snapshot();
+				try {
+					write(key);
+					const start = process.hrtime();
+					write(value);
+					const durationHr = process.hrtime(start);
+					const duration = durationHr[0] * 1000 + durationHr[1] / 1e6;
+					if (duration > 1) {
+						if (duration > 500)
+							logger.error(`Serialization of '${key}': ${duration} ms`);
+						else if (duration > 50)
+							logger.warn(`Serialization of '${key}': ${duration} ms`);
+						else if (duration > 10)
+							logger.info(`Serialization of '${key}': ${duration} ms`);
+						else if (duration > 5)
+							logger.log(`Serialization of '${key}': ${duration} ms`);
+						else logger.debug(`Serialization of '${key}': ${duration} ms`);
+					}
+				} catch (e) {
+					rollback(s);
+					if (e === NOT_SERIALIZABLE) continue;
+					logger.warn(
+						`Skipped not serializable cache item '${key}': ${e.message}`
+					);
+					logger.debug(e.stack);
+				}
+			}
+			write(null);
+			return;
+		}
 		// Try to serialize all at once
 		const s = snapshot();
 		try {
@@ -590,9 +623,32 @@ class PackContentItems {
 		}
 	}
 
-	deserialize({ read }) {
+	deserialize({ read, logger, profile }) {
 		if (read()) {
 			this.map = read();
+		} else if (profile) {
+			const map = new Map();
+			let key = read();
+			while (key !== null) {
+				const start = process.hrtime();
+				const value = read();
+				const durationHr = process.hrtime(start);
+				const duration = durationHr[0] * 1000 + durationHr[1] / 1e6;
+				if (duration > 1) {
+					if (duration > 100)
+						logger.error(`Deserialization of '${key}': ${duration} ms`);
+					else if (duration > 20)
+						logger.warn(`Deserialization of '${key}': ${duration} ms`);
+					else if (duration > 5)
+						logger.info(`Deserialization of '${key}': ${duration} ms`);
+					else if (duration > 2)
+						logger.log(`Deserialization of '${key}': ${duration} ms`);
+					else logger.debug(`Deserialization of '${key}': ${duration} ms`);
+				}
+				map.set(key, value);
+				key = read();
+			}
+			this.map = map;
 		} else {
 			const map = new Map();
 			let key = read();
@@ -787,6 +843,7 @@ class PackFileCacheStrategy {
 	 * @param {Logger} options.logger a logger
 	 * @param {SnapshotOptions} options.snapshot options regarding snapshotting
 	 * @param {number} options.maxAge max age of cache items
+	 * @param {boolean} options.profile track and log detailed timing information for individual cache items
 	 * @param {boolean} options.allowCollectingMemory allow to collect unused memory created during deserialization
 	 */
 	constructor({
@@ -798,6 +855,7 @@ class PackFileCacheStrategy {
 		logger,
 		snapshot,
 		maxAge,
+		profile,
 		allowCollectingMemory
 	}) {
 		this.fileSerializer = createFileSerializer(fs);
@@ -812,6 +870,7 @@ class PackFileCacheStrategy {
 		this.version = version;
 		this.logger = logger;
 		this.maxAge = maxAge;
+		this.profile = profile;
 		this.allowCollectingMemory = allowCollectingMemory;
 		this.snapshot = snapshot;
 		/** @type {Set<string>} */
@@ -840,7 +899,7 @@ class PackFileCacheStrategy {
 	 * @returns {Promise<Pack>} the pack
 	 */
 	_openPack() {
-		const { logger, cacheLocation, version } = this;
+		const { logger, profile, cacheLocation, version } = this;
 		/** @type {Snapshot} */
 		let buildSnapshot;
 		/** @type {Set<string>} */
@@ -857,6 +916,7 @@ class PackFileCacheStrategy {
 				filename: `${cacheLocation}/index.pack`,
 				extension: ".pack",
 				logger,
+				profile,
 				retainedBuffer: this.allowCollectingMemory
 					? allowCollectingMemory
 					: undefined
@@ -1172,7 +1232,8 @@ class PackFileCacheStrategy {
 						.serialize(content, {
 							filename: `${this.cacheLocation}/index.pack`,
 							extension: ".pack",
-							logger: this.logger
+							logger: this.logger,
+							profile: this.profile
 						})
 						.then(() => {
 							for (const dep of newBuildDependencies) {

lib/config/defaults.js

@@ -293,6 +293,7 @@ const applyCacheDefaults = (cache, { name, mode, development }) => {
 			);
 			D(cache, "hashAlgorithm", "md4");
 			D(cache, "store", "pack");
+			D(cache, "profile", false);
 			D(cache, "idleTimeout", 60000);
 			D(cache, "idleTimeoutForInitialStore", 0);
 			D(cache, "maxMemoryGenerations", development ? 5 : Infinity);

lib/config/normalization.js

@@ -131,6 +131,7 @@ const getNormalizedWebpackOptions = config => {
 						type: "filesystem",
 						maxMemoryGenerations: cache.maxMemoryGenerations,
 						maxAge: cache.maxAge,
+						profile: cache.profile,
 						buildDependencies: cloneObject(cache.buildDependencies),
 						cacheDirectory: cache.cacheDirectory,
 						cacheLocation: cache.cacheLocation,

schemas/WebpackOptions.json

@@ -999,6 +999,10 @@
           "description": "Name for the cache. Different names will lead to different coexisting caches.",
           "type": "string"
         },
+        "profile": {
+          "description": "Track and log detailed timing information for individual cache items.",
+          "type": "boolean"
+        },
         "store": {
           "description": "When to store data to the filesystem. (pack: Store data when compiler is idle in a single file).",
           "enum": ["pack"]

test/Defaults.unittest.js

@@ -1489,6 +1489,7 @@ describe("Defaults", () => {
 		+     "maxAge": 5184000000,
 		+     "maxMemoryGenerations": Infinity,
 		+     "name": "default-none",
+		+     "profile": false,
 		+     "store": "pack",
 		+     "type": "filesystem",
 		+     "version": "",
@@ -1529,6 +1530,7 @@ describe("Defaults", () => {
 			+     "maxAge": 5184000000,
 			+     "maxMemoryGenerations": 5,
 			+     "name": "default-development",
+			+     "profile": false,
 			+     "store": "pack",
 			+     "type": "filesystem",
 			+     "version": "",
@@ -1769,6 +1771,7 @@ describe("Defaults", () => {
 			+     "maxAge": 5184000000,
 			+     "maxMemoryGenerations": Infinity,
 			+     "name": "default-none",
+			+     "profile": false,
 			+     "store": "pack",
 			+     "type": "filesystem",
 			+     "version": "",

test/__snapshots__/Cli.test.js.snap

@@ -238,6 +238,19 @@ Object {
     "multiple": false,
     "simpleType": "string",
   },
+  "cache-profile": Object {
+    "configs": Array [
+      Object {
+        "description": "Track and log detailed timing information for individual cache items.",
+        "multiple": false,
+        "path": "cache.profile",
+        "type": "boolean",
+      },
+    ],
+    "description": "Track and log detailed timing information for individual cache items.",
+    "multiple": false,
+    "simpleType": "boolean",
+  },
   "cache-store": Object {
     "configs": Array [
       Object {

types.d.ts

@@ -3825,6 +3825,11 @@ declare interface FileCacheOptions {
 	 */
 	name?: string;
 
+	/**
+	 * Track and log detailed timing information for individual cache items.
+	 */
+	profile?: boolean;
+
 	/**
 	 * When to store data to the filesystem. (pack: Store data when compiler is idle in a single file).
 	 */