Skip to content

feat: Tighter FMA timing via DPC log parsing - #1504

Merged
aavarghese merged 4 commits into
llm-d:mainfrom
rubambiza:feat/dpc-log-parsing-timing
Jun 19, 2026
Merged

feat: Tighter FMA timing via DPC log parsing#1504
aavarghese merged 4 commits into
llm-d:mainfrom
rubambiza:feat/dpc-log-parsing-timing

Conversation

@rubambiza

@rubambiza rubambiza commented Jun 15, 2026

Copy link
Copy Markdown
Collaborator

Summary

  • Add dpc_log_parser.py module that parses DPC controller logs to extract
    httpCallStartTime/k8sCallStartTime fields at microsecond precision
  • Integrate parser into benchmark_fma() to override Kube-timestamp upper
    bounds with tighter DPC-derived values when available
  • Graceful fallback: if DPC log data is unavailable (pre-PR Log call durations on launcher/instance/K8s actuation calls llm-d-incubation/llm-d-fast-model-actuation#522 DPC, low
    verbosity, requester crash before relay), Kube upper bounds stand unchanged
  • Streams log files line-by-line to handle large DPC logs without memory pressure
  • Propagate dpc_timing_available through native_to_br0_1 conversion so the
    analysis report attributes each row to its true source
  • Adds "Source" column (DPC/Kube) to analysis output

Closes #1465

Timing improvement (validated on cluster)

Measured on a 10-iteration nop run (scale 0->1->0 per iteration). The DPC log
parser now yields sub-second hot-start timing, confirming that the previous
8-10s figures were dominated by the kubelet readiness-probe interval rather than
actual wake latency.

Path Before (Kube upper bound) After (DPC log) Source of inflation
Hot 8s (also 3s when probe lands sooner) 0.53-0.59s (t_wake) kubelet readiness probe delay (~10s period)
Warm 53-62s (T_actuation) ~50.5s (t_instance_create) requester scheduling + probe delay
Cold n/a this run -- no cold-launcher iterations occurred in the validation run

An independent cross-check from the vLLM launcher log on the same run reported a
wake transition of ~0.51s, consistent with the DPC-derived t_wake.

Measurement conditions

  • Model: meta-llama/Llama-3.1-8B-Instruct
  • FMA launcher image: ghcr.io/llm-d-incubation/llm-d-fast-model-actuation/launcher:v0.6.0-alpha.13 (includes PR Unexpected EOF from inference-perf-analyze_results.sh #522 timing fields)
  • vLLM: 0.20.2, sleep mode enabled, gpu_memory_utilization=0.95, prefix caching off
  • Cluster: OpenShift on IBM Spectrum Scale storage, NVIDIA GPUs
  • Run: 10 iterations; hit rates this run were 30% hot / 70% warm / 0% cold

Numbers are representative of a single validation run; hot-start hit rate (and
thus how often the sub-second path is exercised) depends on workload pattern and
launcher capacity configuration.

Test plan

  • Unit tests for klog line parsing (hot/warm/cold paths)
  • Edge cases: retry, unready relay, malformed timestamps, multi-requester
  • File-based parsing (directory scanning, missing dir, partial logs)
  • Large-log detection: indicator message located far into the file (past the initial read window)
  • Integration run on cluster with DPC v0.6.0-alpha.13+ (PR Unexpected EOF from inference-perf-analyze_results.sh #522 merged)
  • Verify timing values match manual log inspection (vLLM launcher log cross-check)

Related

Assisted-By: Claude Code

@rubambiza
rubambiza marked this pull request as draft June 15, 2026 13:20
@rubambiza
rubambiza marked this pull request as ready for review June 18, 2026 20:56
Signed-off-by: Gloire Rubambiza <gloire@ibm.com>
Signed-off-by: Gloire Rubambiza <gloire@ibm.com>
Signed-off-by: Gloire Rubambiza <gloire@ibm.com>
The DPC timing refinement silently fell back to Kube upper bounds on
real cluster runs. Two bugs, both surfaced during cluster validation:

1. _is_dpc_log_file() only sniffed the first 256KB of a .log for an
   indicator message. A real controller log was 1.08MB with its first
   relay/wake/create message at byte ~429K (after startup noise), so the
   log was discarded and the parser never ran. Now stream line-by-line
   with early-exit. Added a regression test with an indicator past 256KB.

2. native_to_br0_1 dropped the dpc_timing_available flag during
   conversion, so the analyzer's Source column always showed Kube even
   when timing was DPC-derived. Propagate the flag into launcher_infos.

Validated on cluster: dpc_timing_available true on all iterations,
hot-start t_wake ~0.53-0.59s (vs 8s Kube upper bound), Source=DPC.

Assisted-By: Claude Opus 4.6 <noreply@anthropic.com>

Signed-off-by: Gloire Rubambiza <gloire@ibm.com>
@rubambiza
rubambiza force-pushed the feat/dpc-log-parsing-timing branch from 1361393 to 5d06f1d Compare June 19, 2026 16:33
@rubambiza

Copy link
Copy Markdown
Collaborator Author

The force push (5d06f1d) was a fresh rebase on main.

@aavarghese
aavarghese enabled auto-merge (squash) June 19, 2026 17:45
@aavarghese
aavarghese merged commit 11ae84d into llm-d:main Jun 19, 2026
26 checks passed
@rubambiza
rubambiza deleted the feat/dpc-log-parsing-timing branch July 1, 2026 12:57
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.

[Feature]: Tighter FMA timing via DPC log parsing

2 participants