instrument: always-on Prometheus histograms for frontend routing, scheduling, and request-plane ACK (DYN-3401) - #4
Closed
peilii wants to merge 9 commits into
Conversation
Add per-request ACK latency tracing on the worker request plane to localize the iter4 collapse trigger (GEN request-plane ACK starvation). Carries decoded_at + request_id from read_loop to write_loop so the flush latency splits into queue_ms (write-task scheduling delay = runtime/CPU starvation) vs write_ms (socket), logged to target dynamo_ack_trace, WARN above DYN_ACK_TRACE_WARN_MS. Frontend CannotConnect timeout log gains request_id+timeout_s for correlation. Gated by DYN_ACK_TRACE=1; zero-overhead when off. Signed-off-by: Yuewei Na <nv-yna@users.noreply.github.com>
… (DYN_ACK_TRACE) Add direct logging to identify WHICH runtime is starved during the request-plane ACK-timeout collapse, instead of relying on the frontend-only metric scrape: - tokio_metrics_and_canary_loop now WARNs to target dynamo_stall when its event loop is delayed past DYN_STALL_LOG_MS (default 250ms). - spawn that canary from SharedTcpServer.bind_and_start (gated by DYN_ACK_TRACE) so WORKER runtimes are monitored, not just the frontend HTTP service. - read_loop WARNs the frontend-send -> worker-decode arrival delay (the pre-decode wait the decode->flush trace misses) to target dynamo_ack_trace. Together: each process's log shows if/when its request-plane runtime starves. Signed-off-by: Yuewei Na <nv-yna@users.noreply.github.com>
…DYN_PREFILL_TRACE) Localize disagg prefill pre-decode time: per-request a(arrive)->b(CTX-selected)-> c(dispatch)->d(first-resp)->e(done) gaps + per-CTX in-flight-prefill gauge. Discriminator for CTX under-feed root cause. Zero-cost when off. Signed-off-by: Yuewei Na <nv-yna@users.noreply.github.com>
Add MOCK_KV_WAIT_TIMEOUT_MS gated warning on TRT-LLM workers (both CTX prefill and GEN decode) that fires when a request's wall-clock queue wait from receive() to first scheduling slot exceeds the threshold. Mirrors TRT-LLM's two-sided KV transfer timeout: - CTX side: kv_transfer_sender_future_timeout_ms (sender waits for GEN to acknowledge transfer after respond_and_send_async) - GEN side: kv_transfer_timeout_ms (receiver waits for KV blocks after request_and_receive_async) With --kv-transfer-bandwidth 0 the only delay is orchestration overhead, so any fire indicates the frontend is holding requests too long before the worker sees them. Gated on EngineType::Trtllm only; vLLM and sglang workers are unaffected. Logged to dynamo_stall_op target with op, worker_type, uuid, and wait_ms fields. Refs: DYN-3082
Adds Prometheus histograms for the scheduler admission path and the request-plane ACK flush latency, giving percentile distributions over the full population instead of only the log-threshold tail sampled by DYN_STALL_OP_WARN_MS / DYN_ACK_TRACE_WARN_MS traces. - dynamo_router_overhead_admission_compute_ms (per worker_type): project_worker_loads + select_worker CPU time on the scheduler actor. - dynamo_router_overhead_queue_wait_ms (per worker_type): time a request sits parked in the pending heap before admission. - dynamo_request_plane_ack_flush_seconds: decoded_at → socket flush complete on SharedTcpEndpoint write_loop. All three are observed on every event (not gated by a log threshold) and registered via the frontend HTTP service Prometheus registry. Refs: DYN-2636
The scheduler-side check in core.rs fires only when a request queues (from_waiting=true), which doesn't happen at speedup=1M. Moving the warn to the actual KV sleep site in mocker.rs ensures it fires for every prefill whose handoff delay exceeds MOCK_KV_WAIT_TIMEOUT_MS, giving a reliable signal proportional to ISL and bandwidth config. Refs: DYN-2636
…d tokenize/preprocess histograms
…ker-state propagation, HTTP-to-preprocess wait
dynamo_router_actor_mailbox_wait_ms couldn't distinguish per-request Enqueue
backlog from per-completion-event Update backlog -- the two have very
different volume and semantics under load. Add a command="enqueue"|"update"
label via a new AdmissionCommand::kind() accessor.
The existing dynamo_request_plane_queue_seconds lumps together stream
registration, the tombstone check, and envelope serialization into one
number. Split it into dynamo_request_plane_register_streams_ms,
_associate_instance_ms, and _build_envelope_ms at the three call sites
inside dispatch_and_finalize; add _dispatch_buffer_ms as a finer-grained
(ms, not s) sibling of the existing send_seconds at the same call site.
dynamo_worker_state_update_to_scheduler_ms{event} wraps queue.update().await
in LocalScheduler::mark_prefill_completed/free -- the actual worker-state
-> scheduler propagation path, previously unmeasured.
dynamo_frontend_http_to_preprocess_wait_ms wraps the chat_completions axum
handler from entry to the engine.generate() call, i.e. validation/template
resolution/engine lookup before the pipeline is even invoked -- earlier and
broader than request_preprocess_wait_ms, which starts inside the pipeline.
No behavior change (the associate_instance let-chain was restructured into
a nested if to time just that await; same short-circuit semantics). cargo
test -p dynamo-kv-router -p dynamo-llm -p dynamo-runtime (scheduling::,
preprocessor::, http::service::openai::, pipeline::network:: suites, 345
tests) passes with and without the "metrics" feature.
…quest-plane ACK
New dynamo_frontend_* metrics (frontend_perf.rs):
hash_blocks_ms, hash_seq_ms — block/seq hash CPU time in kv_router.route()
index_lookup_ms — KV index lookup (radix walk or remote)
schedule_ms — scheduler actor wait (enqueue → response)
New dynamo_request_plane_* metrics (request_plane.rs):
ack_flush_seconds — full ACK flush latency (decoded_at → flush)
ack_write_queue_ms — write-task scheduling delay component
ack_socket_write_ms — socket write component
dispatch_buffer_ms{worker} — dispatch_buffer labeled by worker endpoint
+ queue/send/roundtrip_ttft/register_streams/associate_instance/build_envelope
New dynamo_kv_router_* metrics (--features kv-indexer-metrics):
actor_mailbox_wait_ms, actor_poll_gap_ms, schedule_compute_ms,
pending_queue_age_ms, worker_state_update_to_scheduler_ms
Refs: DYN-3401
|
👋 Hi peilii! Thank you for contributing to nv-yna/dynamo. Just a reminder: The 🚀 |
Author
|
Closing — PR will be opened against ai-dynamo/dynamo instead. |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Adds always-on Prometheus histograms across the frontend pipeline. All metrics observe every event — full population distributions, not log-threshold tail samples.
New metrics
Frontend pipeline (
dynamo_frontend_*)dynamo_frontend_tokenize_encode_msdynamo_frontend_request_preprocess_wait_msdynamo_frontend_http_to_preprocess_wait_msdynamo_frontend_hash_blocks_msdynamo_frontend_hash_seq_msdynamo_frontend_index_lookup_msdynamo_frontend_schedule_msRequest-plane (
dynamo_request_plane_*)dynamo_request_plane_ack_flush_secondsdynamo_request_plane_ack_write_queue_msdynamo_request_plane_ack_socket_write_msdynamo_request_plane_dispatch_buffer_msworkerdynamo_request_plane_register_streams_msdynamo_request_plane_associate_instance_msdynamo_request_plane_build_envelope_msScheduler (
dynamo_router_*,dynamo_worker_*)dynamo_router_overhead_admission_compute_msworker_typedynamo_router_overhead_queue_wait_msworker_typedynamo_router_actor_mailbox_wait_msworker_type,commanddynamo_router_actor_poll_gap_msworker_typedynamo_router_schedule_compute_msworker_typedynamo_router_pending_queue_age_msworker_typedynamo_worker_state_update_to_scheduler_mseventworker_typelabel values:prefill/decodeEnv-var gates (unchanged behavior)
DYN_ACK_TRACE=1— enables warn logs for slow ACK flushes (histogram observations are always-on regardless)DYN_STALL_OP_TRACE=1— enables warn logs for slow frontend event-loop ops (histogram observations are always-on regardless)DYN_PREFILL_TRACE=1— enables per-request prefill lifecycle tracingTest plan
cargo check -p dynamo-kv-router -p dynamo-llm -p dynamo-runtimepasses clean/metricsendpoint when running with--features metricsprefill/decode) show up on scheduling histogramsRefs: DYN-3401