feat(build): add Macro render report (#10372)

Counts how much each macro contributes to the total build time and
provides a report at the end of the build with these metrics:
- Count: Number of invocations.
- Min: Minimal render time.
- Avg: Average render time.
- Max: Maximal render time.
- Sum: Total render time.

build/cli.ts

@@ -31,6 +31,7 @@ import SearchIndex from "./search-index.js";
 import { makeSitemapXML, makeSitemapIndexXML } from "./sitemaps.js";
 import { humanFileSize } from "./utils.js";
 import { initSentry } from "./sentry.js";
+import { macroRenderTimes } from "../kumascript/src/render.js";
 
 const { program } = caporal;
 const { prompt } = inquirer;
@@ -402,6 +403,42 @@ function formatTotalFlaws(flawsCountMap, header = "Total_Flaws_Count") {
   return out.join("\n");
 }
 
+function nsToMs(bigint: bigint) {
+  return Number(bigint / BigInt(1_000)) / 1_000;
+}
+
+function formatMacroRenderReport(header = "Macro render report") {
+  const out = ["\n"];
+  out.push(header);
+
+  // Prepare data.
+  const stats = Object.entries(macroRenderTimes).map(([name, times]) => {
+    const sortedTimes = times.slice().sort(compareBigInt);
+    return {
+      name,
+      min: sortedTimes.at(0),
+      max: sortedTimes.at(-1),
+      count: times.length,
+      sum: times.reduce((acc, value) => acc + value, BigInt(0)),
+    };
+  });
+
+  // Sort by total render time.
+  stats.sort(({ sum: a }, { sum: b }) => Number(b - a));
+
+  // Format data.
+  out.push(
+    ["name", "count", "min (ms)", "avg (ms)", "max (ms)", "sum (ms)"].join(",")
+  );
+  for (const { name, min, max, count, sum } of stats) {
+    const avg = sum / BigInt(count);
+    out.push([name, count, ...[min, avg, max, sum].map(nsToMs)].join(","));
+  }
+
+  out.push("\n");
+  return out.join("\n");
+}
+
 interface BuildArgsAndOptions {
   args: {
     files?: string[];
@@ -560,6 +597,7 @@ program
         }
         console.log(`Peak heap memory usage: ${humanFileSize(peakHeapBytes)}`);
         console.log(formatTotalFlaws(totalFlaws));
+        console.log(formatMacroRenderReport());
       }
     } catch (error) {
       // So you get a stacktrace in the CLI output
@@ -570,3 +608,12 @@ program
   });
 
 program.run();
+function compareBigInt(a: bigint, b: bigint): number {
+  if (a < b) {
+    return -1;
+  } else if (a > b) {
+    return 1;
+  } else {
+    return 0;
+  }
+}

kumascript/src/render.ts

@@ -60,6 +60,8 @@ export function normalizeMacroName(name) {
   return name.replace(/:/g, "-").toLowerCase();
 }
 
+export const macroRenderTimes: Record<string, bigint[]> = {};
+
 export async function render(
   source: string,
   pageEnvironment,
@@ -166,6 +168,7 @@ export async function render(
     }
 
     const macroName = normalizeMacroName(token.name);
+    const startTime = process.hrtime.bigint();
 
     if (selectiveMode) {
       if (selectMacros.includes(macroName)) {
@@ -267,6 +270,9 @@ export async function render(
         errors.push(error);
       }
     }
+    const elapsedTime = process.hrtime.bigint() - startTime;
+    macroRenderTimes[macroName] ??= [];
+    macroRenderTimes[macroName].push(elapsedTime);
   }
   return [output, errors];
 }