Skip to content

πŸ› Bug Report β€” CPU profiling reports entire execution as (program)Β #1754

@mrbbot

Description

@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...

Screenshot 2024-03-01 at 14 33 30

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)}%`);
}

Screenshot 2024-03-01 at 14 33 15

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.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type
    No fields configured for issues without a type.

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions