From 5a65b244235bfcb64ecf085bfc65a99a670e9df4 Mon Sep 17 00:00:00 2001 From: Zach Leatherman Date: Tue, 16 Jul 2024 13:37:57 -0500 Subject: [PATCH] Improvements to benchmarking debug logs. debug now logs total passthrough copy file weight. --- package.json | 1 + src/Eleventy.js | 2 ++ src/TemplateContent.js | 55 ++++++++++++++++--------------- src/TemplatePassthrough.js | 8 ++++- src/TemplatePassthroughManager.js | 12 +++++-- src/TemplateWriter.js | 7 ++-- src/Util/MemoizeFunction.js | 10 +++++- src/defaultConfig.js | 5 +-- 8 files changed, 63 insertions(+), 37 deletions(-) diff --git a/package.json b/package.json index 7afe85e31..e0ab530b2 100755 --- a/package.json +++ b/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", diff --git a/src/Eleventy.js b/src/Eleventy.js index 79efa8693..34b0ec9c9 100644 --- a/src/Eleventy.js +++ b/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)}`); } diff --git a/src/TemplateContent.js b/src/TemplateContent.js index a2c21e45a..55aabc3c0 100644 --- a/src/TemplateContent.js +++ b/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(); } diff --git a/src/TemplatePassthrough.js b/src/TemplatePassthrough.js index 9fef4c90e..c1d2fcebb 100644 --- a/src/TemplatePassthrough.js +++ b/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, }; }, diff --git a/src/TemplatePassthroughManager.js b/src/TemplatePassthroughManager.js index 563c33d1e..e549b97e8 100644 --- a/src/TemplatePassthroughManager.js +++ b/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; }); } diff --git a/src/TemplateWriter.js b/src/TemplateWriter.js index d5ed321d4..fae89930b 100755 --- a/src/TemplateWriter.js +++ b/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; } diff --git a/src/Util/MemoizeFunction.js b/src/Util/MemoizeFunction.js index 073e74ebb..f66a155a3 100644 --- a/src/Util/MemoizeFunction.js +++ b/src/Util/MemoizeFunction.js @@ -1,9 +1,11 @@ -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); } @@ -11,8 +13,14 @@ export default function (callback) { 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); }; } diff --git a/src/defaultConfig.js b/src/defaultConfig.js index 85592bdb0..d30e871f3 100644 --- a/src/defaultConfig.js +++ b/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