diff --git a/.changeset/metal-penguins-enjoy.md b/.changeset/metal-penguins-enjoy.md new file mode 100644 index 0000000000..44199e5d96 --- /dev/null +++ b/.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. diff --git a/packages/cli/oclif.manifest.json b/packages/cli/oclif.manifest.json index 86e0e4d1c5..9ab916f8ec 100644 --- a/packages/cli/oclif.manifest.json +++ b/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.", diff --git a/packages/cli/src/commands/hydrogen/debug/cpu.ts b/packages/cli/src/commands/hydrogen/debug/cpu.ts new file mode 100644 index 0000000000..ad4a3d627e --- /dev/null +++ b/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 { + 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); + }, + }, + ); +} diff --git a/packages/cli/src/hooks/init.ts b/packages/cli/src/hooks/init.ts index 09a6f22af0..0ab873548c 100644 --- a/packages/cli/src/hooks/init.ts +++ b/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) ) { diff --git a/packages/cli/src/lib/cpu-profiler.ts b/packages/cli/src/lib/cpu-profiler.ts new file mode 100644 index 0000000000..4d56c07472 --- /dev/null +++ b/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 +> { + 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(); + 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 === '