Repository navigation
perf(telemetry): drop instrumentation that exports nothing - #4481
Conversation
|
Auto-sync is disabled for draft pull requests in this repository. Workflows must be run manually. Contributors can view more details about this message here. |
1b850a5 to
f65553d
Compare
b77a980 to
9620537
Compare
iguehring-nvidia
left a comment
There was a problem hiding this comment.
The issue (#4478) proposed a small ASGI middleware that keeps a per-request duration histogram when traces are off. This PR doesn't implement it, and a metrics-only run now loses all http.server.* metrics. Is that deliberate?
|
🌿 Preview your docs: https://nvidia-preview-pr-4481-cd41640b8372.docs.buildwithfern.com/nemo/gym |
9620537 to
29b45b9
Compare
|
@iguehring-nvidia Yes, deliberate. The Merge order, telemetry first:
What a metrics-only run has after all three:
If metrics-only per-route latency turns out to be needed, it can be its own PR with its own overhead measurement. |
9564fec to
252b69e
Compare
d2c6da7 to
c8d6a0e
Compare
The base branch was changed.
With traces disabled, nemo-lens still enables the configured span groups, so every request paid for instrumentation whose only output is spans. The FastAPI instrumentor costs about 60 µs per inbound request even when no span is exported, and each outbound call through `server_utils.request` opened a no-op client span and injected a `traceparent` nobody would read. `init_telemetry` now records whether this process exports traces, and both sites check it. A metrics-only run therefore no longer reports the instrumentor's `http.server.*` metrics; the docs say so and now name the metrics the pinned instrumentation actually exports, such as `http.server.duration`. Closes #4478. Signed-off-by: Ananth Subramaniam <ansubramania@nvidia.com>
TelemetryConfig.instrument_aiohttp and its NEMO_GYM_OTEL_INSTRUMENT_AIOHTTP env mapping changed nothing: neither Gym nor nemo-lens calls instrument_aiohttp_client or reads the variable. Gym's outbound CLIENT span and traceparent injection come from server_utils.request, gated on the http_client span group, so the docstring's claim was wrong too. Configs that still set the key keep loading because TelemetryConfig allows extra keys, matching the earlier export_strategy/export_rank removal. Signed-off-by: Ananth Subramaniam <ansubramania@nvidia.com>
opentelemetry-instrumentation-aiohttp-client only backs nemo-lens's instrument_aiohttp_client, which nothing calls. Remove it from the telemetry extra and from the packages installed into server venvs. server_utils.request already makes the outbound CLIENT span and injects traceparent without it. Signed-off-by: Ananth Subramaniam <ansubramania@nvidia.com>
c8d6a0e to
cd41640
Compare
…ources-operation metrics (NVIDIA-NeMo#4474) > **Stack:** telemetry lands before the optimizations, so the optimizations can be measured with it. > 1. NVIDIA-NeMo#4474: event-loop, process, request, driver, and resources-operation metrics (base `main`) > 2. NVIDIA-NeMo#4481: drop instrumentation that exports nothing (base NVIDIA-NeMo#4474) > 3. NVIDIA-NeMo#2890: replace the HTTP middleware wrappers with ASGI (base NVIDIA-NeMo#4481) ## What changed A Gym server answers every request on one asyncio event loop. When synchronous work holds that loop, every other request waits, even though no single request looks slow, and nothing Gym exported showed it. This PR adds the event-loop, process, request, HTTP client, rollout-driver, rollout-shape, and resources-operation metrics from NVIDIA-NeMo#3155. They run whenever telemetry exports metrics, except the event-loop task count, which is opt-in. - Event loop and process, from every server process, the head server, and the rollout driver: `gym.event_loop.lag_ms`, `gym.event_loop.tasks`, `gym.gc.pause_duration_ms`, `gym.gc.collections_total`, `gym.gc.collected_total`, `gym.gc.uncollectable_total`, `gym.gc.count`, `process.cpu.time`, `process.memory.usage`, `process.thread.count`, and `process.open_file_descriptor.count`. Each process also reports `process.pid`, so the Uvicorn workers of one server stay distinguishable. - Server requests, counted by the outermost middleware: `gym.server.requests.in_flight`, `gym.server.requests.cancelled_total`, `gym.server.requests.unhandled_exceptions_total`, and `gym.server.responses_total` by `http.response.status_code`, which counts handled errors such as an `HTTPException` as their 4xx or 5xx. - HTTP client: `gym.http.client.requests.in_flight` for outbound calls still waiting for their response, and `gym.http.connection_pool.connect_duration_ms` for each new pooled connection, next to the existing queue-wait metric. - Rollout driver: `gym.driver.rollouts.offered_total`, `gym.driver.rollouts.resident`, and `gym.driver.rollouts.active`, plus `gym.driver.admission_duration_ms`, `gym.driver.output_write_duration_ms`, `gym.driver.output_write_bytes`, and `gym.driver.materialize_duration_ms`. A standalone `gym eval run --no-serve` driver now sets up its own telemetry, which also lets it export the existing `gym.job` span. - Rollout shape, once per completed rollout: `gym.driver.rollout.input_items`, `gym.driver.rollout.output_items`, `gym.driver.rollout.turns`, and `gym.driver.rollout.tool_calls`. Turns and tool calls come from `ng_perf` when rollout observability produced it. - A shared resources-operation contract, `nemo_gym.telemetry.resources_operations.resources_operation`, which reports how long limited work queued (`gym.resources.operation.queue_duration_ms`), how long it ran (`gym.resources.operation.duration_ms`), and how it ended (`nemo.gym.resources.operation.outcome`). `math_with_judge` uses it for its SymPy verifier subprocesses and marks timeouts and crashes. - Naming follows the conventions of Gym's existing metrics: durations in milliseconds ending in `_ms`, counters ending in `_total`, and Gym attributes under `nemo.gym.`. The `process.*` metrics keep their OpenTelemetry semantic-convention names, seconds, and `cpu.mode`, so standard dashboards recognize them. The design keeps the work off the request path, which is why the metrics need no switch of their own. The event loop runs one sampling coroutine per interval. Per-request and per-rollout counts are plain integer updates that the exporter thread reads through observable instruments, so a request makes no OpenTelemetry call. The GC callback only buffers timestamps and totals, because it runs inside a collection. Instruments are registered once per meter, the GC callback is removed with the last observer, and the last observer to stop exports the final totals, so a short-lived driver still reports its counts. ```mermaid flowchart TB subgraph onloop["On the event loop"] requests["Each request: outermost middleware and server_utils.request"] rollouts["Each rollout: driver dispatch and output write"] sampler["Once per interval: sampler coroutine"] end totals["Plain integer totals"] pauses["Bounded GC pause buffer"] hist["Histograms"] subgraph offloop["Off the event loop"] gc["gc.callbacks hook"] exporter["Exporter thread, at each export"] end requests -->|"integer updates"| totals rollouts -->|"integer updates"| totals rollouts -->|"one record per rollout"| hist sampler -->|"lag, task count, and drained GC pauses"| hist gc -->|"pause timestamps"| pauses gc -->|"collection totals"| totals pauses -->|"drained once per interval"| sampler exporter -->|"reads totals and psutil process stats"| totals exporter -->|"exports"| hist classDef hot fill:#e3f4e1,stroke:#2e7d32 class requests,rollouts hot ``` The green steps run once per request or once per rollout, and only update integers or record one histogram point per rollout. Measured costs decided what runs by default: | Measurement | Cost | Where it runs | Default | | --- | ---: | --- | --- | | Request and driver counts | 0.06 µs per update | On the event loop, per request or rollout | On | | One histogram record | 1.7 µs | On the event loop, per rollout or sample | On | | GC callback | 0.5 µs per collection | Inside each collection | On | | Event-loop lag | One sleep per interval | On the event loop, once per second | On | | `psutil` process reads | 4 to 10 µs | On the exporter thread, per export | On | | `asyncio.all_tasks` for the task count | 0.2 ms at 2,000 tasks, 1.7 ms at 16,000, 6.9 ms at 64,000 | On the event loop, once per second | Off, `telemetry.event_loop_task_count` | The task count walks every task on the loop while holding it, and grows with concurrency, so it is the only opt-in measurement. The sampling interval is `telemetry.event_loop_sample_interval_seconds`. ## Why A capacity investigation found that a model server under bursty rollouts spent about 10 ms per call waiting on its own event loop, behind the synchronous work of other requests, with no metric showing it. These metrics make that kind of slowdown visible in any run, and the driver and resources-operation metrics show where work waits outside the servers. ## Issue Part of NVIDIA-NeMo#3155. Per-request request and response byte histograms are not included, so that the request path makes no per-request OpenTelemetry call; output row sizes are reported by `gym.driver.output_write_bytes`. ## Compatibility - With telemetry or metrics off, nothing starts, and the only additions to the request path are one global read in the outermost middleware and one in `server_utils.request`. - With metrics on, the new metrics are exported without further configuration. The task count needs `telemetry.event_loop_task_count: true` or `NEMO_GYM_OTEL_EVENT_LOOP_TASK_COUNT=1`. - Resource attributes gain `process.pid` in every process. - A standalone `gym eval run --no-serve` driver now initializes telemetry from the `telemetry:` block, under the service name suffix `driver`. - `math_with_judge`'s `_wait_for_library_verifier_process` gains an optional keyword-only `operation` argument. ## Validation - `pytest tests/unit_tests/telemetry tests/unit_tests/test_rollout_collection.py tests/unit_tests/test_server_utils.py tests/unit_tests/test_cli_eval.py tests/unit_tests/test_cli.py -n 12` with the `telemetry` extra installed. - `tests/unit_tests/telemetry/test_observer.py` covers GC callback pairing, bounded buffering, and removal; lag from a deliberately blocked event loop; nested observers sharing one process state; no work while metrics are off; the opt-in task count; driver totals exported only by a process that offered rollouts; event-loop settings handed from the supervisor to every server; a failed start that does not stop the server; lifespan composition; request, cancellation, and failure counts; outbound in-flight counts; driver admission, residency, write, and rollout-shape metrics; and the final export of totals when the last observer stops. `test_resources_operations.py` covers queue wait, execution, outcomes, bounded labels, and the disabled path. `test_connection_pool.py` covers new-connection timing, reused connections, refused connections, and the aiohttp override signature. - `gym env test +entrypoint=resources_servers/math_with_judge +should_validate_data=true`. - An end-to-end run through the CPU capacity simulator from NVIDIA-NeMo#3156, with the console exporter, the single-agent-turn Environment Server, and 256 rollouts per run. Every expected instrument was exported by the processes that should export it. The values matched the run: offered rollouts equalled rollouts collected, resident and active returned to zero, input items equalled tasks times six messages, and resources-operation samples equalled two tool calls per rollout, including warm-up. The same check found two defects that this PR fixes: the driver's final totals were never exported, and every server exported the driver's rollout counts as constant zeros. The task gauge was exported only when `NEMO_GYM_OTEL_EVENT_LOOP_TASK_COUNT=1` was set. - An interleaved overhead comparison through the same simulator, with near-instant inference so that Gym's own cost dominates, 2,048 rollouts per run and three runs per setting, with the engine, servers, and driver pinned to separate cores. Traces were off throughout. CPU per rollout, median with range: | Setting | Server CPU per rollout | Driver CPU per rollout | | --- | ---: | ---: | | Base commit, telemetry off | 22.2 ms (22.0–23.3) | 2.77 ms (2.76–2.82) | | Base commit, metrics on | 22.7 ms (22.6–22.8) | 2.78 ms (2.76–2.80) | | This PR, telemetry off | 22.2 ms (22.2–22.5) | 2.81 ms (2.81–2.81) | | This PR, metrics on | 22.8 ms (22.7–23.9) | 2.88 ms (2.87–2.89) | | This PR, metrics and task count on | 22.8 ms (22.8–23.1) | 2.89 ms (2.88–2.95) | With telemetry off, this PR matches the base commit. With metrics on, the new server metrics add nothing measurable on top of Gym's existing metrics. The driver spends about 0.1 ms more per rollout, from its per-rollout histograms. The existing metrics pipeline costs about 2 percent of server CPU in this run, mostly from the FastAPI and aiohttp instrumentors; NVIDIA-NeMo#4478 tracks installing them only when traces are exported. ## Rollout evidence N/A for model rollouts. The change adds observability and does not change agent, model, or verifier decisions. The capacity-simulator runs above exercise real rollouts through the driver, agent, model server, Environment Server, and resources server with a mock inference engine. --------- Signed-off-by: Ananth Subramaniam <ansubramania@nvidia.com>
What changed
With
traces_enabled: false, nemo-lens still enables the configured span groups, so instrumentation whose only output is spans kept running on every request against a tracer that records nothing.This PR skips that work while traces are off:
init_telemetryrecords whether the process exports traces, andnemo_gym.telemetry.setup.is_trace_exporter_active()reports it. When Gym reuses providers another library set up, it checks for a real SDK tracer provider, as it already does for metrics.SimpleServer.instrument_app_for_telemetryinstalls the FastAPI instrumentor only while traces export.server_utils.requestopens the outbound CLIENT span and injectstraceparentonly while traces export.telemetry.instrument_aiohttpsetting and itsNEMO_GYM_OTEL_INSTRUMENT_AIOHTTPvariable are removed. Nothing in Gym or nemo-lens callsnemo.lens.contrib.aiohttp.instrument_aiohttp_client, so the setting never did anything; its docstring described a CLIENT span that Gym in fact creates itself inserver_utils.request.opentelemetry-instrumentation-aiohttp-client, which only backs that unused helper, is dropped from thetelemetryextra and from the packages installed into each server venv.Span groups that also drive metrics, such as
verify,rollout, andsandbox, are unchanged, sogym.verify.*,gym.rollout.*, and the sandbox metrics still report in a metrics-only run.The FastAPI instrumentor is also the source of the
http.server.*metrics.A metrics-only run no longer reports them, and the docs now say so.
The docs also named metrics the pinned instrumentation does not export: a run exports
http.server.duration(ms),http.server.request.size,http.server.response.size, andhttp.server.active_requests, keyed byhttp.target,http.method, andhttp.status_code, whilemetrics.mdx,extending.mdx, and the telemetry README listedhttp.server.request.duration.Why
Measured on one workstation with tracing off, the FastAPI instrumentor adds about 63 µs to each inbound request (15 µs bare, 78 µs instrumented).
The outbound path adds a no-op span and a header injection to every call between servers.
Neither produces anything a metrics-only run can use.
Issue
Closes #4478.
The issue also listed aiohttp client instrumentation at about 58 µs per outbound request.
Nothing in Gym or nemo-lens installs that instrumentor; the outbound cost Gym pays comes from its own client span, which this PR gates, and the setting that appeared to control the instrumentor is removed.
This PR absorbs #4485.
Compatibility
traces_enabled: falseand metrics on lose thehttp.server.*metrics. Turn traces on to keep them.instrument_aiohttpkeep loading, becauseTelemetryConfigallows extra keys; the key has no effect, as before. The setting is removed rather than deprecated, asexport_strategyandexport_rankwere in fix(telemetry): adopt nemo-lens SpanRegistry and reuse an existing Lens setup #3890.telemetryextra no longer installsopentelemetry-instrumentation-aiohttp-client.daytonastill depends on it, so it stays inuv.lockfor thesandboxextra. Code that callsinstrument_aiohttp_clientitself can installnemo-lens[aiohttp].server_utils.request, the trace gate chooses between the traced and untraced send, and feat(telemetry): report event-loop, process, request, driver, and resources-operation metrics #4474's outbound in-flight count wraps either one.Validation
pytest tests/unit_tests/telemetry tests/unit_tests/test_server_utils.py tests/unit_tests/test_cli.py -n 12with thetelemetryextra installed.pytest tests/unit_tests -n 16: the only failures are the same environment-dependent ones as on the base commit (test_opensandbox_compose.py,test_reward_profile.py,test_dataset_orchestrator.py,test_sandbox_stop_retry.py), andtest_exporters.pyneedsmlflow.test_setup.pycovers the trace flag followingtraces_enabled, the flag for reused providers with and without an SDK tracer provider, and the FastAPI instrumentor installed only while traces export.test_config.pychecks that a config settinginstrument_aiohttpstill loads and thatconfigure_telemetry_envno longer exports the variable; it fails on the base commit.In a venv synced from this branch with the
telemetryextra,opentelemetry.instrumentation.aiohttp_clientis not importable, and the full unit suite runs with the same environment-dependent failures as the base commit, including passing propagation tests that checktraceparenton outbound requests.uv lock --checkpasses.test_propagation.pyserves two real FastAPI apps and checks that, with traces off, no CLIENT span is produced and notraceparentreaches the downstream server.Removing either gate makes its test fail.
pre-commit runon the changed files.An interleaved comparison through the CPU capacity simulator from Add a high-concurrency Gym dispatch and resources capacity simulator #3156 (
fast_inference_burst, near-instant inference so that Gym's own cost dominates, 2,048 rollouts per run, three runs per setting, engine, servers, and driver pinned to separate cores, traces off). Server CPU per rollout, median with range:The cost of turning metrics on drops from about 2.9 ms to 1.3 ms per rollout.
Both metrics-on runs exported the same
gym.*metrics, includinggym.rollout.duration_msand the connection-pool metrics; only thehttp.server.*metrics are gone. No run had a failed rollout.Rollout evidence
example_single_tool_callwith the simple agent andgpt-oss-20b(3 tasks) ran from the dependency-removal commits and from the base commit75bb53e6d, both withspan_groups=all, traces on, and console export, throughgym env startand thengym eval run --no-serve. On the base commit every server venv hadopentelemetry-instrumentation-aiohttp-client; with the change, none did, and each still hadopentelemetry-instrumentation-fastapi.HTTP POSTclient spanstraceparentstill joins each outbound request to the server span that handles it. Sandbox spans are not covered, because this environment has no sandbox.The trace gate does not change agent, model, or verifier decisions; the capacity-simulator runs above exercise it through real rollouts with a mock inference engine.