[Bugfix][Rust Frontend] Prevent MM timing from enabling debug tracing (#58378)
Co-authored-by: Bugen Zhao <i@bugenzhao.com> Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com> Signed-off-by: reidliu41 <reid201711@gmail.com> Signed-off-by: Bugen Zhao <i@bugenzhao.com>
Reid committed
Sep 24, 2026 at 17:22 UTC
e430f7421ff095d8f5fbf1b910438f7d35d9bdf3
3 files changed
+79
-9
rust/src/chat/Cargo.toml
+1
-1
@@ -28,6 +28,7 @@ thiserror-ext.workspace = true
28
time.workspace = true
29
tokio.workspace = true
30
tracing.workspace = true
31
+tracing-subscriber.workspace = true
32
trait-set.workspace = true
33
uuid.workspace = true
34
vllm-engine-core-client.workspace = true
@@ -48,7 +49,6 @@ rmp-serde.workspace = true
49
serial_test.workspace = true
50
tempfile.workspace = true
51
tokio.workspace = true
51
-tracing-subscriber.workspace = true
52
uuid.workspace = true
53
vllm-engine-core-client = { workspace = true, features = ["test-util"] }
54
vllm-tokenizer = { workspace = true, features = ["test-utils"] }
rust/src/chat/src/multimodal/timing.rs
+5
-1
@@ -4,6 +4,7 @@
4
//! Multimodal preprocessing spans and their timing collector configuration.
5
6
use tracing::{Span, info_span};
7
+use tracing_subscriber::filter::{Filtered, LevelFilter};
8
use vllm_tracing::timing::{RequestTimingLayer, RequestTimingStats};
9
10
/// Target of the multimodal preprocessing stage spans.
@@ -12,7 +13,10 @@ pub(super) const MM_STAGE_TARGET: &str = "mm_processor_timing";
13
/// Create the timing layer and its stats handle for multimodal preprocessing
14
/// stage spans (`vllm-bench mm-processor`), mirroring the Python
15
/// `TimingContext` / `MultiModalTimingRegistry`.
15
-pub fn mm_timing_layer() -> (RequestTimingLayer, RequestTimingStats) {
16
+pub fn mm_timing_layer<S>() -> (
17
+ Filtered<RequestTimingLayer, LevelFilter, S>,
18
+ RequestTimingStats,
19
+) {
20
RequestTimingLayer::new(MM_STAGE_TARGET)
21
}
22
rust/src/tracing/src/timing.rs
+73
-7
@@ -18,6 +18,7 @@ use std::time::Instant;
18
use tracing::field::{Field, Visit};
19
use tracing::span::Attributes;
20
use tracing::{Id, Subscriber};
21
+use tracing_subscriber::filter::{Filtered, LevelFilter};
22
use tracing_subscriber::layer::{Context, Layer};
23
use tracing_subscriber::registry::LookupSpan;
24
@@ -66,7 +67,8 @@ impl Visit for SpanFields {
67
/// Timed spans must have the configured target and a `stage` field. The
68
/// `request_id` is taken from the timed span itself or its nearest ancestor
69
/// carrying that field, regardless of the ancestor's target. Spans without
69
-/// a request ID are ignored. Span names are unrestricted.
70
+/// a request ID are ignored. Span names are unrestricted. Both the timed spans
71
+/// and their `request_id` ancestors must be at `INFO` level or above.
72
///
73
/// Both fields are read at span creation; subsequent [`tracing::Span::record`]
74
/// calls are ignored. String values are used verbatim; other values use their
@@ -93,13 +95,18 @@ pub struct RequestTimingStats {
95
impl RequestTimingLayer {
96
/// Create the layer and its stats handle. Only spans whose target equals
97
/// `target` and that carry a `stage` field are timed.
96
- pub fn new(target: &'static str) -> (Self, RequestTimingStats) {
98
+ ///
99
+ /// The layer is filtered to `INFO` so that, composed with a filtered log
100
+ /// layer, it does not raise the subscriber's max level hint and enable
101
+ /// `DEBUG`/`TRACE` callsites that the log layer would discard anyway.
102
+ pub fn new<S>(target: &'static str) -> (Filtered<Self, LevelFilter, S>, RequestTimingStats) {
103
let stats = Arc::new(Mutex::new(HashMap::new()));
104
+ let layer = Self {
105
+ target,
106
+ stats: Arc::clone(&stats),
107
+ };
108
(
99
- Self {
100
- target,
101
- stats: Arc::clone(&stats),
102
- },
109
+ Filtered::new(layer, LevelFilter::INFO),
110
RequestTimingStats { stats },
111
)
112
}
@@ -165,8 +172,10 @@ where
172
173
#[cfg(test)]
174
mod tests {
175
+ use std::sync::atomic::{AtomicUsize, Ordering};
176
+
177
use super::*;
169
- use tracing::info_span;
178
+ use tracing::{debug, debug_span, info_span};
179
use tracing_subscriber::layer::SubscriberExt as _;
180
181
const TARGET: &str = "test_request_timing";
@@ -218,6 +227,63 @@ mod tests {
227
assert!(stats.stat().is_empty());
228
}
229
230
+ #[test]
231
+ fn does_not_enable_debug_at_info() {
232
+ let (timing_layer, _) = RequestTimingLayer::new(TARGET);
233
+ let info_layer = tracing_subscriber::fmt::layer()
234
+ .with_writer(std::io::sink)
235
+ .with_filter(LevelFilter::INFO);
236
+ let subscriber = tracing_subscriber::registry().with(timing_layer).with(info_layer);
237
+ let evaluated_debug_fields = AtomicUsize::new(0);
238
+
239
+ tracing::subscriber::with_default(subscriber, || {
240
+ assert_eq!(LevelFilter::current(), LevelFilter::INFO);
241
+ debug!(
242
+ value = evaluated_debug_fields.fetch_add(1, Ordering::Relaxed),
243
+ "debug event"
244
+ );
245
+ assert!(debug_span!("debug span").is_disabled());
246
+ });
247
+
248
+ assert_eq!(evaluated_debug_fields.load(Ordering::Relaxed), 0);
249
+ }
250
+
251
+ #[test]
252
+ fn does_not_disable_explicit_debug_logging() {
253
+ let (timing_layer, _) = RequestTimingLayer::new(TARGET);
254
+ let debug_layer = tracing_subscriber::fmt::layer()
255
+ .with_writer(std::io::sink)
256
+ .with_filter(LevelFilter::DEBUG);
257
+ let subscriber = tracing_subscriber::registry().with(timing_layer).with(debug_layer);
258
+ let evaluated_debug_fields = AtomicUsize::new(0);
259
+
260
+ tracing::subscriber::with_default(subscriber, || {
261
+ assert_eq!(LevelFilter::current(), LevelFilter::DEBUG);
262
+ debug!(
263
+ value = evaluated_debug_fields.fetch_add(1, Ordering::Relaxed),
264
+ "debug event"
265
+ );
266
+ assert!(!debug_span!("debug span").is_disabled());
267
+ });
268
+
269
+ assert_eq!(evaluated_debug_fields.load(Ordering::Relaxed), 1);
270
+ }
271
+
272
+ #[test]
273
+ fn records_stage_timings_when_logging_at_warn() {
274
+ let (timing_layer, stats) = RequestTimingLayer::new(TARGET);
275
+ let warn_layer = tracing_subscriber::fmt::layer()
276
+ .with_writer(std::io::sink)
277
+ .with_filter(LevelFilter::WARN);
278
+ let subscriber = tracing_subscriber::registry().with(timing_layer).with(warn_layer);
279
+ tracing::subscriber::with_default(subscriber, || {
280
+ info_span!("request", request_id = "req-1").in_scope(|| {
281
+ drop(stage_span("media_fetch"));
282
+ });
283
+ });
284
+ assert!(stats.stat()["req-1"].contains_key("media_fetch_secs"));
285
+ }
286
+
287
#[test]
288
fn other_targets_are_ignored() {
289
let (layer, stats) = RequestTimingLayer::new(TARGET);