Improvements to benchmarking debug logs. debug now logs total passthrough copy file weight.

Author: zachleat

package.json

@@ -123,6 +123,7 @@
 		"debug": "^4.3.5",
 		"dependency-graph": "^1.0.0",
 		"fast-glob": "^3.3.2",
+		"filesize": "^10.1.4",
 		"graceful-fs": "^4.2.11",
 		"gray-matter": "^4.0.3",
 		"is-glob": "^4.0.3",

src/Eleventy.js

@@ -3,6 +3,7 @@ import { performance } from "node:perf_hooks";
 import { TemplatePath } from "@11ty/eleventy-utils";
 import BundlePlugin from "@11ty/eleventy-plugin-bundle";
 import debugUtil from "debug";
+import { filesize } from "filesize";
 
 import TemplateData from "./Data/TemplateData.js";
 import TemplateWriter from "./TemplateWriter.js";
@@ -375,6 +376,7 @@ class Eleventy {
 		let slashRet = [];
 
 		if (copyCount) {
+			debug("Total passthrough copy aggregate size: %o", filesize(this.writer.getCopySize()));
 			slashRet.push(`Copied ${chalk.bold(copyCount)}`);
 		}
 

src/TemplateContent.js

@@ -385,7 +385,9 @@ class TemplateContent {
 		return [cacheable, key, inputPathMap, useCache];
 	}
 
-	async compile(str, bypassMarkdown, engineOverride) {
+	async compile(str, options = {}) {
+		let { type, bypassMarkdown, engineOverride } = options;
+
 		let tr = await this.getTemplateRender();
 
 		if (engineOverride !== undefined) {
@@ -396,7 +398,7 @@ class TemplateContent {
 		}
 
 		if (bypassMarkdown && !this.engine.needsCompilation(str)) {
-			return async function () {
+			return function () {
 				return str;
 			};
 		}
@@ -428,8 +430,9 @@ class TemplateContent {
 				}
 			}
 
-			let templateBenchmark = this.bench.get("Template Compile");
-			let inputPathBenchmark = this.bench.get(`> Compile > ${this.inputPath}`);
+			let typeStr = type ? ` ${type}` : "";
+			let templateBenchmark = this.bench.get(`Template Compile${typeStr}`);
+			let inputPathBenchmark = this.bench.get(`> Compile${typeStr} > ${this.inputPath}`);
 			templateBenchmark.before();
 			inputPathBenchmark.before();
 			let fn = await tr.getCompiledTemplate(str);
@@ -491,15 +494,13 @@ class TemplateContent {
 			return this._renderFunction(str, data);
 		}
 
-		return this._render(str, data, true);
+		return this._render(str, data, {
+			type: "Computed Data",
+			bypassMarkdown: true,
+		});
 	}
 
 	async renderPermalink(permalink, data) {
-		this.bench.get("(count) Render Permalink").incrementCount();
-		this.bench
-			.get(`(count) > Render Permalink > ${this.inputPath}${this._getPaginationLogSuffix(data)}`)
-			.incrementCount();
-
 		let permalinkCompilation = this.engine.permalinkNeedsCompilation(permalink);
 
 		// No string compilation:
@@ -528,11 +529,17 @@ class TemplateContent {
 			return this._renderFunction(permalink, data);
 		}
 
-		return this._render(permalink, data, true);
+		return this._render(permalink, data, {
+			type: "Permalink",
+			bypassMarkdown: true,
+		});
 	}
 
 	async render(str, data, bypassMarkdown) {
-		return this._render(str, data, bypassMarkdown);
+		return this._render(str, data, {
+			bypassMarkdown,
+			type: "",
+		});
 	}
 
 	_getPaginationLogSuffix(data) {
@@ -551,13 +558,19 @@ class TemplateContent {
 		return suffix.join("");
 	}
 
-	async _render(str, data, bypassMarkdown) {
+	async _render(str, data, options = {}) {
+		let { bypassMarkdown, type } = options;
+
 		try {
 			if (bypassMarkdown && !this.engine.needsCompilation(str)) {
 				return str;
 			}
 
-			let fn = await this.compile(str, bypassMarkdown, data[this.config.keys.engineOverride]);
+			let fn = await this.compile(str, {
+				bypassMarkdown,
+				engineOverride: data[this.config.keys.engineOverride],
+				type,
+			});
 
 			if (fn === undefined) {
 				return;
@@ -567,29 +580,17 @@ class TemplateContent {
 
 			// Benchmark
 			let templateBenchmark = this.bench.get("Render");
-			// Skip benchmark for each individual pagination entry (very busy output)
-			let logRenderToOutputBenchmark = "pagination" in data;
 			let inputPathBenchmark = this.bench.get(
-				`> Render > ${this.inputPath}${this._getPaginationLogSuffix(data)}`,
+				`> Render${type ? ` ${type}` : ""} > ${this.inputPath}${this._getPaginationLogSuffix(data)}`,
 			);
-			let outputPathBenchmark;
-			if (data.page?.outputPath && logRenderToOutputBenchmark) {
-				outputPathBenchmark = this.bench.get(`> Render to > ${data.page.outputPath}`);
-			}
 
 			templateBenchmark.before();
 			if (inputPathBenchmark) {
 				inputPathBenchmark.before();
 			}
-			if (outputPathBenchmark) {
-				outputPathBenchmark.before();
-			}
 
 			let rendered = await fn(data);
 
-			if (outputPathBenchmark) {
-				outputPathBenchmark.after();
-			}
 			if (inputPathBenchmark) {
 				inputPathBenchmark.after();
 			}

src/TemplatePassthrough.js

@@ -240,6 +240,7 @@ class TemplatePassthrough {
 		}
 
 		let fileCopyCount = 0;
+		let fileSizeCount = 0;
 		let map = {};
 		let b = this.benchmarks.aggregate.get("Passthrough Copy File");
 		// returns a promise
@@ -250,13 +251,15 @@ class TemplatePassthrough {
 				map[copyOp.src] = copyOp.dest;
 				b.before();
 			})
-			.on(copy.events.COPY_FILE_COMPLETE, (/*copyOp*/) => {
+			.on(copy.events.COPY_FILE_COMPLETE, (copyOp) => {
 				fileCopyCount++;
+				fileSizeCount += copyOp.stats.size;
 				b.after();
 			})
 			.then(() => {
 				return {
 					count: fileCopyCount,
+					size: fileSizeCount,
 					map,
 				};
 			});
@@ -311,15 +314,18 @@ class TemplatePassthrough {
 			(results) => {
 				// collate the count and input/output map results from the array.
 				let count = 0;
+				let size = 0;
 				let map = {};
 
 				for (let result of results) {
 					count += result.count;
+					size += result.size;
 					Object.assign(map, result.map);
 				}
 
 				return {
 					count,
+					size,
 					map,
 				};
 			},

src/TemplatePassthroughManager.js

@@ -26,6 +26,7 @@ class TemplatePassthroughManager {
 
 	reset() {
 		this.count = 0;
+		this.size = 0;
 		this.conflictMap = {};
 		this.incrementalFile = null;
 		debug("Resetting counts to 0");
@@ -109,6 +110,10 @@ class TemplatePassthroughManager {
 		return this.count;
 	}
 
+	getCopySize() {
+		return this.size;
+	}
+
 	setFileSystemSearch(fileSystemSearch) {
 		this.fileSystemSearch = fileSystemSearch;
 	}
@@ -145,7 +150,7 @@ class TemplatePassthroughManager {
 		// Eventually we’ll want to move all of this to use Node’s fs.cp, which is experimental and only on Node 16+
 
 		return pass.write().then(
-			({ count, map }) => {
+			({ size, count, map }) => {
 				for (let src in map) {
 					let dest = map[src];
 					if (this.conflictMap[dest]) {
@@ -178,7 +183,8 @@ class TemplatePassthroughManager {
 				} else {
 					if (count) {
 						this.count += count;
-						debug("Copied %o (%d files)", inputPath, count || 0);
+						this.size += size;
+						debug("Copied %o (%d files, %d size)", inputPath, count || 0, size || 0);
 					} else {
 						debug("Skipped copying %o (emulated passthrough copy)", inputPath);
 					}
@@ -296,7 +302,7 @@ class TemplatePassthroughManager {
 				map: aliases,
 			});
 
-			debug(`TemplatePassthrough copy finished. Current count: ${this.count}`);
+			debug(`TemplatePassthrough copy finished. Current count: ${this.count} (size: ${this.size})`);
 			return results;
 		});
 	}

src/TemplateWriter.js

@@ -12,7 +12,6 @@ import FileSystemSearch from "./FileSystemSearch.js";
 import ConsoleLogger from "./Util/ConsoleLogger.js";
 
 const debug = debugUtil("Eleventy:TemplateWriter");
-const debugDev = debugUtil("Dev:Eleventy:TemplateWriter");
 
 class TemplateWriterMissingConfigArgError extends EleventyBaseError {}
 class EleventyPassthroughCopyError extends EleventyBaseError {}
@@ -101,7 +100,6 @@ class TemplateWriter {
 		this.writeCount = 0;
 		this.renderCount = 0;
 		this.skippedCount = 0;
-		debugDev("Resetting counts to 0");
 	}
 
 	set extensionMap(extensionMap) {
@@ -345,7 +343,6 @@ class TemplateWriter {
 		await this._addToTemplateMap(paths, to);
 		await this.templateMap.cache();
 
-		debugDev("TemplateMap cache complete.");
 		return this.templateMap;
 	}
 
@@ -475,6 +472,10 @@ class TemplateWriter {
 		return this.eleventyFiles.getPassthroughManager().getCopyCount();
 	}
 
+	getCopySize() {
+		return this.eleventyFiles.getPassthroughManager().getCopySize();
+	}
+
 	getRenderCount() {
 		return this.renderCount;
 	}

src/Util/MemoizeFunction.js

@@ -1,18 +1,26 @@
-export default function (callback) {
+export default function (callback, options = {}) {
+	let { bench, name } = options;
 	let cache = new Map();
 
 	return (...args) => {
 		// Only supports single-arg functions for now.
 		if (args.filter(Boolean).length > 1) {
+			bench?.get(`(count) ${name} Not valid for memoize`).incrementCount();
 			return callback(...args);
 		}
 
 		let [cacheKey] = args;
 
 		if (!cache.has(cacheKey)) {
 			cache.set(cacheKey, callback(...args));
+
+			bench?.get(`(count) ${name} memoize miss`).incrementCount();
+
+			return cache.get(cacheKey);
 		}
 
+		bench?.get(`(count) ${name} memoize hit`).incrementCount();
+
 		return cache.get(cacheKey);
 	};
 }

src/defaultConfig.js

@@ -68,8 +68,9 @@ export default function (config) {
 		immediate: true,
 	});
 
-	config.addFilter("slug", MemoizeUtil(slugFilter));
-	config.addFilter("slugify", MemoizeUtil(slugifyFilter));
+	let memoizeBench = config.benchmarkManager.get("Configuration");
+	config.addFilter("slug", MemoizeUtil(slugFilter, { name: "slug", bench: memoizeBench }));
+	config.addFilter("slugify", MemoizeUtil(slugifyFilter, { name: "slugify", bench: memoizeBench }));
 
 	// Deprecated, use HtmlBasePlugin instead.
 	// Adds a pathPrefix manually to a URL string