[None][feat] Expose host/GPU per-iter time and clarify iter labeling in /metrics#14127
Conversation
📝 WalkthroughWalkthroughThis PR extends iteration statistics capture to include per-loop CPU timing, GPU forward timing from the preceding loop, and scheduler mode (overlap vs non-overlap), propagating these values through ADP fanout and metrics output with backward-compatible tuple deserialization. ChangesIteration Stats Timing Extension
🎯 3 (Moderate) | ⏱️ ~25 minutes Possibly Related PRs
Suggested Reviewers
🚥 Pre-merge checks | ✅ 4 | ❌ 1❌ Failed checks (1 warning)
✅ Passed checks (4 passed)
✏️ Tip: You can configure your own custom pre-merge checks in the settings. ✨ Finishing Touches🧪 Generate unit tests (beta)
Comment |
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 2
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@tensorrt_llm/_torch/pyexecutor/py_executor.py`:
- Around line 1498-1503: The scheduler_mode calculation can mislabel PP runs
because _executor_loop_pp yields overlap-style iterLatencyMS even when
self.disable_overlap_scheduler is True; update the logic that sets
scheduler_mode so that if self.dist.pp_size > 1 it is always "overlap",
otherwise keep the existing check (use "non_overlap" only when no pipeline
parallelism and disable_overlap_scheduler is True), and leave hostStepTimeMS
comment unchanged; update the assignment that defines scheduler_mode to
reference self.dist.pp_size and self.disable_overlap_scheduler accordingly so PP
executions report "overlap".
- Around line 1611-1617: The IterationStats emitted in _executor_loop is
snapshotting _latest_host_step_time_ms and _latest_prev_device_step_time_ms too
early (profile_step() updates them at the start of the next loop), so iter N
gets stale timings; modify _executor_loop to buffer the produced IterationStats
(e.g., pending_iteration_stats) and only attach and emit timing fields when the
next loop starts and profile_step() has populated
_latest_host_step_time_ms/_latest_prev_device_step_time_ms, then flush the
pending record; apply the same pending-buffer/delayed-flush change to the other
occurrence that snapshots timings (around the block at lines referenced
1638-1642) so all non-overlap exports wait one iteration for correct timing
values.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Path: .coderabbit.yaml
Review profile: CHILL
Plan: Enterprise
Run ID: 08f5c3aa-7be5-4cfb-ae8c-d428a84c5b47
📒 Files selected for processing (3)
tensorrt_llm/_torch/pyexecutor/adp_iter_stats.pytensorrt_llm/_torch/pyexecutor/py_executor.pytensorrt_llm/executor/base_worker.py
7e672eb to
0441ea8
Compare
|
/bot run --disable-fail-fast |
|
PR_Github #48869 [ run ] triggered by Bot. Commit: |
|
PR_Github #48869 [ run ] completed with state
|
0441ea8 to
d1e7d9f
Compare
|
/bot run --disable-fail-fast |
|
PR_Github #49075 [ run ] triggered by Bot. Commit: |
|
PR_Github #49075 [ run ] completed with state
|
…in /metrics Add three new JSON keys to each /metrics IterationStats record and fix a labeling artifact in the `iter` field. All changes are Python-only and ride the existing serializer-injection pattern used for kvCacheIterationStats — no C++ rebuild required. New JSON keys: - hostStepTimeMS: clean per-loop CPU wall captured by profile_step(). Mirrors the log line's `host_step_time`. Always a single-loop measurement, unlike iterLatencyMS which spans ~2 loops under the overlap scheduler. - prevDeviceStepTimeMS: GPU forward time read via the ping-pong CUDA event pair in profile_step(). The "prev_" prefix reflects that under steady state the value lags hostStepTimeMS on the same record by one loop (see the ping-pong design comment in _profiler). - schedulerMode: "overlap" or "non_overlap". Per-record indicator so consumers can interpret iterLatencyMS without inspecting server config. iter relabel: - stats.iter is now stamped at batch construction time in _get_init_iter_stats (the loop that BUILT the batch), instead of at consumption time in _update_iter_stats. Under the overlap and PP schedulers _process_iter_stats runs in a later loop than the one that built the batch, so the live iter_counter mislabeled records by 1+ iters. - Note: this changes /metrics jsonl alignment with server_runtime.log. Under overlap mode the two streams are now off by 1 iter (the log still stamps from the live counter at print time). Signed-off-by: Yueh-Ting Chen <yuehtingc@nvidia.com> Signed-off-by: Yueh-Ting Chen <yueh.ting.chen@gmail.com>
d1e7d9f to
1e3acc5
Compare
|
/bot run --disable-fail-fast |
|
PR_Github #49575 [ run ] triggered by Bot. Commit: |
|
PR_Github #49575 [ run ] completed with state
|
|
/bot run --disable-fail-fast |
|
PR_Github #49838 [ run ] triggered by Bot. Commit: |
|
PR_Github #49838 [ run ] completed with state |
Superjomn
left a comment
Superjomn
left a comment
There was a problem hiding this comment.
Are there any tests to protect this feature? Or it will be broken easily in the following iterations.
Add two focused tests for the changes in 1e3acc5 (Expose host/GPU per-iter time and clarify iter labeling in /metrics): 1. test_update_iter_stats_does_not_overwrite_construction_iter Regression guard: _update_iter_stats must not re-stamp stats.iter from the live self.iter_counter. Before the fix, under overlap and PP schedulers the consuming loop ran 1+ iters after the loop that built the batch, so re-stamping mislabeled records. The test passes a batch stamped at iter=17, advances iter_counter to 999, and confirms the construction-time stamp survives. 2. test_serializer_7_tuple_emits_new_timing_and_scheduler_mode Verifies the three new JSON keys (hostStepTimeMS, prevDeviceStepTimeMS, schedulerMode) emitted from the 7-tuple slots in BaseWorker._stats_serializer. Also confirms a None timing slot omits the key (not null) so consumers can distinguish "first iter / unavailable" from a real zero. Signed-off-by: Yueh-Ting Chen <yueh.ting.chen@gmail.com> Signed-off-by: Yueh-Ting Chen <yuehtingc@nvidia.com>
|
/bot run --disable-fail-fast |
|
PR_Github #50168 [ run ] triggered by Bot. Commit: |
|
PR_Github #50168 [ run ] completed with state
|
|
/bot run --disable-fail-fast |
|
PR_Github #50283 [ run ] triggered by Bot. Commit: |
|
PR_Github #50283 [ run ] completed with state |
…ache-manager-stats
|
/bot run --disable-fail-fast |
|
PR_Github #50550 [ run ] triggered by Bot. Commit: |
|
PR_Github #50550 [ run ] completed with state
|
|
/bot run --disable-fail-fast |
|
PR_Github #50645 [ run ] triggered by Bot. Commit: |
|
PR_Github #50645 [ run ] completed with state
|
|
/bot skip --comment "Given that this MR has earned pre-merge CI success before. The latest merge is only on resolving conflict to the print calls. The failing pipeline is un-related to the change introduced in this MR. Skipping the CI now." |
|
PR_Github #50733 [ skip ] triggered by Bot. Commit: |
|
PR_Github #50733 [ skip ] completed with state |
4 participants
Summary
Add three new JSON keys to each
/metricsIterationStatsrecord and fix alabeling artifact in the
iterfield. All changes are Python-only and ridethe existing serializer-injection pattern used for
kvCacheIterationStats(PR #12413) — no C++ rebuild required.
New JSON keys
hostStepTimeMSprofile_step(). Mirrors the log line'shost_step_time. Always single-loop, unlikeiterLatencyMSwhich spans ~2 loops under the overlap scheduler.prevDeviceStepTimeMSprofile_step(). The"prev_"prefix reflects that under steady state the value lagshostStepTimeMSon the same record by 1 loop.schedulerMode"overlap"|"non_overlap"iterLatencyMSwithout inspecting server config. PP (pp_size > 1) always reports"overlap"since_executor_loop_ppis structurally overlap-style (BatchStatePP is queued in iter N and consumed in a later loop), regardless ofdisable_overlap_scheduler.iterfield relabelstats.iteris now stamped at batch construction time in_get_init_iter_stats(the loop that BUILT the batch) instead of atconsumption time in
_update_iter_stats. Under the overlap and PPschedulers
_process_iter_statsruns in a later loop than the one thatbuilt the batch, so the live
iter_countermislabeled records by 1+ iters.Note: this changes how
/metricsjsonl aligns withserver_runtime.log.Under overlap mode the two streams are now off by 1 iter (the log line still
stamps from the live counter at print time, which is intentional and
unchanged here).
Why
These changes address three concrete pain points users hit when joining
/metricsdata against batch composition for performance benchmarking:numCtxTokens(and otherinflightBatchingStats) appeared to lag theiterlabel by 1+ iterations under overlap — actually theiterlabelitself was wrong; the batch composition was correctly attributed.
iterLatencyMSis misleading for absolute per-loop CPU cost underoverlap (spans ~2 loops,
sum ≈ 2 × wall_time).hostStepTimeMSgivesthe clean per-loop value, and
schedulerModelets consumers branch.prev_device_step_time),not in the JSON.
prevDeviceStepTimeMSexposes it directly to /metricsconsumers.
Implementation summary
tensorrt_llm/_torch/pyexecutor/py_executor.py:_profiler.profile_step(): split timing capture from log emission sotiming is stashed on
self._latest_host_step_time_ms/self._latest_prev_device_step_time_mswheneverenable_iter_perf_statsorprint_iter_logis on._get_init_iter_stats: stampstats.iterat construction._update_iter_stats: removed the consumption-timestats.iteroverwrite(replaced with a comment).
_process_iter_stats: snapshot per-loop timings and pass through theappend/queue path; documented
iterLatencyMSsemantics under bothschedulers.
_append_iter_stats: extended withhost_step_time_ms/prev_device_step_time_mskwargs; computesschedulerModewith thePP-as-overlap rule; injects new keys into the
gather_all_ranksper-rank dict and into the legacy tuple (now 7 entries, defensive
len() > Naccess in the serializer keeps older shapes readable).tensorrt_llm/_torch/pyexecutor/adp_iter_stats.py:ADPIterStatsRecordcarries the new timing fields;
queue/finalize/_discardupdatedto preserve them across the ADP fanout delay. Rank-0 values are broadcast
to all rank rows (true per-rank timing would require widening the
rank-state allgather payload — left for a future PR).
tensorrt_llm/executor/base_worker.py:_stats_serializerreads tupleslots
[4]/[5]/[6]defensively and injects the new JSON keys withfield-level comments explaining the semantics.
Test plan
enable_iter_perf_stats=true+enable_block_reuse=trueGET /metricsJSON containshostStepTimeMS,prevDeviceStepTimeMS, andschedulerModeon each recorditerfield matches construction-time iter (numbers are 1 lower under overlap mode than before)pp_size > 1) reportsschedulerMode = "overlap"in/metricseven whendisable_overlap_scheduler=True.print_iter_log=true(gated condition was widened to also fire whenenable_iter_perf_stats=true)tests/unittest/[x] Write code carefully and responsibly.