Skip to content

Commit ef1310f

Browse files
author
Vineeth Rao Kanaparthi
committed
subscriber: skip RwLock in EnvFilter span callbacks when no dynamic directives
EnvFilter maintains `by_id: RwLock<HashMap<Id, SpanMatcher>>` and `by_cs: RwLock<HashMap<Identifier, CallsiteMatcher>>` for tracking per-span field-level match state. These maps are only populated when `has_dynamics` is true (i.e., when the filter has span/field-level directives like `my_crate[span_name]=debug`). However, the span lifecycle callbacks (`on_new_span`, `on_enter`, `on_exit`, `on_close`, `on_record`) unconditionally acquire the `by_id` read lock (or write lock for `on_close`) on every call. When `has_dynamics` is false — which is the common case for pure target=level configurations like `RUST_LOG=info,hyper=warn` — these maps are always empty, and the lock acquisition is wasted work. Under high concurrency this becomes a bottleneck: a GDB backtrace of a Tokio-based HTTP server under load showed ~25 worker threads contending on these RwLock acquisitions, with threads in `read_contended` blocked by `on_close`'s write lock. The contention scales with the number of EnvFilter instances in the subscriber layer stack (one per layer when using per-layer filtering). This commit adds an early `if !self.has_dynamics { return; }` guard to each of the five span lifecycle methods. This is a pure no-op when dynamic directives are present (the existing code path runs unchanged), and completely eliminates the lock traffic for the common static-only configuration.
1 parent efc690f commit ef1310f

File tree

2 files changed

+109
-0
lines changed

2 files changed

+109
-0
lines changed

tracing-subscriber/src/filter/env/mod.rs

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -566,6 +566,9 @@ impl EnvFilter {
566566
/// [`Filter::on_new_span`] methods on `EnvFilter`'s implementations of those
567567
/// traits, but it does not require the trait to be in scope.
568568
pub fn on_new_span<S>(&self, attrs: &span::Attributes<'_>, id: &span::Id, _: Context<'_, S>) {
569+
if !self.has_dynamics {
570+
return;
571+
}
569572
let by_cs = try_lock!(self.by_cs.read());
570573
if let Some(cs) = by_cs.get(&attrs.metadata().callsite()) {
571574
let span = cs.to_span_match(attrs);
@@ -579,6 +582,9 @@ impl EnvFilter {
579582
/// [`Filter::on_enter`] methods on `EnvFilter`'s implementations of those
580583
/// traits, but it does not require the trait to be in scope.
581584
pub fn on_enter<S>(&self, id: &span::Id, _: Context<'_, S>) {
585+
if !self.has_dynamics {
586+
return;
587+
}
582588
// XXX: This is where _we_ could push IDs to the stack instead, and use
583589
// that to allow changing the filter while a span is already entered.
584590
// But that might be much less efficient...
@@ -593,6 +599,9 @@ impl EnvFilter {
593599
/// [`Filter::on_exit`] methods on `EnvFilter`'s implementations of those
594600
/// traits, but it does not require the trait to be in scope.
595601
pub fn on_exit<S>(&self, id: &span::Id, _: Context<'_, S>) {
602+
if !self.has_dynamics {
603+
return;
604+
}
596605
if self.cares_about_span(id) {
597606
self.scope.get_or_default().borrow_mut().pop();
598607
}
@@ -604,6 +613,9 @@ impl EnvFilter {
604613
/// [`Filter::on_close`] methods on `EnvFilter`'s implementations of those
605614
/// traits, but it does not require the trait to be in scope.
606615
pub fn on_close<S>(&self, id: span::Id, _: Context<'_, S>) {
616+
if !self.has_dynamics {
617+
return;
618+
}
607619
// If we don't need to acquire a write lock, avoid doing so.
608620
if !self.cares_about_span(&id) {
609621
return;
@@ -620,6 +632,9 @@ impl EnvFilter {
620632
/// [`Filter::on_record`] methods on `EnvFilter`'s implementations of those
621633
/// traits, but it does not require the trait to be in scope
622634
pub fn on_record<S>(&self, id: &span::Id, values: &span::Record<'_>, _: Context<'_, S>) {
635+
if !self.has_dynamics {
636+
return;
637+
}
623638
if let Some(span) = try_lock!(self.by_id.read()).get(id) {
624639
span.record_update(values);
625640
}

tracing-subscriber/tests/env_filter/per_layer.rs

Lines changed: 94 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -304,3 +304,97 @@ fn multiple_dynamic_filters() {
304304
handle1.assert_finished();
305305
handle2.assert_finished();
306306
}
307+
308+
/// Tests that a static-only `EnvFilter` (no span-name or field-level
309+
/// directives) correctly filters events inside spans.
310+
///
311+
/// This is a regression test for an optimization that skips acquiring the
312+
/// `by_id` RwLock when `has_dynamics` is false. Without the span lifecycle
313+
/// callbacks, events inside spans must still be filtered correctly based on
314+
/// the static target/level directives.
315+
#[test]
316+
fn static_filter_events_inside_spans() {
317+
let filter: EnvFilter = "info,stuff=debug".parse().expect("filter should parse");
318+
let cool_span = expect::span().named("cool_span");
319+
let (layer, handle) = layer::mock()
320+
.new_span(cool_span.clone())
321+
.enter(cool_span.clone())
322+
.event(
323+
expect::event()
324+
.at_level(Level::DEBUG)
325+
.with_target("stuff")
326+
.in_scope(vec![cool_span.clone()]),
327+
)
328+
.event(
329+
expect::event()
330+
.at_level(Level::INFO)
331+
.in_scope(vec![cool_span.clone()]),
332+
)
333+
.exit(cool_span)
334+
.only()
335+
.run_with_handle();
336+
337+
let _subscriber = tracing_subscriber::registry()
338+
.with(layer.with_filter(filter))
339+
.set_default();
340+
341+
{
342+
let _span = tracing::info_span!("cool_span").entered();
343+
tracing::debug!(target: "stuff", "target-enabled debug inside span");
344+
tracing::trace!("should be disabled even inside span");
345+
tracing::info!("info inside span");
346+
}
347+
348+
handle.assert_finished();
349+
}
350+
351+
/// Tests that a static-only `EnvFilter` (no dynamic directives) used as a
352+
/// per-layer filter correctly handles span enter/exit/close without
353+
/// interacting with the `by_id`/`by_cs` RwLocks.
354+
///
355+
/// This verifies the optimization is safe: multiple spans can be created,
356+
/// entered, exited, and dropped with a static-only filter, and events are
357+
/// filtered purely by target and level.
358+
#[test]
359+
fn static_filter_multiple_spans() {
360+
let filter: EnvFilter = "info,stuff=debug".parse().expect("filter should parse");
361+
let span_a = expect::span().named("span_a");
362+
let span_b = expect::span().named("span_b");
363+
let (layer, handle) = layer::mock()
364+
.new_span(span_a.clone())
365+
.enter(span_a.clone())
366+
.event(
367+
expect::event()
368+
.at_level(Level::INFO)
369+
.in_scope(vec![span_a.clone()]),
370+
)
371+
.new_span(span_b.clone())
372+
.enter(span_b.clone())
373+
.event(
374+
expect::event()
375+
.at_level(Level::DEBUG)
376+
.with_target("stuff")
377+
.in_scope(vec![span_b.clone(), span_a.clone()]),
378+
)
379+
.exit(span_b)
380+
.exit(span_a)
381+
.only()
382+
.run_with_handle();
383+
384+
let _subscriber = tracing_subscriber::registry()
385+
.with(layer.with_filter(filter))
386+
.set_default();
387+
388+
{
389+
let _a = tracing::info_span!("span_a").entered();
390+
tracing::debug!("should be disabled by default level");
391+
tracing::info!("info in span_a");
392+
{
393+
let _b = tracing::info_span!("span_b").entered();
394+
tracing::debug!(target: "stuff", "debug in nested span_b");
395+
tracing::trace!(target: "stuff", "trace should be disabled");
396+
}
397+
}
398+
399+
handle.assert_finished();
400+
}

0 commit comments

Comments
 (0)