Skip to content

Add per-stage load telemetry to the model server (RUN-544) - #2545

Open
kamh04 wants to merge 6 commits into
mainfrom
kamalhaddad/run-544-load-telemetry
Open

Add per-stage load telemetry to the model server (RUN-544)#2545
kamh04 wants to merge 6 commits into
mainfrom
kamalhaddad/run-544-load-telemetry

Conversation

@kamh04

@kamh04 kamh04 commented Jul 13, 2026

Copy link
Copy Markdown

🚀 What

Breaks the opaque model.load() time into named, machine-readable stages, emitted once per model load as a structured log line (model load telemetry: {...}) and per-stage OTel spans — with zero customer code changes:

  • server_boot_ms — process start → load start (interpreter + server imports), recovered from /proc/self/stat
  • Stage timings: setup, extensions_load (incl. TRT-LLM), import_model_module (customer imports — where import torch lands), model_init, setup_environment, model_load
  • torch compile attribution: torch_compile_ms (Dynamo ledger diffed around load()), torch_compile_phases_ms (top-5 phases), torch_unique_graphs, torch_graph_breaks, torch_fx_cache_hits/_misses (is persistent compile caching actually working?)
  • gpu_mem_allocated_gb / gpu_mem_delta_gb — weights→GPU footprint
  • unattributed_ms — total minus the sum of stages, the honesty bucket

Context: reconstruction of the fleet's worst container_ready cold starts (Linear: RUN-544, "Profile container_ready portion of GPU Cold Start") showed 62–91% of the worst cases is deterministic recompute (compile/warmup) — visible today only via fragile per-framework log mining. This gives every truss model a first-party breakdown.

💻 How

A LoadTelemetry context manager (load_telemetry.py) wraps the stages of ModelWrapper._load_impl and snapshots torch state before/after the customer's load(). Design invariants, each pinned by a test:

  • Telemetry is write-only: internal failures degrade to missing fields + a warning, never a failed or slower load.
  • torch is never imported by the server: it is read from sys.modules, so it is only observed when the customer's code already imported it. Non-torch models pay nothing.
  • torch.compile() is lazy (compilation happens at first forward), so compile time is read from Dynamo's compilation_time_metrics ledger, snapshotted before load() and diffed after — feature-detected because the API is semi-private and has moved across torch versions.
  • GPU memory is only read when CUDA is already initialized, because memory_allocated() would otherwise trigger CUDA init.

Cost: microseconds of clock reads + one <1 KB log line per cold start; predict path untouched; spans go through the existing (default no-op) tracer.

🔬 Testing

  • 12 unit tests (test_load_telemetry.py): stage/unattributed arithmetic, compile-delta attribution incl. the pre-seeded-exclusion boundary, version-fallback key ladder, phase-list bounding, counter deltas, CUDA-init guard, /proc parsing (incl. parens-in-comm), finalize-never-raises.
  • Server-level integration test (test_truss_server.py::test_load_emits_load_telemetry_line): real ModelWrapper.load() against the fixture truss → exactly one parseable line, real stage timings, torch fields via sys.modules without torch installed, GPU fields absent (not fabricated) without CUDA.
  • Real-torch end-to-end: built the serving image locally from this branch (TrussHandle.build_serving_docker_image) with a probe model whose load() runs torch.compile over 3 input shapes. Observed line matched all predictions: torch_unique_graphs: 3, torch_fx_cache_misses: 3, torch_compile_ms: 3839.6 with real Dynamo phase keys, load_total_ms exactly equal to the legacy "Completed model.load() in N ms" value, unattributed_ms: 0.0.
  • Full truss/tests/templates/server suite green (49 tests); ruff clean.

Notes for review

  • The telemetry line is on the customer-visible log stream (deliberate — customers see their own load breakdown), landing right after "Completed model.load() execution in N ms".
  • Open question: the telemetry JSON is nested inside the log record's message, so Loki-side extraction needs regexp rather than | json. Happy to flatten fields to the top level of the record in this PR if preferred.
  • Deployed-image verification note: truss push builds with the released context builder, so this change reaches deployments only via a release — verified via the local image build instead; a staged probe model exists for post-release rollout verification.

🤖 Generated with Claude Code

kamh04 and others added 4 commits July 13, 2026 10:14
Breaks the opaque model.load() time into named stages — setup,
extensions_load, import_model_module (customer imports), model_init,
setup_environment, model_load — plus torch.compile wall time and GPU
memory attribution, emitted as one structured log line
("model load telemetry: {...}") and per-stage OTel spans via the
server's existing tracer.

Design invariants:
- Telemetry is write-only: internal failures degrade to missing fields
  and a warning, never a failed or slower load.
- torch is never imported by the server: it is read from sys.modules,
  so it is only observed when the customer's code already imported it.
  Non-torch models pay nothing.
- torch.compile() is lazy (compilation happens at first forward, not at
  the call site), so compile time is read from Dynamo's
  compilation_time_metrics ledger, snapshotted before model.load() and
  diffed after — feature-detected because the API is semi-private and
  has moved across torch versions.
- GPU memory is only read when CUDA is already initialized, because
  memory_allocated() would otherwise trigger CUDA init.

unattributed_ms (total minus the sum of stages) keeps the breakdown
honest: it is the "we don't know yet" bucket.

Context: reconstruction of the fleet's worst container_ready cold
starts showed 62-91% is deterministic recompute (compile/warmup),
visible today only via fragile per-framework log mining. This gives
every truss model a first-party breakdown with zero customer changes.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Long compiles need the why, not just the wall time. Alongside
torch_compile_ms, emit (all as deltas attributed to model.load(),
feature-detected like the rest):

- torch_compile_phases_ms: top-5 phases by duration from dynamo's
  compilation_time_metrics ledger — splits dynamo tracing vs inductor
  codegen vs autotuning, bounded so the log line stays small
- torch_unique_graphs: distinct graphs compiled during load
- torch_graph_breaks: each break splits the graph and forces another
  compile — a direct lead when compile time is unexpectedly high
- torch_fx_cache_hits / torch_fx_cache_misses: whether the inductor
  FX-graph cache served the compile — misses mean the work was
  recomputed from scratch, i.e. persistent compile caching is not
  effective for this model (the b10-transfer question, answerable
  fleet-wide once this ships)

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Boots the real ModelWrapper.load() path against the fixture truss and
asserts the telemetry line end to end: real per-stage timings, stage
sum bounded by the total, torch fields read via sys.modules with a
pre-seeded fake dynamo (zero load-attributed delta, and no torch import
required), and GPU fields absent rather than fabricated when CUDA does
not exist.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
The load stages cover everything inside model.load(), but the server's
own boot (interpreter start + server imports + startup code before
load) was invisible. Recover process start time from /proc/self/stat
(starttime ticks since boot + /proc/uptime) and emit
server_boot_ms = process start -> LoadTelemetry construction.

For standard truss images the server process is the container
entrypoint, so this approximates container start -> load start, making
the telemetry line's coverage of container_ready near complete:
container_ready ~= server_boot_ms + load_total_ms + readiness-probe
detection tail.

Linux-only by nature; feature-detected like everything else (absent on
other platforms, never an error).

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
@linear

linear Bot commented Jul 13, 2026

Copy link
Copy Markdown

RUN-544

@CLAassistant

CLAassistant commented Jul 13, 2026

Copy link
Copy Markdown

CLA assistant check
All committers have signed the CLA.

kamh04 and others added 2 commits July 13, 2026 18:12
…rom control dictConfig)

The full-suite CI run applies the server dictConfig (via the control app
tests), which sets the uvicorn logger to propagate=False. caplog captures
at the root logger, so the telemetry line was emitted but never captured.
Restore propagation for the test's duration via monkeypatch.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
…ows)

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
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.

2 participants