cloudflare / cloudflare/workerd
wrangler check startup does not consistently include entire startup time, leading to incorrect profiles and timing information
- Dominant language
- C++
- Stars
- 8.7k
- Forks
- 739
- Avg merge
- 2d 20h
- Merged PRs (30d)
- 174
Description
## Summary
When trying to profile worker startup via the inspector, the resulting `.cpuprofile` can omit a large portion of the actual startup CPU time.
This was observed from tooling that uses `workerd`'s inspector-based CPU profiler during startup, specifically:
1. `wrangler check startup`
2. CPU profiles captured during failed `wrangler versions upload`
The symptom is that the worker can fail a `1000ms` startup limit, but the captured CPU profile only contains a much smaller amount of work.
In one example profile, the profile duration was only about `95.7ms`, even though the worker was timing out at the `1000ms` startup limit and prior local startup profiles for the same worker had reportedly been around `350-450ms`.
## Observed Behavior
Concrete example from a `.cpuprofile` (DM if you need it):
- `endTime - startTime ~= 95,778us`
- `sum(timeDeltas) ~= 95,737us`
- sample count: `22`
That profile was generated for a worker that was hitting the `1000ms` startup limit.
Reported expectations from prior runs:
- same worker previously produced startup profiles around `350-450ms`
- startup failures have become more common recently
- the newer profiles appear to omit a large amount of work rather than merely reflecting machine-to-machine performance differences
## Investigation Findings
I inspected the current `workerd` startup and CPU profiling code paths and did **not** find evidence of a recent direct change to the core CPU profiler implementation itself.
### Inspector profiler commands are handled on the isolate thread
Relevant code paths:
- `src/workerd/server/server.c++`
- `src/workerd/io/worker.c++`
Important pieces:
- `startInspector()` captures the isolate thread executor
- inspector websocket messages are forwarded onto that executor
- `Worker::Isolate::attachInspector(...)` sets up the channel
- `InspectorChannelImpl::dispatchProtocolMessage(...)` handles `Profiler.start/stop`
This means `Profiler.start()` is not "active" just because the client sent it. It only becomes active once the message is actually dispatched and handled on the isolate thread.
### Startup work happens synchronously on that same isolate thread
Relevant code paths:
- `src/workerd/server/server.c++` in `Server::makeWorkerImpl()`
- `src/workerd/io/worker.c++` in `Worker::Script` construction
- `src/workerd/io/worker.c++` in `Worker::Worker` construction
The important ordering is:
1. `Server::makeWorkerImpl()` creates/registers the isolate
2. startup proceeds synchronously
3. `isolate->newScript(...)` creates `Worker::Script`
4. `Worker::Script` performs script/module compilation work
5. `Worker(...)` performs globals instantiation and top-level evaluation
Within `worker.c++`, startup work is split across at least these phases:
- script/service-worker compilation
- module compilation / module resolution
- top-level evaluation
- startup microtask flushing
- handler extraction / validation paths
### Some startup work clearly happens before a late inspector `Profiler.start()` can run
This appears to be the core issue.
If an external tool starts `workerd`, connects to the inspector, and sends `Profiler.start()`, there is still a window where:
1. the inspector port is up
2. the isolate exists or is about to exist
3. startup work is already running synchronously on the isolate thread
4. the `Profiler.start()` message has not yet executed on that thread
In that case, the profile only covers whatever happens **after** the isolate thread gets around to processing the inspector command.
That neatly matches the observed symptom:
- total startup limit hit: around `1000ms`
- visible profile duration: around `95ms`
### Existing inspector tests do not cover this startup case
Relevant test:
- `src/workerd/server/tests/inspector/driver.mjs`
That test validates request-time profiling after `Profiler.start()` and after driving a fetch request. It does **not** validate the case where startup has already completed by the time the profiler command is processed.
There is also an existing test comment noting that the inspector port can come up before the worker is actually ready, and the test waits for the HTTP port specifically to avoid connecting too early. That is another hint that inspector readiness and actual startup completion are distinct phases here.
## Likely Root Cause
The most likely root cause is **startup-vs-profiler command ordering**, not a direct regression in the low-level V8 profiler wrapper.
Put differently:
- this looks less like "Profiler.stop is truncating profiles"
- and more like "Profiler.start is landing too late to observe the full startup work"
## Important Caveat
There is one additional nuance that may matter for any eventual fix:
### Some startup work may happen before a V8 isolate exists
In `Server::makeWorkerImpl()`, if the new module registry path is enabled, `WorkerdApi::newWorkerdModuleRegistry(...)` runs before the isolate is created.
That means:
- if meaningful startup CPU time is spent there
- and that work is outside actual JS execution on a V8 isolate
then even a perfectly-timed V8 CPU profile may still not account for that part.
So there may actually be **two** separate issues to think about:
1. startup JS work is missed because `Profiler.start()` executes too late
2. some startup wall-clock work may happen outside the scope of V8 CPU profiling entirely
Contributor guide
Assessment
This issue has not been assessed yet.