feat: introduce slogCallbacks for the host to handle slog calls

michaelfig · michaelfig · commit e2eb92e1833b · 2021-03-20T00:41:58.000-06:00
This means rather than making another subsystem for SwingSet to
report metrics to the host at runtime, just intercept the existing
slog events and collate their data to produce the metrics we need.
diff --git a/packages/SwingSet/src/controller.js b/packages/SwingSet/src/controller.js
@@ -56,6 +56,7 @@ export async function makeSwingsetController(
   const {
     verbose,
     debugPrefix = '',
+    slogCallbacks,
     slogFile,
     testTrackDecref,
     defaultManagerType = env.WORKER_TYPE || 'local',
@@ -223,6 +224,7 @@ export async function makeSwingsetController(
     makeNodeWorker,
     startSubprocessWorkerNode,
     startXSnap,
+    slogCallbacks,
     writeSlogObject,
     WeakRef,
     FinalizationRegistry,
@@ -320,13 +322,15 @@ export async function buildVatController(
     verbose,
     kernelBundles,
     debugPrefix,
+    slogCallbacks,
     testTrackDecref,
     defaultManagerType,
   } = runtimeOptions;
   const actualRuntimeOptions = {
     verbose,
     debugPrefix,
     testTrackDecref,
+    slogCallbacks,
     defaultManagerType,
   };
   const initializationOptions = { verbose, kernelBundles };
diff --git a/packages/SwingSet/src/kernel/kernel.js b/packages/SwingSet/src/kernel/kernel.js
@@ -94,6 +94,7 @@ export default function buildKernel(
     hostStorage,
     debugPrefix,
     vatEndowments,
+    slogCallbacks = {},
     makeConsole,
     replaceGlobalMeter,
     transformMetering,
@@ -119,8 +120,8 @@ export default function buildKernel(
   );
 
   const kernelSlog = writeSlogObject
-    ? makeSlogger(writeSlogObject)
-    : makeDummySlogger(makeConsole);
+    ? makeSlogger(slogCallbacks, writeSlogObject)
+    : makeDummySlogger(slogCallbacks, makeConsole);
 
   const kernelKeeper = makeKernelKeeper(enhancedCrankBuffer, kernelSlog);
 
diff --git a/packages/SwingSet/src/kernel/metrics.js b/packages/SwingSet/src/kernel/metrics.js
@@ -83,6 +83,11 @@ export const KERNEL_STATS_UPDOWN_METRICS = [
     name: 'swingset_clist_entries',
     description: 'Number of entries in the kernel c-list',
   },
+  {
+    key: 'vats',
+    name: 'swingset_vats',
+    description: 'Number of active vats',
+  },
 ];
 
 export const KERNEL_STATS_METRICS = [
diff --git a/packages/SwingSet/src/kernel/slogger.js b/packages/SwingSet/src/kernel/slogger.js
@@ -1,22 +1,100 @@
-import { assert, details as X } from '@agoric/assert';
+import { assert, details as X, quote } from '@agoric/assert';
 
 const IDLE = 'idle';
 const STARTUP = 'startup';
 const DELIVERY = 'delivery';
 
-export function makeDummySlogger(makeConsole) {
+function makeCallbackRegistry(callbacks) {
+  const todo = new Set(Object.keys(callbacks));
   return harden({
-    addVat: () => 0,
-    vatConsole: () => makeConsole('disabled slogger'),
-    startup: () => () => 0, // returns nop finish() function
-    delivery: () => () => 0,
-    syscall: () => () => 0,
-    changeCList: () => () => 0,
-    terminateVat: () => () => 0,
+    /**
+     * Robustly wrap a method with a callbacks[method] function, if defined.  We
+     * incur no runtime overhead if the given callback method isn't defined.
+     *
+     * @param {string} method wrap with callbacks[method]
+     * @param {(...args: Array<unknown>) => unknown} impl the original
+     * implementation of the method
+     * @returns {(...args: Array<unknown>) => unknown} the wrapped method if the
+     * callback is defined, or original method if not
+     */
+    registerCallback(method, impl) {
+      todo.delete(method);
+      const cb = callbacks[method];
+      if (!cb) {
+        // No registered callback, just use the implementation directly.
+        console.error('no registered callback for', method);
+        return impl;
+      }
+
+      return (...args) => {
+        // Invoke the implementation first.
+        const ret = impl(...args);
+        try {
+          // Allow the callback to observe the call synchronously, and affect
+          // the finisher function, but not to throw an exception.
+          const cbRet = cb(method, args, ret);
+          if (typeof ret === 'function') {
+            // We wrap the finisher in the callback's return value.
+            return (...finishArgs) => {
+              try {
+                return cbRet(...finishArgs);
+              } catch (e) {
+                console.error(
+                  `failed to call registered ${method}.finish function:`,
+                  e,
+                );
+              }
+              return ret(...args);
+            };
+          }
+          // We just return the callback's return value.
+          return cbRet;
+        } catch (e) {
+          console.error('failed to call registered', method, 'callback:', e);
+        }
+        return ret;
+      };
+    },
+    /**
+     * Declare that all the methods have been registered.
+     *
+     * @param {string} errorUnusedMsg message to display if there are callback
+     * names that don't correspond to a registration
+     */
+    doneRegistering(errorUnusedMsg = `Unrecognized callback names:`) {
+      const cbNames = [...todo.keys()];
+      if (!cbNames.length) {
+        return;
+      }
+      console.warn(
+        errorUnusedMsg,
+        cbNames
+          .map(quote)
+          .sort()
+          .join(', '),
+      );
+    },
   });
 }
 
-export function makeSlogger(writeObj) {
+export function makeDummySlogger(slogCallbacks, makeConsole) {
+  const { registerCallback: reg, doneRegistering } = makeCallbackRegistry(
+    slogCallbacks,
+  );
+  const dummySlogger = harden({
+    addVat: reg('addVat', () => 0),
+    vatConsole: reg('vatConsole', () => makeConsole('disabled slogger')),
+    startup: reg('startup', () => () => 0), // returns nop finish() function
+    delivery: reg('delivery', () => () => 0),
+    syscall: reg('syscall', () => () => 0),
+    changeCList: reg('changeCList', () => () => 0),
+    terminateVat: reg('terminateVat', () => () => 0),
+  });
+  doneRegistering(`Unrecognized makeDummySlogger slogCallbacks names:`);
+  return dummySlogger;
+}
+
+export function makeSlogger(slogCallbacks, writeObj) {
   const write = writeObj ? e => writeObj(e) : () => 0;
 
   const vatSlogs = new Map(); // vatID -> vatSlog
@@ -28,7 +106,7 @@ export function makeSlogger(writeObj) {
     let syscallNum;
 
     function assertOldState(exp, msg) {
-      assert(state === exp, X`vat ${vatID} in ${state}, not ${exp}: ${msg}`);
+      assert.equal(state, exp, X`vat ${vatID} in ${state}, not ${exp}: ${msg}`);
     }
 
     function vatConsole(origConsole) {
@@ -65,9 +143,9 @@ export function makeSlogger(writeObj) {
       syscallNum = 0;
 
       // dr: deliveryResult
-      function finish(dr) {
+      function finish(dr, stats) {
         assertOldState(DELIVERY, 'delivery-finish called twice?');
-        write({ type: 'deliver-result', ...when, dr });
+        write({ type: 'deliver-result', ...when, dr, stats });
         state = IDLE;
       }
       return harden(finish);
@@ -126,13 +204,30 @@ export function makeSlogger(writeObj) {
   //   write({ type: 'annotate-vat', vatID, data });
   // }
 
-  return harden({
-    addVat,
-    vatConsole: (vatID, ...args) => vatSlogs.get(vatID).vatConsole(...args),
-    startup: (vatID, ...args) => vatSlogs.get(vatID).startup(...args),
-    delivery: (vatID, ...args) => vatSlogs.get(vatID).delivery(...args),
-    syscall: (vatID, ...args) => vatSlogs.get(vatID).syscall(...args),
-    changeCList: (vatID, ...args) => vatSlogs.get(vatID).changeCList(...args),
-    terminateVat: (vatID, ...args) => vatSlogs.get(vatID).terminateVat(...args),
+  const { registerCallback: reg, doneRegistering } = makeCallbackRegistry(
+    slogCallbacks,
+  );
+  const slogger = harden({
+    addVat: reg('addVat', addVat),
+    vatConsole: reg('vatConsole', (vatID, ...args) =>
+      vatSlogs.get(vatID).vatConsole(...args),
+    ),
+    startup: reg('startup', (vatID, ...args) =>
+      vatSlogs.get(vatID).startup(...args),
+    ),
+    delivery: reg('delivery', (vatID, ...args) =>
+      vatSlogs.get(vatID).delivery(...args),
+    ),
+    syscall: reg('syscall', (vatID, ...args) =>
+      vatSlogs.get(vatID).syscall(...args),
+    ),
+    changeCList: reg('changeCList', (vatID, ...args) =>
+      vatSlogs.get(vatID).changeCList(...args),
+    ),
+    terminateVat: reg('terminateVat', (vatID, ...args) =>
+      vatSlogs.get(vatID).terminateVat(...args),
+    ),
   });
+  doneRegistering(`Unrecognized makeSlogger slogCallbacks names:`);
+  return slogger;
 }
diff --git a/packages/SwingSet/src/kernel/state/kernelKeeper.js b/packages/SwingSet/src/kernel/state/kernelKeeper.js
@@ -457,6 +457,7 @@ export default function makeKernelKeeper(storage, kernelSlog) {
           break;
         }
       }
+      decStat('vats');
     }
 
     return kernelPromisesToReject;
@@ -543,6 +544,7 @@ export default function makeKernelKeeper(storage, kernelSlog) {
 
   function allocateUnusedVatID() {
     const nextID = Nat(BigInt(getRequired(`vat.nextID`)));
+    incStat('vats');
     storage.set(`vat.nextID`, `${nextID + 1n}`);
     return makeVatID(nextID);
   }
diff --git a/packages/cosmic-swingset/lib/launch-chain.js b/packages/cosmic-swingset/lib/launch-chain.js
@@ -15,6 +15,7 @@ import {
   loadSwingsetConfigFile,
 } from '@agoric/swingset-vat';
 import { assert, details as X } from '@agoric/assert';
+import makeStore from '@agoric/store';
 import { getBestSwingStore } from './check-lmdb';
 import { exportKernelStats } from './kernel-stats';
 
@@ -47,7 +48,7 @@ async function buildSwingset(
   storage,
   vatsDir,
   argv,
-  debugName = undefined,
+  { debugName = undefined, slogCallbacks },
 ) {
   const debugPrefix = debugName === undefined ? '' : `${debugName}:`;
   let config = loadSwingsetConfigFile(`${vatsDir}/chain-config.json`);
@@ -78,7 +79,9 @@ async function buildSwingset(
   if (!swingsetIsInitialized(storage)) {
     await initializeSwingset(config, argv, storage, { debugPrefix });
   }
-  const controller = await makeSwingsetController(storage, deviceEndowments);
+  const controller = await makeSwingsetController(storage, deviceEndowments, {
+    slogCallbacks,
+  });
 
   // We DON'T want to run the kernel yet, only when we're in the scheduler at
   // endBlock!
@@ -106,20 +109,88 @@ export async function launch(
     // console.error('would outbound bridge', dstID, obj);
     return doOutboundBridge(dstID, obj);
   }
+
+  const wrapDeltaMS = (finisher, useDeltaMS) => {
+    const startMS = Date.now();
+    return (...finishArgs) => {
+      try {
+        return finisher(...finishArgs);
+      } finally {
+        const deltaMS = Date.now() - startMS;
+        useDeltaMS(deltaMS, finishArgs);
+      }
+    };
+  };
+
+  // Not to be confused with the gas model, this meter is for OpenTelemetry.
+  const metricMeter = meterProvider.getMeter('ag-chain-cosmos');
+  const METRIC_LABELS = { app: 'ag-chain-cosmos' };
+
+  const nameToBaseMetric = makeStore('metricName');
+  nameToBaseMetric.init(
+    'swingset_vat_startup',
+    metricMeter.createValueRecorder('swingset_vat_startup', {
+      description: 'Vat startup time (ms)',
+    }),
+  );
+  nameToBaseMetric.init(
+    'swingset_vat_delivery',
+    metricMeter.createValueRecorder('swingset_vat_delivery', {
+      description: 'Vat delivery time (ms)',
+    }),
+  );
+  const vatToMetrics = makeStore();
+
+  const getVatMetric = (vatID, name) => {
+    let nameToMetric;
+    if (vatToMetrics.has(vatID)) {
+      nameToMetric = vatToMetrics.get(vatID);
+    } else {
+      nameToMetric = makeStore('metricName');
+      vatToMetrics.init(vatID, nameToMetric);
+    }
+    let metric;
+    if (nameToMetric.has(name)) {
+      metric = nameToMetric.get(name);
+    } else {
+      // Bind the base metric to the vatID label.
+      metric = nameToBaseMetric.get(name).bind({ ...METRIC_LABELS, vatID });
+      nameToMetric.init(name, metric);
+    }
+    return metric;
+  };
+
+  /**
+   * Measure some interesting stats.  We currently do a per-vat recording of
+   * time spent in the vat for startup and delivery.
+   */
+  const slogCallbacks = {
+    startup(_method, [vatID], finisher) {
+      return wrapDeltaMS(finisher, deltaMS => {
+        getVatMetric(vatID, 'swingset_vat_startup').record(deltaMS);
+      });
+    },
+    delivery(_method, [vatID], finisher) {
+      return wrapDeltaMS(finisher, (deltaMS, [_dr, _stats]) => {
+        // console.info(vatID, 'delivery.finish', stats);
+        getVatMetric(vatID, 'swingset_vat_delivery').record(deltaMS);
+      });
+    },
+  };
+
   log.debug(`buildSwingset`);
   const { controller, mb, bridgeInbound, timer } = await buildSwingset(
     mailboxStorage,
     bridgeOutbound,
     storage,
     vatsDir,
     argv,
-    debugName,
+    {
+      debugName,
+      slogCallbacks,
+    },
   );
 
-  const METRIC_LABELS = { app: 'ag-chain-cosmos' };
-
-  // Not to be confused with the gas model, this meter is for OpenTelemetry.
-  const metricMeter = meterProvider.getMeter('ag-chain-cosmos');
   exportKernelStats({ controller, metricMeter, log, labels: METRIC_LABELS });
 
   const schedulerCrankTimeHistogram = metricMeter

Original file line number	Diff line number	Diff line change
`@@ -457,6 +457,7 @@ export default function makeKernelKeeper(storage, kernelSlog) {`
`457`	`457`	`break;`
`458`	`458`	`}`
`459`	`459`	`}`
	`460`	`+ decStat('vats');`
`460`	`461`	`}`
`461`	`462`
`462`	`463`	`return kernelPromisesToReject;`
`@@ -543,6 +544,7 @@ export default function makeKernelKeeper(storage, kernelSlog) {`
`543`	`544`
`544`	`545`	`function allocateUnusedVatID() {`
`545`	`546`	const nextID = Nat(BigInt(getRequired(`vat.nextID`)));
	`547`	`+ incStat('vats');`
`546`	`548`	storage.set(`vat.nextID`, `${nextID + 1n}`);
`547`	`549`	`return makeVatID(nextID);`
`548`	`550`	`}`