Merge pull request #8765 from Agoric/8647-benchmarkerator-cleanup

Clean up Benchmarkerator doc and Benchmarkerator report output formatting

packages/benchmark/doc/benchmarkerator.md

@@ -150,7 +150,7 @@ provides various information about the execution.  It has the properties:
 The benchmark that you define by incorporating The Benchmarkerator is a
 standalone Node executable.  You run it with the command:
 
-`node benchmark-yourbenchmarkname.js [OPTIONS...]`
+`tsx benchmark-yourbenchmarkname.js [OPTIONS...]`
 
 The supported command line options are:
 
@@ -176,6 +176,13 @@ An optional `--` flag ends the options list.  Any remaining command line
 arguments after `--` are are passed to the benchmark itself in the
 `context.argv` array.
 
+Note that benchmarks are run with `tsx` rather than `node`.  This is because the
+benchmarking tools make use of TypeScript code that is part of our test
+infrastructure.  `tsx` actually runs `node`, but makes sure all the various
+magic environment voodoo is set up so that TypeScript code can also be
+executed.  If you do not have `tsx` in your environment, it can be installed
+from NPM.
+
 ## Results output
 
 Timing results and other collected metrics are output to _stdout_.  Two batches

packages/benchmark/src/benchmarkerator.js

@@ -447,7 +447,7 @@ const printBenchmarkStats = stats => {
   const dc1 = `${''.padEnd(wc1, '-')}`;
 
   const wc2 = 6;
-  const hc2 = `${'Delta'.padStart(wc2)}`;
+  const hc2 = `${'Total'.padStart(wc2)}`;
   const dc2 = ` ${''.padStart(wc2 - 1, '-')}`;
 
   const wc3 = 10;
@@ -480,15 +480,21 @@ const printBenchmarkStats = stats => {
   const hg4 = `${'Delta'.padStart(wg4)}`;
   const dg4 = ` ${''.padStart(wg4 - 1, '-')}`;
 
+  const wg5 = 9;
+  const hg5 = `${'PerRound'.padStart(wg5)}`;
+  const dg5 = ` ${''.padStart(wg5 - 1, '-')}`;
+
   log(``);
-  log(`${hg1} ${hg2} ${hg3} ${hg4}`);
-  log(`${dg1} ${dg2} ${dg3} ${dg4}`);
+  log(`${hg1} ${hg2} ${hg3} ${hg4} ${hg5}`);
+  log(`${dg1} ${dg2} ${dg3} ${dg4} ${dg5}`);
   for (const [key, entry] of Object.entries(stats.gauges)) {
     const col1 = `${key.padEnd(wg1)}`;
     const col2 = `${String(entry.start).padStart(wg2)}`;
     const col3 = `${String(entry.end).padStart(wg3)}`;
-    const col4 = `${String(entry.end - entry.start).padStart(wg4)}`;
-    log(`${col1} ${col2} ${col3} ${col4}`);
+    const delta = entry.end - entry.start;
+    const col4 = `${String(delta).padStart(wg4)}`;
+    const col5 = `${pn(delta / stats.rounds).padStart(wg5)}`;
+    log(`${col1} ${col2} ${col3} ${col4} ${col5}`);
   }
 };
 
@@ -547,6 +553,13 @@ const organizeRoundsStats = (rounds, perRoundStats) => {
 export const makeBenchmarkerator = async () => {
   const benchmarks = new Map();
 
+  if (slogFile) {
+    // Kernel slogger will append to the slog file if it already exists, but
+    // here we don't want that because repeat runs would result in confusing
+    // slog output due to crank numbers, vat IDs, krefs, and vrefs all resetting
+    // with each run.
+    fs.unlinkSync(slogFile);
+  }
   const setupStartTime = readClock();
   const swingsetTestKit = await makeSwingsetTestKit(console.log, undefined, {
     defaultManagerType,
@@ -688,12 +701,13 @@ export const makeBenchmarkerator = async () => {
       benchmarkContext.title = title;
       const rounds = commandLineRounds || benchmark.rounds || 1;
       benchmarkContext.rounds = rounds;
-      log(`Benchmark "${title}" setup:`);
-      benchmarkContext.config = await (benchmark.setup
-        ? benchmark.setup(benchmarkContext)
-        : {});
-      log(`Benchmark "${title}" setup complete`);
-      log(`------------------------------------------------------------------`);
+      if (benchmark.setup) {
+        log(`Benchmark "${title}" setup:`);
+        benchmarkContext.config = await benchmark.setup(benchmarkContext);
+      } else {
+        log(`Benchmark "${title}" no setup function configured`);
+      }
+      log('-'.repeat(70));
       const perRoundStats = [];
       for (let round = 1; round <= rounds; round += 1) {
         if (benchmark.setupRound) {
@@ -704,26 +718,30 @@ export const makeBenchmarkerator = async () => {
           time: readClock(),
           cranks: getCrankNumber(),
         };
-        log(`Benchmark "${title}" round ${round}:`);
+        log(`Benchmark "${title}" round ${round} start crank ${start.cranks}`);
         await benchmark.executeRound(benchmarkContext, round);
         const end = {
           rawStats: controller.getStats(),
           time: readClock(),
           cranks: getCrankNumber(),
         };
+        log(`Benchmark "${title}" round ${round} end crank ${end.cranks - 1}`);
+        log('-'.repeat(70));
         perRoundStats.push({ start, end });
         if (benchmark.finishRound) {
           await benchmark.finishRound(benchmarkContext, round);
         }
       }
       const benchmarkStats = organizeRoundsStats(rounds, perRoundStats);
-      log('-'.repeat(70));
       log(`Benchmark "${title}" stats:`);
       printBenchmarkStats(benchmarkStats);
       benchmarkReport[title] = benchmarkStats;
       log('-'.repeat(70));
       if (benchmark.finish) {
+        log(`Benchmark "${title}" setup:`);
         await benchmark.finish(benchmarkContext);
+      } else {
+        log(`Benchmark "${title}" no finish function configured`);
       }
     }
     await eventLoopIteration();