🐛 Bug Report — CPU profiling reports entire execution as (program)

[mrbbot]

Hey! 👋 When investigating cloudflare/workers-sdk#4409, I observed that CPU profiles from workerd contain a single (program) entry for the entire duration of the profile. To reproduce this...

# config.capnp
using Workerd = import "/workerd/workerd.capnp";

const config :Workerd.Config = (
  services = [
    ( name = "main", worker = .worker ),
  ],
  sockets = [
    ( name = "http", address = "*:8080", http = (), service = "main" ),
  ]
);

const worker :Workerd.Worker = (
  modules = [
    ( name = "./index.mjs", esModule = embed "index.mjs" )
  ],
  compatibilityDate = "2024-01-01",
  compatibilityFlags = ["nodejs_compat"],
);

// index.mjs
import { Buffer } from "node:buffer";

const encoder = new TextEncoder();

async function pbkdf2Derive(password) {
  const passwordArray = encoder.encode(password);
  const passwordKey = await crypto.subtle.importKey(
    "raw", passwordArray, "PBKDF2", false, ["deriveBits"]
  );
  const saltArray = crypto.getRandomValues(new Uint8Array(16));
  const keyBuffer = await crypto.subtle.deriveBits(
    { name: "PBKDF2", hash: "SHA-256", salt: saltArray, iterations: 1_000_000 },
    passwordKey, 256
  );
  return Buffer.from(keyBuffer).toString("base64");
}

export default {
  async fetch(request, env, ctx) {
    return new Response(await pbkdf2Derive("hello!"));
  }
}

// stress.mjs
const total = 1_000;
for (let i = 0; i < total; i++) {
  const response = await fetch("http://127.0.0.1:8080");
  await response.arrayBuffer();
  if (i % 10 === 0) console.log(`${(i * 100 / total).toFixed(0)}%`);
}

...then run...

$ npx workerd serve config.capnp --verbose --control-fd=1 --watch --inspector-addr=127.0.0.1:9229 &
$ node stress.mjs

...then visit chrome://inspect to open DevTools and start a CPU profile for a few seconds. For me, the result looks something like...

If I run the following similar code in Node directly with node --inspect-brk index-node.mjs, visit chrome://inspect and start a CPU profile I see something like...

// index-node.mjs
import { Buffer } from "node:buffer";
import { webcrypto as crypto } from "node:crypto";

const encoder = new TextEncoder();

async function pbkdf2Derive(password) {
  const passwordArray = encoder.encode(password);
  const passwordKey = await crypto.subtle.importKey(
    "raw", passwordArray, "PBKDF2", false, ["deriveBits"]
  );
  const saltArray = crypto.getRandomValues(new Uint8Array(16));
  const keyBuffer = await crypto.subtle.deriveBits(
    { name: "PBKDF2", hash: "SHA-256", salt: saltArray, iterations: 1_000_000 },
    passwordKey, 256
  );
  return Buffer.from(keyBuffer).toString("base64");
}

const total = 1_000;
for (let i = 0; i < total; i++) {
  console.log(await pbkdf2Derive("hello!"));
  if (i % 10 === 0) console.log(`${(i * 100 / total).toFixed(0)}%`);
}

I get that Node probably implements more of these APIs in JavaScript, hence the deeper flame graphs, but I'd still expect to see pbkdf2Dervie() in the workerd profile's flame graph.