diff --git a/.changeset/startup-profile-summary.md b/.changeset/startup-profile-summary.md new file mode 100644 index 00000000000..cd4380f462b --- /dev/null +++ b/.changeset/startup-profile-summary.md @@ -0,0 +1,7 @@ +--- +"wrangler": minor +--- + +Graduate `wrangler check startup` from alpha and show bundle size and a local timing summary + +The command no longer prints an alpha warning. It now reports its local profile window, sampled active, garbage collection, and idle time alongside the raw and compressed bundle sizes. The existing measurement warning continues to distinguish these local measurements from startup time measured on Cloudflare. diff --git a/packages/wrangler/src/__tests__/startup-profiling.test.ts b/packages/wrangler/src/__tests__/startup-profiling.test.ts index c2b20b1f98a..2dcb4a2982c 100644 --- a/packages/wrangler/src/__tests__/startup-profiling.test.ts +++ b/packages/wrangler/src/__tests__/startup-profiling.test.ts @@ -5,6 +5,7 @@ import { writeWranglerConfig, } from "@cloudflare/workers-utils/test-helpers"; import { afterEach, beforeEach, describe, test } from "vitest"; +import { summarizeStartupProfile } from "../check/commands"; import { logger } from "../logger"; import { collectCLIOutput } from "./helpers/collect-cli-output"; import { mockConsoleMethods } from "./helpers/mock-console"; @@ -33,6 +34,13 @@ describe("wrangler check startup", () => { expect(std.out).toContain( `CPU Profile has been written to worker-startup.cpuprofile` ); + expect(std.out).toMatch(/Bundle: \d+\.\d{2} KiB \/ gzip: \d+\.\d{2} KiB/); + expect(std.out).toContain("Local startup profile:"); + expect(std.out).toContain("Profile window:"); + expect(std.out).toContain("Sampled time:"); + expect(std.out).toContain("Active:"); + expect(std.out).toContain("Idle:"); + expect(std.out).toContain("Samples:"); await expect( readFile("worker-startup.cpuprofile", "utf8") @@ -160,3 +168,57 @@ describe("wrangler check startup", () => { ).resolves.toContain("callFrame"); }); }); + +describe("summarizeStartupProfile", () => { + test("separates active, garbage collection, and idle samples", ({ + expect, + }) => { + expect( + summarizeStartupProfile({ + nodes: [ + { + id: 1, + callFrame: { + functionName: "(idle)", + scriptId: "0", + url: "", + lineNumber: -1, + columnNumber: -1, + }, + }, + { + id: 2, + callFrame: { + functionName: "(garbage collector)", + scriptId: "0", + url: "", + lineNumber: -1, + columnNumber: -1, + }, + }, + { + id: 3, + callFrame: { + functionName: "startup", + scriptId: "1", + url: "index.js", + lineNumber: 0, + columnNumber: 0, + }, + }, + ], + startTime: 1_000, + endTime: 8_000, + samples: [1, 2, 3], + timeDeltas: [1_000, 2_000, 3_000], + }) + ).toEqual({ + profileWindow: 7_000, + sampledTime: 6_000, + activeTime: 5_000, + garbageCollectionTime: 2_000, + idleTime: 1_000, + sampleCount: 3, + }); + }); +}); diff --git a/packages/wrangler/src/check/commands.ts b/packages/wrangler/src/check/commands.ts index 651098d371a..5e83eeab6d0 100644 --- a/packages/wrangler/src/check/commands.ts +++ b/packages/wrangler/src/check/commands.ts @@ -2,6 +2,7 @@ import { randomUUID } from "node:crypto"; import events from "node:events"; import { readFile, writeFile } from "node:fs/promises"; import path from "node:path"; +import { gzipSync } from "node:zlib"; import { log } from "@cloudflare/cli-shared-helpers"; import { spinnerWhile } from "@cloudflare/cli-shared-helpers/interactive"; import { getWranglerTmpDir, UserError } from "@cloudflare/workers-utils"; @@ -17,16 +18,27 @@ import { } from "../deployment-bundle/module-collection"; import { logger } from "../logger"; import type { Config } from "@cloudflare/workers-utils"; +import type Protocol from "devtools-protocol"; import type { ModuleDefinition } from "miniflare"; import type { FormData, FormDataEntryValue } from "undici"; const mimeTypeModuleType = flipObject(moduleTypeMimeType); +const ONE_KIB_BYTES = 1024; + +export interface StartupProfileSummary { + profileWindow: number; + sampledTime: number; + activeTime: number; + garbageCollectionTime: number; + idleTime: number; + sampleCount: number; +} export const checkNamespace = createNamespace({ metadata: { description: "☑︎ Run checks on your Worker", owner: "Workers: Authoring and Testing", - status: "alpha", + status: "stable", hidden: true, }, }); @@ -79,16 +91,28 @@ async function checkStartupHandler( }); logger.resetLoggerLevel(); } + const parsedWorkerBundle = await parseFormDataFromFile(workerBundle); + const bundleSize = await getBundleSize(parsedWorkerBundle); const cpuProfileResult = await spinnerWhile({ - promise: analyseBundle(workerBundle), + promise: analyseBundleProfile(parsedWorkerBundle), startMessage: "Analysing", endMessage: chalk.green("Startup phase analysed"), }); + const startupSummary = summarizeStartupProfile(cpuProfileResult); await writeFile(outfile, JSON.stringify(await cpuProfileResult)); log( [ + `Bundle: ${(bundleSize.size / ONE_KIB_BYTES).toFixed(2)} KiB / gzip: ${(bundleSize.gzipSize / ONE_KIB_BYTES).toFixed(2)} KiB`, + "", + "Local startup profile:", + ` Profile window: ${formatMicroseconds(startupSummary.profileWindow)}`, + ` Sampled time: ${formatMicroseconds(startupSummary.sampledTime)}`, + ` Active: ${formatMicroseconds(startupSummary.activeTime)} (including ${formatMicroseconds(startupSummary.garbageCollectionTime)} garbage collection)`, + ` Idle: ${formatMicroseconds(startupSummary.idleTime)}`, + ` Samples: ${startupSummary.sampleCount}`, + "", `CPU Profile has been written to ${outfile}. Load it into the Chrome DevTools profiler (or directly in VSCode) to view a flamegraph.`, "", "Note that the CPU Profile was measured on your Worker running locally on your machine, which has a different CPU than when your Worker runs on Cloudflare.", @@ -98,6 +122,54 @@ async function checkStartupHandler( ); } +function formatMicroseconds(microseconds: number): string { + return `${(microseconds / 1000).toFixed(1)} ms`; +} + +async function getBundleSize(workerBundle: FormData) { + const modules: Blob[] = []; + for (const entry of workerBundle.values()) { + if (entry instanceof Blob && entry.type !== "application/source-map") { + modules.push(entry); + } + } + const bundle = new Blob(modules); + return { + size: bundle.size, + gzipSize: gzipSync(await bundle.arrayBuffer()).byteLength, + }; +} + +export function summarizeStartupProfile( + profile: Protocol.Profiler.Profile +): StartupProfileSummary { + const nodes = new Map(profile.nodes.map((node) => [node.id, node])); + const samples = profile.samples ?? []; + const timeDeltas = profile.timeDeltas ?? []; + let sampledTime = 0; + let idleTime = 0; + let garbageCollectionTime = 0; + + for (const [index, timeDelta] of timeDeltas.entries()) { + sampledTime += timeDelta; + const functionName = nodes.get(samples[index] ?? 0)?.callFrame.functionName; + if (functionName === "(idle)") { + idleTime += timeDelta; + } else if (functionName === "(garbage collector)") { + garbageCollectionTime += timeDelta; + } + } + + return { + profileWindow: profile.endTime - profile.startTime, + sampledTime, + activeTime: sampledTime - idleTime, + garbageCollectionTime, + idleTime, + sampleCount: samples.length, + }; +} + export const checkStartupCommand = createCommand({ args: { outfile: { @@ -139,7 +211,7 @@ export const checkStartupCommand = createCommand({ metadata: { description: "⌛ Profile your Worker's startup performance", owner: "Workers: Authoring and Testing", - status: "alpha", + status: "stable", }, behaviour: { suggestSkillsAfterHandler: true, @@ -211,6 +283,12 @@ async function parseFormDataFromFile(file: string): Promise { export async function analyseBundle( workerBundle: string | FormData ): Promise> { + return { ...(await analyseBundleProfile(workerBundle)) }; +} + +async function analyseBundleProfile( + workerBundle: string | FormData +): Promise { if (typeof workerBundle === "string") { workerBundle = await parseFormDataFromFile(workerBundle); } @@ -256,9 +334,12 @@ export async function analyseBundle( ws.send(JSON.stringify({ id: 1, method: "Profiler.enable", params: {} })); ws.send(JSON.stringify({ id: 2, method: "Profiler.start", params: {} })); - const cpuProfileResult = new Promise>((accept) => { + const cpuProfileResult = new Promise((accept) => { ws.addEventListener("message", (e) => { - const data = JSON.parse(e.data as string); + const data = JSON.parse(e.data as string) as { + method?: string; + result: { profile: Protocol.Profiler.Profile }; + }; if (data.method === "Profiler.stop") { void mf.dispose().then(() => accept(data.result.profile)); }