Now shows total files copied in passthrough copy output. Fixes #1077.

Adds aggregate benchmarks. Changes threshold percent from 10% to 8%.

src/Benchmark.js

@@ -1,27 +1,36 @@
+const { performance } = require("perf_hooks");
+
 class Benchmark {
   constructor() {
     this.reset();
   }
 
+  getNewTimestamp() {
+    if (performance) {
+      return performance.now();
+    }
+    return new Date().getTime();
+  }
+
   reset() {
     this.timeSpent = 0;
     this.timesCalled = 0;
-    this.beforeDates = [];
+    this.beforeTimers = [];
   }
 
   before() {
     this.timesCalled++;
-    this.beforeDates.push(new Date());
+    this.beforeTimers.push(this.getNewTimestamp());
   }
 
   after() {
-    if (!this.beforeDates.length) {
+    if (!this.beforeTimers.length) {
       throw new Error("You called Benchmark after() without a before().");
     }
 
-    let before = this.beforeDates.pop();
-    if (!this.beforeDates.length) {
-      this.timeSpent += new Date().getTime() - before.getTime();
+    let before = this.beforeTimers.pop();
+    if (!this.beforeTimers.length) {
+      this.timeSpent += this.getNewTimestamp() - before;
     }
   }
 
@@ -32,10 +41,6 @@ class Benchmark {
   getTotal() {
     return this.timeSpent;
   }
-
-  getTotalString() {
-    return this.timeSpent > 0 ? ` (${this.timeSpent}ms)` : "";
-  }
 }
 
 module.exports = Benchmark;

src/BenchmarkGroup.js

@@ -1,19 +1,21 @@
 const chalk = require("chalk");
 
 const Benchmark = require("./Benchmark");
-const debugWarn = require("debug")("Eleventy:Warnings");
+const debugBenchmark = require("debug")("Eleventy:Benchmark");
 
 class BenchmarkGroup {
   constructor() {
     this.benchmarks = {};
-    this.start = new Date();
     this.isVerbose = true;
     this.minimumThresholdMs = 0;
+    this.minimumThresholdPercent = 8;
   }
 
-  reset() {
-    this.start = new Date();
+  setIsVerbose(isVerbose) {
+    this.isVerbose = isVerbose;
+  }
 
+  reset() {
     for (var type in this.benchmarks) {
       this.benchmarks[type].reset();
     }
@@ -52,37 +54,60 @@ class BenchmarkGroup {
     this.minimumThresholdMs = val;
   }
 
+  setMinimumThresholdPercent(minimumThresholdPercent) {
+    let val = parseInt(minimumThresholdPercent, 10);
+    if (isNaN(val)) {
+      throw new Error(
+        "`setMinimumThresholdPercent` expects a number argument."
+      );
+    }
+    this.minimumThresholdPercent = val;
+  }
+
   get(type) {
-    this.benchmarks[type] = new Benchmark();
+    if (!this.benchmarks[type]) {
+      this.benchmarks[type] = new Benchmark();
+    }
     return this.benchmarks[type];
   }
 
-  finish(label, thresholdPercent, isVerbose) {
-    let totalTimeSpent = new Date().getTime() - this.start.getTime();
-    thresholdPercent = thresholdPercent !== undefined ? thresholdPercent : 10;
+  finish(label, totalTimeSpent) {
     for (var type in this.benchmarks) {
       let bench = this.benchmarks[type];
+      let isAbsoluteMinimumComparison = this.minimumThresholdMs > 0;
       let totalForBenchmark = bench.getTotal();
       let percent = (totalForBenchmark * 100) / totalTimeSpent;
+
+      let extraOutput = [];
+      if (!isAbsoluteMinimumComparison) {
+        extraOutput.push(`${percent.toFixed(1)}%`);
+      }
+      let timesCalledCount = bench.getTimesCalled();
+      if (timesCalledCount > 1) {
+        extraOutput.push(`called ${timesCalledCount}×`);
+        extraOutput.push(
+          `${(totalForBenchmark / timesCalledCount).toFixed(1)}ms each`
+        );
+      }
+
+      let str = chalk.yellow(
+        `Benchmark (${label}): ${type} took ${totalForBenchmark.toFixed(0)}ms ${
+          extraOutput.length ? `(${extraOutput.join(", ")})` : ""
+        }`
+      );
+
       if (
-        percent > thresholdPercent &&
-        totalForBenchmark >= this.minimumThresholdMs
+        (isAbsoluteMinimumComparison &&
+          totalForBenchmark >= this.minimumThresholdMs) ||
+        percent > this.minimumThresholdPercent
       ) {
-        let timesCalledCount = bench.getTimesCalled();
-        let timesCalled = "";
-        if (timesCalledCount > 1) {
-          timesCalled = `, called ${timesCalledCount}×`;
-        }
-        let str = chalk.yellow(
-          `Benchmark (${label}): ${type} took ${bench.getTotal()}ms (${percent.toFixed(
-            1
-          )}%${timesCalled})`
-        );
-        if (isVerbose) {
+        if (this.isVerbose) {
           console.log(str);
         }
+      }
 
-        debugWarn(str);
+      if (totalForBenchmark.toFixed(0) > 0) {
+        debugBenchmark(str);
       }
     }
   }

src/BenchmarkManager.js

@@ -1,31 +1,50 @@
 const BenchmarkGroup = require("./BenchmarkGroup");
+const { performance } = require("perf_hooks");
 
 class BenchmarkManager {
   constructor() {
-    this.benches = {};
+    this.benchmarkGroups = {};
     this.isVerbose = true;
+    this.start = this.getNewTimestamp();
   }
 
   reset() {
-    for (var j in this.benches) {
-      this.benches[j].reset();
+    this.start = this.getNewTimestamp();
+
+    for (var j in this.benchmarkGroups) {
+      this.benchmarkGroups[j].reset();
     }
   }
 
+  getNewTimestamp() {
+    if (performance) {
+      return performance.now();
+    }
+    return new Date().getTime();
+  }
+
   setVerboseOutput(isVerbose) {
     this.isVerbose = !!isVerbose;
   }
 
   getBenchmarkGroup(name) {
-    if (!this.benches[name]) {
-      this.benches[name] = new BenchmarkGroup();
+    if (!this.benchmarkGroups[name]) {
+      this.benchmarkGroups[name] = new BenchmarkGroup();
+
+      // Special behavior for aggregate benchmarks
+      // so they don’t console.log every time
+      if (name === "Aggregate") {
+        this.benchmarkGroups[name].setIsVerbose(false);
+      } else {
+        this.benchmarkGroups[name].setIsVerbose(this.isVerbose);
+      }
     }
 
-    return this.benches[name];
+    return this.benchmarkGroups[name];
   }
 
   getAll() {
-    return this.benches;
+    return this.benchmarkGroups;
   }
 
   get(name) {
@@ -36,9 +55,10 @@ class BenchmarkManager {
     return this.getAll();
   }
 
-  finish(thresholdPercent) {
-    for (var j in this.benches) {
-      this.benches[j].finish(j, thresholdPercent, this.isVerbose);
+  finish() {
+    let totalTimeSpentBenchmarking = this.getNewTimestamp() - this.start;
+    for (var j in this.benchmarkGroups) {
+      this.benchmarkGroups[j].finish(j, totalTimeSpentBenchmarking);
     }
   }
 }

src/Eleventy.js

@@ -227,15 +227,11 @@ class Eleventy {
 
     let writeCount = this.writer.getWriteCount();
     let skippedCount = this.writer.getSkippedCount();
-
     let copyCount = this.writer.getCopyCount();
-    let skippedCopyCount = this.writer.getSkippedCopyCount();
 
     if (copyCount) {
       ret.push(
-        `Copied ${copyCount} ${simplePlural(copyCount, "item", "items")}${
-          skippedCopyCount ? ` (skipped ${skippedCopyCount})` : ""
-        } /`
+        `Copied ${copyCount} ${simplePlural(copyCount, "file", "files")} /`
       );
     }
 
@@ -634,6 +630,9 @@ Arguments:
     // See: TemplateWriter:pathCache and EleventyWatchTargets
     await this.write();
 
+    let initWatchBench = this.watcherBench.get("Start up --watch");
+    initWatchBench.before();
+
     await this.initWatch();
 
     // TODO improve unwatching if JS dependencies are removed (or files are deleted)
@@ -642,7 +641,10 @@ Arguments:
 
     let watcher = chokidar.watch(rawFiles, this.getChokidarConfig());
 
-    this.watcherBench.finish("Initialize --watch", 10, this.isVerbose);
+    initWatchBench.after();
+
+    this.watcherBench.setIsVerbose(true);
+    this.watcherBench.finish("Watch");
 
     console.log("Watching…");
 

src/EleventyFiles.js

@@ -10,6 +10,7 @@ const TemplatePassthroughManager = require("./TemplatePassthroughManager");
 const config = require("./Config");
 const debug = require("debug")("Eleventy:EleventyFiles");
 // const debugDev = require("debug")("Dev:Eleventy:EleventyFiles");
+const aggregateBench = require("./BenchmarkManager").get("Aggregate");
 
 class EleventyFiles {
   constructor(input, outputDir, formats, passthroughAll) {
@@ -313,12 +314,15 @@ class EleventyFiles {
     let globs = this.getFileGlobs();
 
     debug("Searching for: %o", globs);
+    let bench = aggregateBench.get("Searching the file system");
+    bench.before();
     let paths = TemplatePath.addLeadingDotSlashArray(
       await fastglob(globs, {
         caseSensitiveMatch: false,
         dot: true
       })
     );
+    bench.after();
 
     if ("extensionMap" in this.config) {
       let extensions = this.config.extensionMap;
@@ -355,13 +359,17 @@ class EleventyFiles {
   // TODO this isn’t great but reduces complexity avoiding using TemplateData:getLocalDataPaths for each template in the cache
   async getWatcherTemplateJavaScriptDataFiles() {
     let globs = await this.getTemplateData().getTemplateJavaScriptDataFileGlob();
-    return TemplatePath.addLeadingDotSlashArray(
+    let bench = aggregateBench.get("Searching the file system");
+    bench.before();
+    let results = TemplatePath.addLeadingDotSlashArray(
       await fastglob(globs, {
         ignore: ["**/node_modules/**"],
         caseSensitiveMatch: false,
         dot: true
       })
     );
+    bench.after();
+    return results;
   }
 
   /* Ignored by `eleventy --watch` */

src/Engines/TemplateEngine.js

@@ -3,6 +3,7 @@ const fs = require("fs-extra");
 const TemplatePath = require("../TemplatePath");
 const EleventyExtensionMap = require("../EleventyExtensionMap");
 const debug = require("debug")("Eleventy:TemplateEngine");
+const aggregateBench = require("../BenchmarkManager").get("Aggregate");
 
 class TemplateEngine {
   constructor(name, includesDir) {
@@ -61,6 +62,8 @@ class TemplateEngine {
     // TODO: reuse mustache partials in handlebars?
     let partialFiles = [];
     if (this.includesDir) {
+      let bench = aggregateBench.get("Searching the file system");
+      bench.before();
       this.extensions.forEach(function(extension) {
         partialFiles = partialFiles.concat(
           fastglob.sync(prefix + extension, {
@@ -69,6 +72,7 @@ class TemplateEngine {
           })
         );
       });
+      bench.after();
     }
 
     partialFiles = TemplatePath.addLeadingDotSlashArray(partialFiles);

src/Template.js

@@ -14,8 +14,10 @@ const TemplateFileSlug = require("./TemplateFileSlug");
 const ComputedData = require("./ComputedData");
 const Pagination = require("./Plugins/Pagination");
 const TemplateContentPrematureUseError = require("./Errors/TemplateContentPrematureUseError");
+
 const debug = require("debug")("Eleventy:Template");
 const debugDev = require("debug")("Dev:Eleventy:Template");
+const bench = require("./BenchmarkManager").get("Aggregate");
 
 class Template extends TemplateContent {
   constructor(path, inputDir, outputDir, templateData) {
@@ -553,7 +555,10 @@ class Template extends TemplateContent {
     if (!shouldWriteFile) {
       this.skippedCount++;
     } else {
+      let templateBenchmark = bench.get("Template Write");
+      templateBenchmark.before();
       return fs.outputFile(outputPath, finalContent).then(() => {
+        templateBenchmark.after();
         this.writeCount++;
         debug(`${outputPath} ${lang.finished}.`);
       });
@@ -580,7 +585,8 @@ class Template extends TemplateContent {
     let promises = [];
     for (let page of mapEntry._pages) {
       let content = await this.renderPageEntry(mapEntry, page);
-      promises.push(this._write(page.outputPath, content));
+      let promise = this._write(page.outputPath, content);
+      promises.push(promise);
     }
 
     return Promise.all(promises);