Skip to content

b7ecc30f - Add continuous CPU profiling next to the OpenTelemetry SDK - #4532

Draft
TaprootFreak wants to merge 1 commit into
developfrom
feat/observability-pyroscope-profiling
Draft

b7ecc30f - Add continuous CPU profiling next to the OpenTelemetry SDK#4532
TaprootFreak wants to merge 1 commit into
developfrom
feat/observability-pyroscope-profiling

Conversation

@TaprootFreak

Copy link
Copy Markdown
Collaborator

Why

Tracing tells us how long a request waited. It cannot tell us what burned the CPU while it ran — and that was exactly the question on 2026-07-30, when the event loop sat at 84 % of a core with a p90 delay of 827 ms at 1.2 req/s. Answering it required attaching a V8 profiler to the live production process: a two-minute snapshot, bought with a production intervention, with no history and no before/after.

This adds continuous CPU profiling so the question is answerable at any time, and so a regression becomes visible before someone complains.

What this does

startProfiling() mirrors startTracing() in src/tracing.ts: it does nothing unless PYROSCOPE_SERVER_ADDRESS is set. LOC, tests and any environment without a profiling backend boot exactly as before. Wall/CPU sampling only — heap profiling is a second sampler with its own cost and stays off until allocation sites are the question.

The infrastructure side (backend, data source, transport) is a separate PR in the infrastructure repository; without it nothing receives these profiles.

Details worth a reviewer's attention

collectCpuTime is not optional. Without it the wall profiler reports elapsed time, which says very little about an event loop that spends most of it waiting. With it, the series carrying real CPU time is wall:cpu:nanoseconds:wall:nanoseconds. Note the type: the Node SDK emits wall:* types, not the process_cpu:* types Go services produce. Querying process_cpu:… for this service returns nothing, silently.

The env tag comes from ENVIRONMENT. Both environments push to one backend, the same way they already push to one trace backend, so profiles need a label to keep them apart. Reusing the variable the app already keys off avoids a second source of truth. It is checked explicitly rather than passed through, because the SDK would otherwise reject the undefined tag value with a message that says nothing about where it came from.

A profiler failure is logged loudly and swallowed. An observability extra must never be the reason the API fails to boot. console is the only channel that exists at this point — the module runs before Nest bootstraps, so DfxLogger is unavailable, and OTel's diag logger is a no-op unless a sink is registered, which would turn a failure into silence. Hence the one deliberate no-console disable, with the reasoning in place.

Sampling stays at the 100 Hz default. The obvious knob for reducing overhead does not work: measured on a CPU-saturated process, halving the rate to 50 Hz changed throughput by less than the run-to-run spread (-4.3 % vs -4.6 %). The cost is in having the sampler installed at all, not in the rate — turning it down would buy resolution loss and nothing else.

Measured overhead

Four alternating 25 s runs of a fully CPU-bound loop (event-loop utilization 1.0 — the worst case for a sampling profiler; a real request mix has idle time to absorb the sampler):

throughput CPU per unit of work RSS loop delay p99
no profiler 554.5 /s 1796 µs 49 MB 1.93 ms
profiler, 100 Hz 530.7 /s (-4.3 %) 1878 µs (+4.6 %) 75 MB (+25 MB) 2.03 ms
profiler, 50 Hz 529.0 /s (-4.6 %) 1881 µs 75 MB 2.04 ms

The workload was modelled on the profile that started this: building short-lived objects out of string fields (row parsing) plus the garbage collection that follows.

Native dependency

@datadog/pprof ships musl prebuilds for linux/arm64 at ABI 115, so the node:20-alpine image needs no toolchain and nothing is compiled at install time. Verified by running a profiling client inside that exact image and confirming the profiles arrived, rather than assuming from the package metadata.

One thing to keep an eye on: the SDK declares engines.node: ">=20.20.2" and the image currently provides exactly 20.20.2 — correct today, with no headroom. A future SDK bump to >=22 would require moving the base image first.

Verification

  • Unit tests cover all four paths: disabled without the variable, started with the expected config, idempotent, and the two failure modes (missing ENVIRONMENT, SDK throwing) each returning false while the app keeps running. Each case loads its own module copy, because importing the module starts the profiler as a side effect.
  • 18/18 tests pass, type-check, lint and prettier clean.
  • End-to-end against a real backend: the actual src/tracing.ts — not a stand-in — was run against a live instance; profiles arrived labelled service_name=dfx-api, env=prd, with the three expected wall:* types and real stack frames.

Tracing measures how long a request waited; it cannot say what burned the
CPU while it ran. Answering that on 2026-07-30 required attaching a V8
profiler to the live production process — a two-minute snapshot bought
with a production intervention.

startProfiling() mirrors startTracing(): it is inert unless
PYROSCOPE_SERVER_ADDRESS is set, so LOC, tests and any environment
without a Pyroscope instance boot unchanged. Wall/CPU sampling only —
heap profiling is a second sampler with its own cost and stays off.

Details worth knowing:

- collectCpuTime is required. Without it the wall profiler reports
  elapsed time, which says little about an event loop that is mostly
  waiting. With it, the series to chart is
  wall:cpu:nanoseconds:wall:nanoseconds — note it is a wall:* type, not
  the process_cpu:* type Go services emit.
- The env tag comes from ENVIRONMENT, the variable the app already keys
  off, so dev and prd stay apart in the shared Pyroscope without
  introducing a second source of truth.
- A profiler failure is logged loudly and swallowed: an observability
  extra must never be the reason the API fails to boot. console is the
  only channel available before Nest bootstraps.
- Sampling stays at the 100 Hz default. Measured on a CPU-saturated Node
  process, halving it to 50 Hz changed throughput by less than the
  run-to-run spread — the cost is in installing the sampler, not in the
  rate.

Measured overhead against no profiler, on a fully CPU-bound loop (worst
case; four alternating 25s runs): -4.3 % throughput, +4.6 % CPU per unit
of work, +25 MB RSS.

The native dependency ships musl prebuilds for linux/arm64 at ABI 115,
so the node:20-alpine image needs no toolchain. Note the SDK requires
Node >= 20.20.2 and the image currently provides exactly 20.20.2.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant