Merge pull request #8491 from Agoric/control-profiling

Swingset startup & benchmark plumbing for node/v8 per-vat profiling & debugging

packages/SwingSet/src/controller/controller.js

@@ -103,6 +103,8 @@ function unhandledRejectionHandler(e, pr) {
  *   kernelBundle?: Bundle
  *   xsnapBundleData?: ReturnType<import('./bundle-handler.js').makeXsnapBundleData>,
  *   bundleHandler?: import('./bundle-handler.js').BundleHandler,
+ *   profileVats?: string[],
+ *   debugVats?: string[],
  * }} runtimeOptions
  */
 export async function makeSwingsetController(
@@ -126,6 +128,8 @@ export async function makeSwingsetController(
     warehousePolicy = {},
     overrideVatManagerOptions = {},
     xsnapBundleData = makeXsnapBundleData(),
+    profileVats = [],
+    debugVats = [],
   } = runtimeOptions;
   const {
     bundleHandler = makeWorkerBundleHandler(
@@ -146,9 +150,13 @@ export async function makeSwingsetController(
     tmpName,
     debug: !!env.XSNAP_DEBUG,
     workerTraceRootPath: env.XSNAP_TEST_RECORD,
+    profileVats,
+    debugVats,
   });
   const startSubprocessWorkerNode = makeStartSubprocessWorkerNode(
     startSubprocessWorker,
+    profileVats,
+    debugVats,
   );
 
   function writeSlogObject(obj) {

packages/SwingSet/src/controller/startNodeSubprocess.js

@@ -1,13 +1,27 @@
 import process from 'process';
 
-export function makeStartSubprocessWorkerNode(startSubprocessWorker) {
+export function makeStartSubprocessWorkerNode(
+  startSubprocessWorker,
+  profileVats,
+  debugVats,
+) {
   // launch a worker in a subprocess (which runs Node.js)
-  function startSubprocessWorkerNode(nameDisplayArg, nodeOptions) {
+  function startSubprocessWorkerNode(nameDisplayArg, vatID, nodeOptions) {
     const supervisorCodePath = new URL(
       '../supervisors/subprocess-node/supervisor-subprocess-node.js',
       import.meta.url,
     ).pathname;
     const args = nodeOptions ? [...nodeOptions] : [];
+    if (profileVats.includes(vatID)) {
+      args.push('--cpu-prof');
+      args.push('--cpu-prof-interval');
+      args.push('100');
+      args.push('--cpu-prof-name');
+      args.push(`CPU.${nameDisplayArg}.cpuprofile`);
+    }
+    if (debugVats.includes(vatID)) {
+      args.push('--inspect-brk');
+    }
     args.push(supervisorCodePath);
     args.push(nameDisplayArg);
     return startSubprocessWorker(process.execPath, args);

packages/SwingSet/src/controller/startXSnap.js

@@ -41,6 +41,8 @@ const NETSTRING_MAX_CHUNK_SIZE = 12_000_000;
  *   debug?: boolean,
  *   workerTraceRootPath?: string,
  *   overrideBundles?: import('../types-external.js').Bundle[],
+ *   profileVats?: string[],
+ *   debugVats?: string[],
  * }} options
  */
 export function makeStartXSnap(options) {
@@ -54,6 +56,8 @@ export function makeStartXSnap(options) {
     snapStore,
     workerTraceRootPath,
     overrideBundles,
+    profileVats = [],
+    debugVats = [],
     debug = false,
   } = options;
 
@@ -123,6 +127,7 @@ export function makeStartXSnap(options) {
    * @param {string} name
    * @param {object} details
    * @param {import('../types-external.js').BundleID[]} details.bundleIDs
+   * @param {string} details.vatID
    * @param {(request: Uint8Array) => Promise<Uint8Array>} details.handleCommand
    * @param {boolean} [details.metered]
    * @param {StartXSnapInitDetails} [details.init]
@@ -131,11 +136,18 @@ export function makeStartXSnap(options) {
     name,
     {
       bundleIDs,
+      vatID,
       handleCommand,
       metered,
       init: initDetails = { from: 'bundles' },
     },
   ) {
+    if (profileVats.includes(vatID)) {
+      Fail`startXSnap: not yet supporting profiling for vat ${vatID}`;
+    }
+    if (debugVats.includes(vatID)) {
+      Fail`startXSnap: not yet supporting debugging for vat ${vatID}`;
+    }
     const meterOpts = metered ? {} : { meteringLimit: 0 };
     const snapshotLoadOpts = getSnapshotLoadOptions(initDetails);
     await null;

packages/SwingSet/src/kernel/vat-loader/manager-subprocess-node.js

@@ -30,14 +30,15 @@ export function makeNodeSubprocessFactory(tools) {
       Fail`nodeOptions must be an array`;
 
     // Node worker subprocess adds `nameDisplayArg` as a dummy argument so that
-    // 'ps'shows which worker is for which vat
+    // 'ps' shows which worker is for which vat
     const nameDisplayArg = `${vatID}:${name !== undefined ? name : ''}`;
 
     const mk = makeManagerKit();
 
     // start the worker and establish a connection
-    const { fromChild, toChild, terminate, done } = startSubprocessWorker(
+    const { fromChild, toChild, done } = startSubprocessWorker(
       nameDisplayArg,
+      vatID,
       nodeOptions,
     );
 
@@ -107,7 +108,8 @@ export function makeNodeSubprocessFactory(tools) {
     sendToWorker(['setBundle', vatID, bundle, liveSlotsOptions]);
 
     function shutdown() {
-      terminate();
+      // terminate(); // XXX currently disabled since it breaks profiling; we should revisit if we develop a problem with worker vat processes refusing to exit when requested to do so
+      sendToWorker(['exit']);
       return E.when(done, _ => undefined);
     }
     const manager = mk.getManager(shutdown);

packages/SwingSet/src/kernel/vat-loader/manager-subprocess-xsnap.js

@@ -143,6 +143,7 @@ export function makeXsSubprocessFactory({
     // start the worker and establish a connection
     let worker = await startXSnap(nameDisplayArg, {
       bundleIDs,
+      vatID,
       handleCommand: handleCommandKit.handleCommand,
       metered,
       init: snapshotInfo && { from: 'snapStore', vatID },
@@ -258,6 +259,7 @@ export function makeXsSubprocessFactory({
       [worker, snapshotResults] = await Promise.all([
         startXSnap(nameDisplayArg, {
           bundleIDs,
+          vatID,
           handleCommand: handleCommandKit.handleCommand,
           metered,
           init: {

packages/SwingSet/src/supervisors/subprocess-node/supervisor-subprocess-node.js

@@ -6,6 +6,7 @@ import '@endo/init';
 import anylogger from 'anylogger';
 import fs from 'fs';
 import { Buffer } from 'buffer';
+import process from 'node:process';
 
 import { assert, details as X, Fail } from '@agoric/assert';
 import { importBundle } from '@endo/import-bundle';
@@ -188,6 +189,9 @@ async function handleCommand(command) {
       return handleSetBundle(margs);
     case 'deliver':
       return handleDeliver(margs);
+    case 'exit':
+      process.exit(0);
+      break;
     default:
       throw Error(`unrecognized downlink message ${type}`);
   }

packages/benchmark/doc/benchmarkerator.md

@@ -101,7 +101,7 @@ provides various information about the execution.  It has the properties:
 
 `options: Record<string, string>`
 
-  Named options from the command line (see Command Line below).
+  Named configuration options from the command line (see Command Line below).
 
 `argv: string[]`
 
@@ -139,12 +139,16 @@ The supported command line options are:
 |--------|------|
 | `-r N`<br/>`--rounds N` | Execute _N_ rounds of each benchmark |
 | `-b PATT`<br/>`--benchmark PATT` | Only execute benchmarks matching _PATT_ (may be specified more than once; this is similar to Ava's `-m` option)|
-| `-o NAME VAL`<br/>`--option NAME VAL` | Set option _NAME_ to _VAL_ in the `context.options` record (may be specified more than once)  |
+| `-c NAME VAL`<br/>`--config NAME VAL` | Set configuration option _NAME_ to _VAL_ in the `context.options` record (may be specified more than once)  |
 | `-v`<br/>`--verbose` | Enable verbose output |
 | `--vat-type TYPE` | Use the specified vat manager type rather than the default `xs-worker` |
 | `-l`<br/>`--local` | Shorthand for `--vat-type local` (vats run in the same process as the kernel; less realistic than `xs-worker` but much faster and easier to debug) |
-| `-d PATH`<br/>`--dump PATH` | Output JSON-formated benchmark data into _PATH_ |
-| `-s PATH`<br/>`--slot PATH` | Output a log file into _PATH_ |
+| `-n`<br/>`--node` | Shorthand for `--vat-type node-subprocess` |
+| `-x`<br/>`--xs` | Shorthand for `--vat-type xs-worker` |
+| `-o PATH`<br/>`--output PATH` | Output JSON-formated benchmark data into _PATH_ |
+| `-s PATH`<br/>`--slog PATH` | Output a slog file into _PATH_ |
+| `-p VATID`<br/>`--profile VATID` | Collect CPU profile data for vat VATID |
+| `-d VATID`<br/>`--debug VATID` | Enable debug mode for vat VATID |
 | `-h`<br/>`--help` | Output this helpful usage information and then exit |
 
 An optional `--` flag ends the options list.  Any remaining command line
@@ -157,13 +161,21 @@ Timing results and other collected metrics are output to _stdout_.  Two batches
 of information are provided: one for the setup phase and one for the benchmark
 rounds themselves (in aggregate).
 
-If you specify the `--dump FILEPATH` command line option, a JSON-formatted
+If you specify the `--output FILEPATH` command line option, a JSON-formatted
 (i.e., machine readable) version of this same data will be output to the
 indicated file.
 
 Output results include execution times (according to Node's nanosecond clock),
 crank counts, and the various kernel resource usage data reported by
 `controller.getStats()`.
 
+Per-vat JS engine-level profiling is enabled for a given vat via the `--profile
+VATID` command line option.  Note that this option is only available when the
+vat manager type is `node-process` or `xs-worker`.  For `node-process` vats, the
+profiling data will be placed in the file `CPU.${vatID}:${vatName}.cpuprofile`.
+The `.cpuprofile` file format can be read and displayed by Chrome debugger, VS
+Code plugins available for this purpose, and various other tools.  For
+`xs-worker` vats, profiling data format is TBD.
+
 In addition, if you specify the `--slog FILEPATH` command line option, a
 SwingSet slog file for the run will be output to the file indicated.

packages/benchmark/src/benchmarkerator.js

@@ -132,31 +132,45 @@ ${process.argv[0]} ${process.argv[1]} [FLAGS] [-- [ARGS...]]
 
 FLAGS may be:
   -r N
-  --rounds N       - execute N rounds of each benchmark by default
+  --rounds N        - execute N rounds of each benchmark
 
   -b PATT
-  --benchmark PATT - only execute benchmarks matching PATT (may be specified more than once)
+  --benchmark PATT  - only execute benchmarks matching PATT (may be specified more than once)
 
   -v
-  --verbose        - output verbose debugging messages it runs
+  --verbose         - output verbose debugging messages as it runs
 
-  -o NAME VAL
-  --option NAME VAL - set named option NAME to VAL
+  -c NAME VAL
+  --config NAME VAL - set named configuration option NAME to VAL
 
-  --vat-type TYPE  - use the specified vat manager type rather than the default 'xs-worker'
+  --vat-type TYPE   - use the specified vat manager type rather than the default 'xs-worker'
 
   -l
-  --local          - shorthand for '--vat-type local'
-                     (less realistic perf numbers but faster and easier to debug)
+  --local           - shorthand for '--vat-type local'
+                      (less realistic perf numbers but faster and easier to debug)
+
+  -n
+  --node            - shorthand for '--vat-type node-subprocess'
+                      (similar to --local, but enables per-vat profiling and debugging in v8)
+
+  -x
+  --xs              - shorthand for '--vat-type xs-worker'
+                      (the default; provided for completeness)
+
+  -p VATID
+  --profile VATID   - turn on CPU profile for vat VATID (may be repeated for multiple vats)
+
+  -d VATID
+  --debug VATID     - turn on debugging for vat VATID
 
   -s PATH
-  --slog PATH      - output a slog file into PATH
+  --slog PATH       - output a slog file into PATH
 
-  -d PATH
-  --dump PATH      - output JSON-formatted benchmark data into PATH
+  -o PATH
+  --output PATH     - output JSON-formatted benchmark data into PATH
 
   -h
-  --help           - output this helpful usage information and then exit
+  --help            - output this helpful usage information and then exit
 
 additional ARGS are passed to the benchmark in the context.argv array
 `);
@@ -171,6 +185,8 @@ const fail = (message, printUsage) => {
 };
 
 let stillScanningArgs = true;
+const profileVats = [];
+const debugVats = [];
 while (argv[0] && stillScanningArgs) {
   const flag = argv.shift();
   switch (flag) {
@@ -186,8 +202,8 @@ while (argv[0] && stillScanningArgs) {
     case '--verbose':
       verbose = true;
       break;
-    case '-d':
-    case '--dump':
+    case '-o':
+    case '--output':
       dumpFile = argv.shift();
       break;
     case '--vat-type': {
@@ -208,17 +224,33 @@ while (argv[0] && stillScanningArgs) {
     case '--local':
       defaultManagerType = 'local';
       break;
+    case '-n':
+    case '--node':
+      defaultManagerType = 'node-subprocess';
+      break;
+    case '-x':
+    case '--xs':
+      defaultManagerType = 'xs-worker';
+      break;
     case '-?':
     case '-h':
     case '--help':
       help = true;
       break;
+    case '-p':
+    case '--profile':
+      profileVats.push(argv.shift());
+      break;
+    case '-d':
+    case '--debug':
+      debugVats.push(argv.shift());
+      break;
     case '-s':
     case '--slog':
       slogFile = argv.shift();
       break;
-    case '-o':
-    case '--option': {
+    case '-c':
+    case '--config': {
       const optionName = argv.shift();
       const optionValue = argv.shift();
       options[optionName] = optionValue;
@@ -233,6 +265,15 @@ while (argv[0] && stillScanningArgs) {
   }
 }
 
+if (defaultManagerType === 'local') {
+  if (profileVats.length > 0) {
+    fail`per-vat profiling not supported under vat type 'local'`;
+  }
+  if (debugVats.length > 0) {
+    fail`per-vat debugging not supported under vat type 'local'`;
+  }
+}
+
 harden(options);
 
 if (help) {
@@ -441,6 +482,8 @@ export const makeBenchmarkerator = async () => {
   const swingsetTestKit = await makeSwingsetTestKit(console.log, undefined, {
     defaultManagerType,
     verbose,
+    profileVats,
+    debugVats,
     slogFile,
   });
   const {

packages/boot/tools/supports.ts

@@ -244,6 +244,8 @@ export const matchIter = (t: AvaT, iter, valueRef) => {
  * @param [options.storage]
  * @param [options.verbose]
  * @param [options.slogFile]
+ * @param [options.profileVats]
+ * @param [options.debugVats]
  * @param [options.defaultManagerType]
  */
 export const makeSwingsetTestKit = async (
@@ -254,6 +256,8 @@ export const makeSwingsetTestKit = async (
     storage = makeFakeStorageKit('bootstrapTests'),
     verbose = false,
     slogFile = undefined as string | undefined,
+    profileVats = [] as string[],
+    debugVats = [] as string[],
     defaultManagerType = 'local' as ManagerType,
   } = {},
 ) => {
@@ -363,7 +367,7 @@ export const makeSwingsetTestKit = async (
     configPath,
     [],
     {},
-    { debugName: 'TESTBOOT', verbose, slogSender },
+    { debugName: 'TESTBOOT', verbose, slogSender, profileVats, debugVats },
   );
   console.timeLog('makeBaseSwingsetTestKit', 'buildSwingset');