Merge pull request #1140 from Agoric/perf-tools

Add simple stats dumping capability to swingset runner and kernel dumper

packages/swingset-runner/.eslintrc.js

@@ -20,6 +20,7 @@ module.exports = {
     'no-restricted-syntax': ['off', 'ForOfStatement'],
     'no-unused-expressions': 'off',
     'no-loop-func': 'off',
+    'yoda': ['error', 'never', { 'exceptRange': true }],
     'import/prefer-default-export': 'off', // contrary to Agoric standard
   },
   globals: {

packages/swingset-runner/demo/megaPong/bootstrap.js

@@ -23,7 +23,7 @@ export default function setup(syscall, state, helpers) {
               r => log(`=> alice.introduceYourselfTo(bob) resolved to '${r}'`),
               e => log(`=> alice.introduceYourselfTo(bob) rejected as '${e}'`),
             );
-          const count = Number(argv[0]);
+          const count = argv[0] ? Number(argv[0]) : 10;
           E(vats.alice).grind('hey!', count);
         },
       }),

packages/swingset-runner/demo/resolveChain/bootstrap.js

@@ -3,11 +3,14 @@ import harden from '@agoric/harden';
 console.log(`=> loading bootstrap.js`);
 
 function build(E, log) {
+  let count;
   function waitFor(who, p) {
     p.then(
       answer => {
-        log(`Alice: Bob answers with value ${answer[0]}`);
-        if (answer[0] < 3) {
+        if (0 < count && count < 50) {
+          log(`Alice: Bob answers with value ${answer[0]}`);
+        }
+        if (answer[0] < count || count < 0) {
           E(who).gen();
           waitFor(who, answer[1]);
         }
@@ -20,6 +23,7 @@ function build(E, log) {
 
   return {
     bootstrap(argv, vats) {
+      count = argv[0] ? Number(argv[0]) : 3;
       const bob = vats.bob;
       const p = E(bob).init();
       E(bob).gen();

packages/swingset-runner/src/kerneldump.js

@@ -7,21 +7,23 @@ import { openSwingStore as openSimpleSwingStore } from '@agoric/swing-store-simp
 
 import { dumpStore } from './dumpstore';
 import { auditRefCounts } from './auditstore';
+import { printStats } from './printStats';
 
 function usage() {
   console.log(`
 Command line:
   kerneldump [FLAGS...] [TARGET]
 
 FLAGS may be:
-  --raw       - just dump the kernel state database as key/value pairs
+  --raw       - dump the kernel state database as key/value pairs,
                 alphabetically without annotation
   --lmdb      - read an LMDB state database (default)
   --refcounts - audit kernel promise reference counts
   --auditonly - only audit, don't dump
   --filedb    - read a simple file-based (aka .jsonlines) data store
   --help      - print this helpful usage information
   --out PATH  - output dump to PATH ("-" indicates stdout, the default)
+  --stats     - just print summary stats and exit
 
 TARGET is one of: the base directory where a swingset's vats live, a swingset
 data store directory, or the path to a swingset database file.  If omitted, it
@@ -55,6 +57,7 @@ export function main() {
   const argv = process.argv.splice(2);
   let rawMode = false;
   let refCounts = false;
+  let justStats = false;
   let doDump = true;
   let dbMode = '--lmdb';
   let dbSuffix = '.mdb';
@@ -72,6 +75,9 @@ export function main() {
       case '--auditonly':
         doDump = false;
         break;
+      case '--stats':
+        justStats = true;
+        break;
       case '--help':
         usage();
         process.exit(0);
@@ -123,10 +129,16 @@ export function main() {
     default:
       fail(`invalid database mode ${dbMode}`, true);
   }
-  if (doDump) {
-    dumpStore(store.storage, outfile, rawMode);
-  }
-  if (refCounts) {
-    auditRefCounts(store.storage);
+  if (justStats) {
+    const stats = JSON.parse(store.storage.get('kernelStats'));
+    const cranks = Number(store.storage.get('crankNumber'));
+    printStats(stats, cranks);
+  } else {
+    if (doDump) {
+      dumpStore(store.storage, outfile, rawMode);
+    }
+    if (refCounts) {
+      auditRefCounts(store.storage);
+    }
   }
 }

packages/swingset-runner/src/main.js

@@ -16,6 +16,7 @@ import {
 
 import { dumpStore } from './dumpstore';
 import { auditRefCounts } from './auditstore';
+import { printStats } from './printStats';
 
 const log = console.log;
 
@@ -28,7 +29,7 @@ function readClock() {
 }
 
 function usage() {
-  console.log(`
+  log(`
 Command line:
   runner [FLAGS...] CMD [{BASEDIR|--} [ARGS...]]
 
@@ -38,21 +39,22 @@ FLAGS may be:
   --filedb       - runs using the simple file-based data store
   --memdb        - runs using the non-persistent in-memory data store
   --blockmode    - run in block mode (checkpoint every BLOCKSIZE blocks)
-  --blocksize N  - set BLOCKSIZE to N (default 200)
+  --blocksize N  - set BLOCKSIZE to N cranks (default 200)
   --logtimes     - log block execution time stats while running
   --logmem       - log memory usage stats after each block
   --logdisk      - log disk space usage stats after each block
   --logstats     - log kernel stats after each block
   --logall       - log kernel stats, block times, memory use, and disk space
   --logtag STR   - tag for stats log file (default "runner")
   --forcegc      - run garbage collector after each block
-  --batchsize N  - set BATCHSIZE to N (default 200)
+  --batchsize N  - set BATCHSIZE to N cranks (default 200)
   --verbose      - output verbose debugging messages as it runs
   --audit        - audit kernel promise reference counts after each crank
   --dump         - dump a kernel state store snapshot after each crank
   --dumpdir DIR  - place kernel state dumps in directory DIR (default ".")
   --dumptag STR  - prefix kernel state dump filenames with STR (default "t")
   --raw          - perform kernel state dumps in raw mode
+  --stats        - print performance stats at the end of a run
 
 CMD is one of:
   help   - print this helpful usage information
@@ -70,7 +72,7 @@ Any remaining args are passed to the swingset's bootstrap vat.
 }
 
 function fail(message, printUsage) {
-  console.log(message);
+  log(message);
   if (printUsage) {
     usage();
   }
@@ -102,6 +104,7 @@ export async function main() {
   let dumpDir = '.';
   let dumpTag = 't';
   let rawMode = false;
+  let shouldPrintStats = false;
 
   while (argv[0] && argv[0].startsWith('-')) {
     const flag = argv.shift();
@@ -157,6 +160,9 @@ export async function main() {
         rawMode = true;
         doDumps = true;
         break;
+      case '--stats':
+        shouldPrintStats = true;
+        break;
       case '--audit':
         doAudits = true;
         break;
@@ -196,7 +202,7 @@ export async function main() {
       );
     }
     if (!logMem) {
-      console.log('Warning: --forcegc without --logmem may be a mistake');
+      log('Warning: --forcegc without --logmem may be a mistake');
     }
   }
 
@@ -426,6 +432,10 @@ export async function main() {
     if (!runInBlockMode) {
       store.commit();
     }
+    if (shouldPrintStats) {
+      const cranks = Number(store.storage.get('crankNumber'));
+      printStats(controller.getStats(), cranks);
+    }
     store.close();
     if (logTimes) {
       if (totalSteps) {

packages/swingset-runner/src/printStats.js

@@ -0,0 +1,35 @@
+const log = console.log;
+
+export function printStats(stats, cranks) {
+  const wk = 32;
+  const wi = 9;
+  const wf = 8;
+
+  const h1 = `${'Stat'.padEnd(wk)}`;
+  const d1 = `${''.padEnd(wk, '-')}`;
+
+  const h2 = `${'Value'.padStart(wi)}`;
+  const d2 = ` ${''.padStart(wi - 1, '-')}`;
+
+  const h3 = `${'MaxValue'.padStart(wi)}`;
+  const d3 = ` ${''.padStart(wi - 1, '-')}`;
+
+  const h4 = ` ${'PerCrank'.padStart(wf)}`;
+  const d4 = ` ${''.padStart(wf, '-')}`;
+
+  log(`In ${cranks} cranks:`);
+  log(`${h1} ${h2} ${h3} ${h4}`);
+  log(`${d1} ${d2} ${d3} ${d4}`);
+
+  for (const [key, value] of Object.entries(stats)) {
+    if (!key.endsWith('Max')) {
+      const maxKey = `${key}Max`;
+      const col1 = `${key.padEnd(wk)}`;
+      const col2 = `${String(value).padStart(wi)}`;
+      const v3 = stats[maxKey] !== undefined ? stats[maxKey] : '';
+      const col3 = `${String(v3).padStart(wi)}`;
+      const col4 = `${String((value / cranks).toFixed(4)).padStart(wf)}`;
+      log(`${col1} ${col2} ${col3}  ${col4}`);
+    }
+  }
+}