Add CPU profiler command (#1352)

* Add debug:cpu command to profile CPU at startup

* Changesets

.changeset/metal-penguins-enjoy.md

@@ -0,0 +1,7 @@
+---
+'@shopify/cli-hydrogen': minor
+---
+
+We've added an experimental tool for profiling the CPU at startup. This is useful for debugging slow startup times when Oxygen deployments fail with related errors.
+
+Run the new `h2 debug cpu` command to build + watch your app and generate a `startup.cpuprofile` file that you can open in DevTools or VSCode to see a flamegraph of CPU usage.

packages/cli/oclif.manifest.json

@@ -592,6 +592,32 @@
       },
       "args": {}
     },
+    "hydrogen:debug:cpu": {
+      "id": "hydrogen:debug:cpu",
+      "description": "Builds and profiles the server startup time the app.",
+      "strict": true,
+      "pluginName": "@shopify/cli-hydrogen",
+      "pluginAlias": "@shopify/cli-hydrogen",
+      "pluginType": "core",
+      "aliases": [],
+      "flags": {
+        "path": {
+          "name": "path",
+          "type": "option",
+          "description": "The path to the directory of the Hydrogen storefront. The default is the current directory.",
+          "multiple": false
+        },
+        "output": {
+          "name": "output",
+          "type": "option",
+          "description": "Specify a path to generate the profile file. Defaults to \"startup.cpuprofile\".",
+          "required": false,
+          "multiple": false,
+          "default": "startup.cpuprofile"
+        }
+      },
+      "args": {}
+    },
     "hydrogen:env:list": {
       "id": "hydrogen:env:list",
       "description": "List the environments on your linked Hydrogen storefront.",

packages/cli/src/commands/hydrogen/debug/cpu.ts

@@ -0,0 +1,119 @@
+import {Flags} from '@oclif/core';
+import {joinPath, resolvePath} from '@shopify/cli-kit/node/path';
+import Command from '@shopify/cli-kit/node/base-command';
+import {outputInfo, outputWarn} from '@shopify/cli-kit/node/output';
+import colors from '@shopify/cli-kit/node/colors';
+import {writeFile} from '@shopify/cli-kit/node/fs';
+import ansiEscapes from 'ansi-escapes';
+import {
+  getProjectPaths,
+  getRemixConfig,
+  handleRemixImportFail,
+  type ServerMode,
+} from '../../../lib/remix-config.js';
+import {createRemixLogger, muteDevLogs} from '../../../lib/log.js';
+import {commonFlags, flagsToCamelObject} from '../../../lib/flags.js';
+import {createCpuStartupProfiler} from '../../../lib/cpu-profiler.js';
+
+const DEFAULT_OUTPUT_PATH = 'startup.cpuprofile';
+
+export default class DebugCpu extends Command {
+  static description = 'Builds and profiles the server startup time the app.';
+  static flags = {
+    path: commonFlags.path,
+    output: Flags.string({
+      description: `Specify a path to generate the profile file. Defaults to "${DEFAULT_OUTPUT_PATH}".`,
+      default: DEFAULT_OUTPUT_PATH,
+      required: false,
+    }),
+  };
+
+  async run(): Promise<void> {
+    const {flags} = await this.parse(DebugCpu);
+    const directory = flags.path ? resolvePath(flags.path) : process.cwd();
+    const output = flags.output
+      ? resolvePath(flags.output)
+      : joinPath(process.cwd(), flags.output);
+
+    await runDebugCpu({
+      ...flagsToCamelObject(flags),
+      path: directory,
+      output,
+    });
+  }
+}
+
+async function runDebugCpu({
+  path: appPath,
+  output = DEFAULT_OUTPUT_PATH,
+}: {
+  path?: string;
+  output?: string;
+}) {
+  if (!process.env.NODE_ENV) process.env.NODE_ENV = 'production';
+
+  muteDevLogs({workerReload: false});
+
+  const {root, buildPathWorkerFile} = getProjectPaths(appPath);
+
+  outputInfo(
+    '⏳️ Starting profiler for CPU startup... Profile will be written to:\n' +
+      colors.dim(output),
+  );
+
+  const runProfiler = await createCpuStartupProfiler();
+
+  const [{watch}, {createFileWatchCache}] = await Promise.all([
+    import('@remix-run/dev/dist/compiler/watch.js'),
+    import('@remix-run/dev/dist/compiler/fileWatchCache.js'),
+  ]).catch(handleRemixImportFail);
+
+  let times = 0;
+  const fileWatchCache = createFileWatchCache();
+
+  await watch(
+    {
+      config: await getRemixConfig(root),
+      options: {
+        mode: process.env.NODE_ENV as ServerMode,
+        sourcemap: true,
+      },
+      fileWatchCache,
+      logger: createRemixLogger(),
+    },
+    {
+      onBuildStart() {
+        if (times > 0) {
+          process.stdout.write(ansiEscapes.eraseLines(4));
+        }
+
+        outputInfo(`\n#${++times} Building and profiling...`);
+      },
+      async onBuildFinish(context, duration, succeeded) {
+        if (succeeded) {
+          const {profile, totalScriptTimeMs} = await runProfiler(
+            buildPathWorkerFile,
+          );
+
+          process.stdout.write(ansiEscapes.eraseLines(2));
+          outputInfo(
+            `#${times} Total time: ${totalScriptTimeMs.toLocaleString()} ms` +
+              `\n${colors.dim(output)}`,
+          );
+
+          await writeFile(output, JSON.stringify(profile, null, 2));
+
+          outputInfo(`\nWaiting for changes...`);
+        } else {
+          outputWarn('\nBuild failed, waiting for changes to restart...');
+        }
+      },
+      async onFileChanged(file) {
+        fileWatchCache.invalidateFile(file);
+      },
+      async onFileDeleted(file) {
+        fileWatchCache.invalidateFile(file);
+      },
+    },
+  );
+}

packages/cli/src/hooks/init.ts

@@ -7,7 +7,10 @@ const EXPERIMENTAL_VM_MODULES_FLAG = '--experimental-vm-modules';
 const hook: Hook<'init'> = async function (options) {
   if (
     options.id &&
-    ['hydrogen:dev', 'hydrogen:preview'].includes(options.id) &&
+    // All the commands that rely on MiniOxygen:
+    ['hydrogen:dev', 'hydrogen:preview', 'hydrogen:debug:cpu'].includes(
+      options.id,
+    ) &&
     !process.execArgv.includes(EXPERIMENTAL_VM_MODULES_FLAG) &&
     !(process.env.NODE_OPTIONS ?? '').includes(EXPERIMENTAL_VM_MODULES_FLAG)
   ) {

packages/cli/src/lib/cpu-profiler.ts

@@ -0,0 +1,130 @@
+import {readFile} from '@shopify/cli-kit/node/fs';
+import {Session, type Profiler} from 'node:inspector';
+import type {SourceMapConsumer} from 'source-map';
+
+export async function createCpuStartupProfiler() {
+  const {createMiniOxygen} = await import('@shopify/mini-oxygen');
+
+  const miniOxygen = createMiniOxygen({
+    script: 'export default {}',
+    modules: true,
+    log: () => {},
+  });
+
+  await miniOxygen.ready();
+
+  return async (scriptPath: string) => {
+    const script = await readFile(scriptPath);
+
+    const stopProfiler = await startProfiler();
+    await miniOxygen.reload({script});
+    const rawProfile = await stopProfiler();
+
+    return enhanceProfileNodes(rawProfile, scriptPath + '.map');
+  };
+}
+
+function startProfiler(): Promise<
+  (filepath?: string) => Promise<Profiler.Profile>
+> {
+  const session = new Session();
+  session.connect();
+
+  return new Promise((resolveStart) => {
+    session.post('Profiler.enable', () => {
+      session.post('Profiler.start', () => {
+        resolveStart(() => {
+          return new Promise((resolveStop, rejectStop) => {
+            session.post('Profiler.stop', (err, {profile}) => {
+              session.disconnect();
+
+              if (err) {
+                return rejectStop(err);
+              }
+
+              resolveStop(profile);
+            });
+          });
+        });
+      });
+    });
+  });
+}
+
+async function enhanceProfileNodes(
+  profile: Profiler.Profile,
+  sourceMapPath: string,
+) {
+  const {SourceMapConsumer} = await import('source-map');
+  const sourceMap = JSON.parse(await readFile(sourceMapPath));
+  const smc = await new SourceMapConsumer(sourceMap, 'file://' + sourceMapPath);
+
+  const scriptDescendants = new Set<number>();
+  let totalScriptTimeMicrosec = 0;
+  const totalTimeMicrosec = profile.endTime - profile.startTime;
+  const timePerSample = profile.samples?.length
+    ? totalTimeMicrosec / profile.samples.length
+    : 0;
+
+  for (const node of profile.nodes) {
+    if (node.callFrame.url === '<script>' || scriptDescendants.has(node.id)) {
+      scriptDescendants.add(node.id);
+      node.children?.forEach((id) => scriptDescendants.add(id));
+    }
+
+    if (scriptDescendants.has(node.id)) {
+      // Enhance paths with sourcemaps of known files.
+      augmentNode(node, smc);
+
+      // Accrue total time spent by the script (app + deps).
+      totalScriptTimeMicrosec +=
+        Math.round((node.hitCount ?? 0) * timePerSample * 1000) / 1000;
+    } else {
+      // These nodes are not part of the script (app + deps), so we
+      // silence them to remove visual noise from the profile.
+      silenceNode(node);
+    }
+  }
+
+  smc.destroy();
+
+  return {
+    profile,
+    totalTimeMs: totalTimeMicrosec / 1000,
+    totalScriptTimeMs: totalScriptTimeMicrosec / 1000,
+  };
+}
+
+function augmentNode(node: Profiler.ProfileNode, smc: SourceMapConsumer) {
+  const originalPosition = smc.originalPositionFor({
+    line: node.callFrame.lineNumber + 1,
+    column: node.callFrame.columnNumber + 1,
+  });
+
+  node.callFrame.url = originalPosition.source || node.callFrame.url;
+
+  // Some helpers like `__toESM(...)` etc. might not have a name
+  // after minification. These will show up as `(annonymous)`.
+  node.callFrame.functionName =
+    originalPosition.name || node.callFrame.functionName;
+
+  node.callFrame.lineNumber = originalPosition.line
+    ? originalPosition.line - 1
+    : node.callFrame.lineNumber;
+
+  node.callFrame.columnNumber =
+    originalPosition.column ?? node.callFrame.columnNumber;
+}
+
+function silenceNode(node: Profiler.ProfileNode) {
+  Object.assign(node, {
+    children: [],
+    callFrame: {
+      functionName: '(profiler)',
+      scriptId: '0',
+      url: '',
+      lineNumber: -1,
+      columnNumber: -1,
+    },
+  });
+}