Add experimental inaccurate CPU time measurement, closes #161

Author: mrbbot

packages/cli-parser/test/help.spec.ts

@@ -60,6 +60,7 @@ Core Options:
                              handlers
      --actual-time           Always return correct time from Date      [boolean]
                              methods
+     --inaccurate-cpu        Log inaccurate CPU time measurements      [boolean]
 
 Test Options:
  -b, --boolean-option        Boolean option                            [boolean]

packages/core/src/plugins/core.ts

@@ -133,6 +133,7 @@ export interface CoreOptions {
   globalTimers?: boolean;
   globalRandom?: boolean;
   actualTime?: boolean;
+  inaccurateCpu?: boolean;
 }
 
 function mapMountEntries(
@@ -400,6 +401,14 @@ export class CorePlugin extends Plugin<CoreOptions> implements CoreOptions {
   })
   actualTime?: boolean;
 
+  @Option({
+    type: OptionType.BOOLEAN,
+    description: "Log inaccurate CPU time measurements",
+    logName: "Inaccurate CPU Time Measurements",
+    fromWrangler: ({ miniflare }) => miniflare?.inaccurate_cpu,
+  })
+  inaccurateCpu?: boolean;
+
   readonly processedModuleRules: ProcessedModuleRule[] = [];
 
   readonly upstreamURL?: URL;
@@ -506,6 +515,13 @@ export class CorePlugin extends Plugin<CoreOptions> implements CoreOptions {
     const DecompressionStreamImpl =
       webStreams.DecompressionStream ?? DecompressionStream;
 
+    if (this.inaccurateCpu) {
+      ctx.log.warn(
+        "CPU time measurements are experimental, highly inaccurate and not representative of deployed worker performance.\n" +
+          "They should only be used for relative comparisons and may be removed in the future."
+      );
+    }
+
     // Build globals object
     // noinspection JSDeprecatedSymbols
     this.#globals = {

packages/core/src/standards/http.ts

@@ -21,7 +21,16 @@ import {
   waitForOpenOutputGate,
 } from "@miniflare/shared";
 import type { WebSocket } from "@miniflare/web-sockets";
-import { Colorize, blue, bold, green, grey, red, yellow } from "kleur/colors";
+import {
+  Colorize,
+  blue,
+  bold,
+  dim,
+  green,
+  grey,
+  red,
+  yellow,
+} from "kleur/colors";
 import { splitCookiesString } from "set-cookie-parser";
 import {
   Request as BaseRequest,
@@ -913,6 +922,10 @@ function millisFromHRTime([seconds, nanoseconds]: HRTime): string {
   return `${((seconds * 1e9 + nanoseconds) / 1e6).toFixed(2)}ms`;
 }
 
+function millisFromCPUTime(microseconds: number): string {
+  return `${(microseconds / 1e3).toFixed(2)}ms`;
+}
+
 function colourFromHTTPStatus(status: number): Colorize {
   if (200 <= status && status < 300) return green;
   if (400 <= status && status < 500) return yellow;
@@ -924,19 +937,27 @@ export async function logResponse(
   log: Log,
   {
     start,
+    startCpu,
     method,
     url,
     status,
     waitUntil,
   }: {
     start: HRTime;
+    startCpu?: NodeJS.CpuUsage;
     method: string;
     url: string;
     status?: number;
     waitUntil?: Promise<any[]>;
   }
 ): Promise<void> {
+  const cpuParts: string[] = [];
+
   const responseTime = millisFromHRTime(process.hrtime(start));
+  if (startCpu !== undefined) {
+    const responseTimeCpu = millisFromCPUTime(process.cpuUsage(startCpu).user);
+    cpuParts.push(dim(grey(` (CPU: ~${responseTimeCpu}`)));
+  }
 
   // Wait for all waitUntil promises to resolve
   let waitUntilResponse: any[] | undefined;
@@ -948,6 +969,15 @@ export async function logResponse(
     log.error(e);
   }
   const waitUntilTime = millisFromHRTime(process.hrtime(start));
+  if (startCpu !== undefined) {
+    if (waitUntilResponse?.length) {
+      const waitUntilTimeCpu = millisFromCPUTime(
+        process.cpuUsage(startCpu).user
+      );
+      cpuParts.push(dim(grey(`, waitUntil: ~${waitUntilTimeCpu}`)));
+    }
+    cpuParts.push(dim(grey(")")));
+  }
 
   log.log(
     [
@@ -961,6 +991,7 @@ export async function logResponse(
       // Only include waitUntilTime if there were waitUntil promises
       waitUntilResponse?.length ? grey(`, waitUntil: ${waitUntilTime}`) : "",
       grey(")"),
+      ...cpuParts,
     ].join("")
   );
 }

packages/core/test/plugins/core.spec.ts

@@ -195,6 +195,7 @@ test("CorePlugin: parses options from wrangler config", async (t) => {
         global_timers: true,
         global_random: true,
         actual_time: true,
+        inaccurate_cpu: true,
       },
     },
     configDir
@@ -256,6 +257,7 @@ test("CorePlugin: parses options from wrangler config", async (t) => {
     globalTimers: true,
     globalRandom: true,
     actualTime: true,
+    inaccurateCpu: true,
   });
   // Check build upload dir defaults to dist
   options = parsePluginWranglerConfig(
@@ -301,6 +303,7 @@ test("CorePlugin: logs options", (t) => {
     globalTimers: true,
     globalRandom: true,
     actualTime: true,
+    inaccurateCpu: true,
   });
   t.deepEqual(logs, [
     // script is OptionType.NONE so omitted
@@ -324,6 +327,7 @@ test("CorePlugin: logs options", (t) => {
     "Allow Global Timers: true",
     "Allow Global Secure Random: true",
     "Actual Time: true",
+    "Inaccurate CPU Time Measurements: true",
   ]);
   // Check logs default wrangler config/package paths
   logs = logPluginOptions(CorePlugin, {

packages/core/test/standards/http.spec.ts

@@ -1326,3 +1326,33 @@ test("logResponse: logs waitUntil error", async (t) => {
     /GET http:\/\/localhost 200 OK \(\d+.\d{2}ms, waitUntil: \d+.\d{2}ms\)/
   );
 });
+test("logResponse: logs CPU time", async (t) => {
+  const log = new TestLog();
+
+  // Check without waitUntil
+  const toLog: Parameters<typeof logResponse>[1] = {
+    start: process.hrtime(),
+    startCpu: process.cpuUsage(),
+    method: "GET",
+    url: "http://localhost",
+    status: 404,
+  };
+  await logResponse(log, toLog);
+  let [level, message] = log.logs[0];
+  t.is(level, LogLevel.NONE);
+  t.regex(
+    message,
+    /GET http:\/\/localhost 404 Not Found \(\d+.\d{2}ms\) \(CPU: ~\d+.\d{2}ms\)/
+  );
+
+  // Check with waitUntil
+  log.logs = [];
+  toLog.waitUntil = Promise.all([Promise.resolve(42)]);
+  await logResponse(log, toLog);
+  [level, message] = log.logs[0];
+  t.is(level, LogLevel.NONE);
+  t.regex(
+    message,
+    /GET http:\/\/localhost 404 Not Found \(\d+.\d{2}ms, waitUntil: \d+.\d{2}ms\) \(CPU: ~\d+.\d{2}ms, waitUntil: ~\d+.\d{2}ms\)/
+  );
+});

packages/http-server/src/index.ts

@@ -254,8 +254,9 @@ export function createRequestListener<Plugins extends HTTPPluginSignatures>(
   mf: MiniflareCore<Plugins>
 ): RequestListener {
   return async (req, res) => {
-    const { HTTPPlugin } = await mf.getPlugins();
+    const { CorePlugin, HTTPPlugin } = await mf.getPlugins();
     const start = process.hrtime();
+    const startCpu = CorePlugin.inaccurateCpu ? process.cpuUsage() : undefined;
     const { request, url } = await convertNodeRequest(
       req,
       await HTTPPlugin.getRequestMeta(req)
@@ -334,6 +335,7 @@ export function createRequestListener<Plugins extends HTTPPluginSignatures>(
     assert(req.method && req.url);
     await logResponse(mf.log, {
       start,
+      startCpu,
       method: req.method,
       url: req.url,
       status,

packages/http-server/test/index.spec.ts

@@ -669,6 +669,31 @@ test("createRequestListener: should include Content-Length header on responses",
     });
   });
 });
+test("createRequestListener: logs response", async (t) => {
+  const log = new TestLog();
+  const mf = useMiniflareWithHandler(
+    { HTTPPlugin },
+    {},
+    (globals) => new globals.Response("body"),
+    log
+  );
+  const port = await listen(t, http.createServer(createRequestListener(mf)));
+
+  let [body] = await request(port);
+  t.is(body, "body");
+  let logs = log.logsAtLevel(LogLevel.NONE);
+  t.is(logs.length, 1);
+  t.regex(logs[0], /^GET \/ 200 OK \(\d+\.\d+ms\)$/);
+
+  // Check includes inaccurate CPU time if enabled
+  await mf.setOptions({ inaccurateCpu: true });
+  log.logs = [];
+  [body] = await request(port);
+  t.is(body, "body");
+  logs = log.logsAtLevel(LogLevel.NONE);
+  t.is(logs.length, 1);
+  t.regex(logs[0], /^GET \/ 200 OK \(\d+\.\d+ms\) \(CPU: ~\d+\.\d+ms\)$/);
+});
 
 test("createServer: handles regular requests", async (t) => {
   const mf = useMiniflareWithHandler({ HTTPPlugin }, {}, (globals, req) => {

packages/scheduler/src/index.ts

@@ -24,6 +24,7 @@ export class CronScheduler<Plugins extends SchedulerPluginSignatures> {
   // noinspection JSMismatchedCollectionQueryUpdate
   private previousValidatedCrons?: Cron[];
   private scheduledHandles?: ITimerHandle[];
+  private inaccurateCpu?: boolean;
 
   constructor(
     private readonly mf: MiniflareCore<Plugins>,
@@ -36,6 +37,7 @@ export class CronScheduler<Plugins extends SchedulerPluginSignatures> {
 
   [kReload] = async (event: ReloadEvent<Plugins>): Promise<void> => {
     const validatedCrons = event.plugins.SchedulerPlugin.validatedCrons;
+    this.inaccurateCpu = event.plugins.CorePlugin.inaccurateCpu;
     // Checking references here, if different, SchedulerPlugin setup must've
     // been called meaning crons changed so reload scheduled tasks
     if (this.previousValidatedCrons === validatedCrons) return;
@@ -53,10 +55,12 @@ export class CronScheduler<Plugins extends SchedulerPluginSignatures> {
       const spec = cron.toString();
       return cronScheduler.setInterval(cron, async () => {
         const start = process.hrtime();
+        const startCpu = this.inaccurateCpu ? process.cpuUsage() : undefined;
         // scheduledTime will default to Date.now()
         const waitUntil = this.mf.dispatchScheduled(undefined, spec);
         await logResponse(this.mf.log, {
           start,
+          startCpu,
           method: "SCHD",
           url: spec,
           waitUntil,

packages/scheduler/test/index.spec.ts

@@ -72,6 +72,15 @@ test("CronScheduler: schedules tasks for validated CRONs on reload", async (t) =
   t.is(events.length, 1);
   t.is(events[0].cron, "30 * * * *");
   t.regex(log.logs[0][1], /^SCHD 30 \* \* \* \* \(\d+\.\d+ms\)$/);
+
+  // Check includes inaccurate CPU time if enabled
+  await mf.setOptions({ inaccurateCpu: true });
+  log.logs = [];
+  await dispatch("30 * * * *");
+  t.regex(
+    log.logs[0][1],
+    /^SCHD 30 \* \* \* \* \(\d+\.\d+ms\) \(CPU: ~\d+\.\d+ms\)$/
+  );
 });
 test("CronScheduler: destroys tasks when CRONs change", async (t) => {
   const events: ScheduledEvent[] = [];

packages/shared/src/wrangler.ts

@@ -94,6 +94,7 @@ export interface WranglerEnvironmentConfig {
     global_timers?: boolean;
     global_random?: boolean;
     actual_time?: boolean;
+    inaccurate_cpu?: boolean;
   }; // inherited
 }