Skip to content

Consume centralized DPC "HTTP call done" log line; align actuation baseline - #1583

Merged
maugustosilva merged 6 commits into
llm-d:mainfrom
rubambiza:feat/dpc-parser-centralized-http-line
Jul 6, 2026
Merged

Consume centralized DPC "HTTP call done" log line; align actuation baseline#1583
maugustosilva merged 6 commits into
llm-d:mainfrom
rubambiza:feat/dpc-parser-centralized-http-line

Conversation

@rubambiza

Copy link
Copy Markdown
Collaborator

Summary

Updates the FMA DPC-log timing pipeline for two coordinated upstream changes in llm-d-fast-model-actuation (both present in its v0.6.0 release):

  1. Consume the centralized "HTTP call done" log line. The dual-pods controller replaced its three per-message HTTP-timing log lines with one centralized line discriminated by a purpose field. The parser now keys on purpose tokens: wake → hot-start anchor, create_instance → warm-start anchor, relay_ready → shared readiness end (relay_unready ignored). Cold-launcher timing is unchanged (it comes from a Kubernetes API call, not an HTTP call). Without this, once the upstream change is picked up the parser silently falls back to coarse Kubernetes-timestamp upper bounds and the sub-second wake fidelity goes blank.

  2. Align the actuation baseline to container start. The controller's actuation metric now measures from the requester inference-server container's state.running.startedAt rather than the requester pod's creationTimestamp. The harness's Kube-timestamp fallback is realigned to the same baseline so it agrees with the controller.

Closes #1547.

Key change: explicit, non-silent timing source

The single dpc_timing_available boolean is replaced with a per-iteration timing_source. The three values measure three different intervals (not one interval at three fidelities) — each ends at requester readiness but subtracts from a different start point:

  • dpc — measured inside the DPC log as relay_readiness − httpCallStartTime of the wake/create call. Baseline is the HTTP call start (after the container is up), so it is the tightest interval. Highest fidelity.
  • kube_container_start — Kube fallback: requester ready − container state.running.startedAt. Matches the controller's own actuation-metric baseline; a coarser upper bound than dpc (starts earlier).
  • kube_pod_create — Kube fallback reverted to requester ready − pod creationTimestamp because container-start was unavailable. Earliest baseline, coarsest, degraded.

A kube_pod_create reversion emits a logger.warning naming the requester (fired only for the final source, after DPC refinement, so a DPC-timed iteration never emits a spurious warning). Because the sources measure different intervals, per-iteration timing_source exists so consumers don't mix them blindly. It propagates through native_to_br0_1.py and renders as a three-way Source column in the analysis output; dpc_timing_available is retained as a derived property for backward-compatible readers.

Testing

  • Unit: tests/test_dpc_log_parser.py (15) + tests/test_fma_functions.py (18); full suite 562 passed, 31 skipped.
  • Preserves the large-file streaming and partial-log regressions from feat: Tighter FMA timing via DPC log parsing #1504 (adapted to the new format; the streaming regression uses a non-indicator filler so the first indicator genuinely lands past 256KB).
  • Smoke test against a real controller log (1.12 MB, from a Qwen3-8B run): the updated parser extracts 11 records with sub-second hot-start t_hot (0.536 / 0.537 / 0.542 / 0.591 s, median 0.539s) — the same log yielded zero records under the old parser. Corroborates the ~0.51s vLLM-log weight-reload figure.

Draft status

Marked draft pending cluster end-to-end validation: confirm the emitted result.yaml shows timing_source: dpc with sub-second t_wake, and that any fallback iteration reports the correct source. The smoke test above exercised the DPC-log path against real data; the container-start fallback path is unit-tested only, and is what the cluster run will exercise. Will flip to ready for review once that passes.

rubambiza added 6 commits July 1, 2026 16:14
Replace message-string dispatch with purpose-based dispatch on the new
centralized "HTTP call done" klog line. The DPC now emits one HTTP-call
line per request with purpose field identifying the call type (wake,
create_instance, relay_ready). Ignores relay_unready and other purposes.
Cold-launcher path unchanged (k8sCallStartTime).

- Convert all test log lines to new centralized format
- Implement purpose-based dispatch in parse_dpc_log
- Update _DPC_INDICATOR_MSGS and module docstring
- All 15 tests pass (hot/warm/cold paths + edge cases)

Assisted-By: Claude Code (Anthropic AI) <noreply@anthropic.com>

Signed-off-by: Gloire Rubambiza <gloire@ibm.com>
Updated two robustness tests to use the new centralized "HTTP call done"
format with purpose field instead of the old distinct messages. Preserves
coverage for _is_dpc_log_file streaming behavior and partial-log handling.

- test_indicator_message_past_256kb_still_parsed: Filler now uses benign
  purpose="get_health" HTTP call done lines (indicator but no timing record)
  to ensure file is recognized as DPC, while real anchor still lands past 256KB.
- test_file_without_relay_but_with_wake_still_parsed: Updated to new format
  with full HTTP call done fields for wake-only case (requester crashed).

All 15 tests pass. No production changes needed.

Assisted-By: Claude Code (Anthropic AI) <noreply@anthropic.com>

Signed-off-by: Gloire Rubambiza <gloire@ibm.com>
The prior filler used "HTTP call done" purpose="get_health" lines, but
_is_dpc_log_file matches on the message string "HTTP call done" alone, so it
returned True at the very first filler line. That defeated the regression: a
re-introduced 256KB-sniffing bug would still find the indicator immediately.

Switch filler to a benign non-indicator klog line ("Flag" ...) so the first
indicator in the file is the real anchor from SAMPLE_LOG, sitting past the
256KB boundary. Same assertions; regression now genuinely bites.

Assisted-By: Claude Code (Anthropic AI) <noreply@anthropic.com>

Signed-off-by: Gloire Rubambiza <gloire@ibm.com>
The DPC's fma_actuation_seconds metric (llm-d#599) now measures actuation
from the requester inference-server container state.running.startedAt,
not the requester pod creation_timestamp. Align the harness Kube-timestamp
fallback to the same baseline so it agrees with the controller.

Replace FMALauncherInfo.dpc_timing_available (bool) with a per-iteration
timing_source string: dpc | kube_container_start | kube_pod_create.
dpc_timing_available is kept as a derived property (timing_source == 'dpc')
and still emitted in dump() for backward-compatible downstream readers.

Add get_container_start_timestamp() mirroring the controller read and
select_kube_fallback_baseline(): prefer container start; when unavailable,
revert to creation_timestamp, set timing_source=kube_pod_create, and emit
a logger.warning naming the requester so a reversion is never silent.

Propagate timing_source (and container_start_timestamp) through
native_to_br0_1.py and render a three-way Source column in
nop-analyze_results.py so kube_pod_create is distinguishable from
kube_container_start.

Assisted-By: Claude Code (Anthropic AI) <noreply@anthropic.com>

Signed-off-by: Gloire Rubambiza <gloire@ibm.com>
select_kube_fallback_baseline previously emitted the kube_pod_create
'may be overstated' warning inline whenever container_start_timestamp
was 0.0. But the DPC-refine step in the finally block can later override
timing_source to 'dpc', so a requester that ended up DPC-timed could
still have emitted a spurious, mooted WARNING during the loop.

Make select_kube_fallback_baseline pure (select baseline + tentative
timing_source, no logging). Add warn_on_pod_create_baseline() and call it
once, after DPC refinement, only for launchers whose FINAL timing_source
is kube_pod_create. A genuine reversion still warns; a DPC-overridden one
no longer does. kube_container_start / dpc paths are unchanged.

Assisted-By: Claude Code (Anthropic AI) <noreply@anthropic.com>

Signed-off-by: Gloire Rubambiza <gloire@ibm.com>
Assisted-By: Claude Code (Anthropic AI) <noreply@anthropic.com>

Signed-off-by: Gloire Rubambiza <gloire@ibm.com>
for launcher_info in iteration["launcher_infos"]:
ct = float(launcher_info["requester_info"]["creation_timestamp"]["value"])
rt = float(launcher_info["requester_info"]["ready_timestamp"]["value"])
ttrr = rt - ct if rt > 0.0 else 0.0

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should this time also start at container_start instead of create?

@rubambiza

Copy link
Copy Markdown
Collaborator Author

Cluster e2e validation — passed ✅

Ran standup → 10 iterations → teardown on FMA v0.6.0 with Qwen3-8B, harness built from this branch tip (f5fbc11). Same FMA version / model / cluster as the earlier baseline run, which under the old parser produced dpc_timing_available: false on every iteration.

Emitted result.yaml:

  • timing_source: dpc on all 10 iterations (derived dpc_timing_available: true consistent).
  • Sub-second hot-start t_wake: 0.537, 0.537, 0.557, 0.587, 0.593, 0.597 s — the wake fidelity this change recovers, corroborating the ~0.51s vLLM-log weight-reload figure.
  • Warm t_instance_create (DPC-internal HTTP timing): ~40.5s cluster + one 60.5s — far tighter than the Kube-timestamp upper bounds.
  • No 403/forbidden/iterations: []; run + teardown clean, GPUs freed.

Scope note (honest coverage boundary)

Because every real actuation had DPC-log HTTP timing present, the run exercised only the dpc path. The Kube-timestamp fallback (timing_source: kube_container_start / kube_pod_create) did not fire on this healthy run — it triggers only when DPC-log timing is absent — so that path remains covered by unit tests (tests/test_fma_functions.py) rather than this live run.

Flipping to ready for review.

@rubambiza
rubambiza marked this pull request as ready for review July 2, 2026 21:09
@maugustosilva
maugustosilva merged commit 0110798 into llm-d:main Jul 6, 2026
26 checks passed
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.

Update DPC log parser to consume the centralized "HTTP call done" log line

3 participants