From 4d3cafa8ee0d8c1c513a81a02a9e66dd18d5be68 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 20 Oct 2020 13:36:25 -0700 Subject: [PATCH 01/13] subscriber: use a warm dispatcher in fmt benches Signed-off-by: Eliza Weisman --- tracing-subscriber/benches/fmt.rs | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/tracing-subscriber/benches/fmt.rs b/tracing-subscriber/benches/fmt.rs index 754401a9f9..b6c144da6a 100644 --- a/tracing-subscriber/benches/fmt.rs +++ b/tracing-subscriber/benches/fmt.rs @@ -41,8 +41,9 @@ fn bench_new_span(c: &mut Criterion) { group.bench_with_input(BenchmarkId::new("multithreaded", i), i, |b, &i| { b.iter_custom(|iters| { let mut total = Duration::from_secs(0); + let dispatch = mk_dispatch(); for _ in 0..iters { - let bench = MultithreadedBench::new(mk_dispatch()); + let bench = MultithreadedBench::new(duspatch.clone()); let elapsed = bench .thread(move || { for n in 0..i { @@ -95,7 +96,8 @@ fn mk_dispatch() -> tracing::Dispatch { fn bench_event(c: &mut Criterion) { bench_thrpt(c, "event", |group, i| { group.bench_with_input(BenchmarkId::new("root/single_threaded", i), i, |b, &i| { - tracing::dispatcher::with_default(&mk_dispatch(), || { + let dispatch = mk_dispatch(); + tracing::dispatcher::with_default(&dispatch, || { b.iter(|| { for n in 0..i { tracing::info!(n); @@ -106,8 +108,9 @@ fn bench_event(c: &mut Criterion) { group.bench_with_input(BenchmarkId::new("root/multithreaded", i), i, |b, &i| { b.iter_custom(|iters| { let mut total = Duration::from_secs(0); + let dispatch = mk_dispatch(); for _ in 0..iters { - let bench = MultithreadedBench::new(mk_dispatch()); + let bench = MultithreadedBench::new(dispatch.clone()); let elapsed = bench .thread(move || { for n in 0..i { @@ -156,8 +159,9 @@ fn bench_event(c: &mut Criterion) { |b, &i| { b.iter_custom(|iters| { let mut total = Duration::from_secs(0); + let dispatch = mk_dispatch(); for _ in 0..iters { - let bench = MultithreadedBench::new(mk_dispatch()); + let bench = MultithreadedBench::new(dispatch.clone()); let elapsed = bench .thread_with_setup(move |start| { let span = tracing::info_span!("unique_parent", foo = false); @@ -203,13 +207,13 @@ fn bench_event(c: &mut Criterion) { i, |b, &i| { b.iter_custom(|iters| { + let dispatch = mk_dispatch(); let mut total = Duration::from_secs(0); for _ in 0..iters { - let dispatch = mk_dispatch(); let parent = tracing::dispatcher::with_default(&dispatch, || { tracing::info_span!("shared_parent", foo = "hello world") }); - let bench = MultithreadedBench::new(dispatch); + let bench = MultithreadedBench::new(dispatch.clone()); let parent2 = parent.clone(); bench.thread_with_setup(move |start| { let _guard = parent2.enter(); From 86f2cfebb06691192505392b4684d73e2391fe9a Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 20 Oct 2020 13:39:39 -0700 Subject: [PATCH 02/13] add multiparent Signed-off-by: Eliza Weisman --- tracing-subscriber/benches/fmt.rs | 73 ++++++++++++++++++++++++++++++- 1 file changed, 72 insertions(+), 1 deletion(-) diff --git a/tracing-subscriber/benches/fmt.rs b/tracing-subscriber/benches/fmt.rs index b6c144da6a..a039e66d4d 100644 --- a/tracing-subscriber/benches/fmt.rs +++ b/tracing-subscriber/benches/fmt.rs @@ -43,7 +43,7 @@ fn bench_new_span(c: &mut Criterion) { let mut total = Duration::from_secs(0); let dispatch = mk_dispatch(); for _ in 0..iters { - let bench = MultithreadedBench::new(duspatch.clone()); + let bench = MultithreadedBench::new(dispatch.clone()); let elapsed = bench .thread(move || { for n in 0..i { @@ -253,6 +253,77 @@ fn bench_event(c: &mut Criterion) { }) }, ); + group.bench_with_input( + BenchmarkId::new("multi-parent/multithreaded", i), + i, + |b, &i| { + b.iter_custom(|iters| { + let dispatch = mk_dispatch(); + let mut total = Duration::from_secs(0); + for _ in 0..iters { + let parent = tracing::dispatcher::with_default(&dispatch, || { + tracing::info_span!("multiparent", foo = "hello world") + }); + let bench = MultithreadedBench::new(dispatch.clone()); + let parent2 = parent.clone(); + bench.thread_with_setup(move |start| { + let _guard = parent2.enter(); + start.wait(); + let mut span = tracing::info_span!("parent"); + for n in 0..i { + let s = tracing::info_span!(parent: &span, "parent2", n, i); + s.in_scope(|| { + tracing::info!(n); + }); + span = s; + } + }); + let parent2 = parent.clone(); + bench.thread_with_setup(move |start| { + let _guard = parent2.enter(); + start.wait(); + let mut span = tracing::info_span!("parent"); + for n in 0..i { + let s = tracing::info_span!(parent: &span, "parent2", n, i); + s.in_scope(|| { + tracing::info!(n); + }); + span = s; + } + }); + let parent2 = parent.clone(); + bench.thread_with_setup(move |start| { + let _guard = parent2.enter(); + start.wait(); + let mut span = tracing::info_span!("parent"); + for n in 0..i { + let s = tracing::info_span!(parent: &span, "parent2", n, i); + s.in_scope(|| { + tracing::info!(n); + }); + span = s; + } + }); + let parent2 = parent.clone(); + bench.thread_with_setup(move |start| { + let _guard = parent2.enter(); + start.wait(); + let mut span = tracing::info_span!("parent"); + for n in 0..i { + let s = tracing::info_span!(parent: &span, "parent2", n, i); + s.in_scope(|| { + tracing::info!(n); + }); + span = s; + } + }); + let elapsed = bench.run(); + total += elapsed; + } + total + }) + }, + ); }); } From e79515dd173d8028508b04590f18f003eb45db85 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 20 Oct 2020 12:48:15 -0700 Subject: [PATCH 03/13] subscriber: update `sharded-slab` to 0.1 Signed-off-by: Eliza Weisman --- tracing-subscriber/Cargo.toml | 2 +- tracing-subscriber/src/registry/sharded.rs | 6 +++--- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/tracing-subscriber/Cargo.toml b/tracing-subscriber/Cargo.toml index e79ca3d17a..e5c93916e2 100644 --- a/tracing-subscriber/Cargo.toml +++ b/tracing-subscriber/Cargo.toml @@ -54,7 +54,7 @@ tracing-serde = { path = "../tracing-serde", version = "0.2", optional = true } parking_lot = { version = ">= 0.7, <= 0.11", optional = true } # registry -sharded-slab = { version = "^0.0.9", optional = true } +sharded-slab = { version = "0.1.0", optional = true } thread_local = { version = "1.0.1", optional = true } [dev-dependencies] diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index d26a3e70e3..20e8bf71c0 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -1,4 +1,4 @@ -use sharded_slab::{Guard, Slab}; +use sharded_slab::{Entry, Slab}; use thread_local::ThreadLocal; use super::stack::SpanStack; @@ -65,7 +65,7 @@ pub struct Registry { #[cfg_attr(docsrs, doc(cfg(feature = "registry")))] #[derive(Debug)] pub struct Data<'a> { - inner: Guard<'a, DataInner>, + inner: Entry<'a, DataInner>, } #[derive(Debug)] @@ -130,7 +130,7 @@ impl Registry { self.spans.insert(s) } - fn get(&self, id: &Id) -> Option> { + fn get(&self, id: &Id) -> Option> { self.spans.get(id_to_idx(id)) } From cecb0f700b1c19a74ee67771ba5a83cc2ba4606b Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 20 Oct 2020 13:01:16 -0700 Subject: [PATCH 04/13] registry: pool hashmap allocations Signed-off-by: Eliza Weisman --- tracing-subscriber/src/registry/extensions.rs | 38 ++++----- tracing-subscriber/src/registry/sharded.rs | 77 +++++++++++++++---- 2 files changed, 79 insertions(+), 36 deletions(-) diff --git a/tracing-subscriber/src/registry/extensions.rs b/tracing-subscriber/src/registry/extensions.rs index 31e453a70b..e3cdf013d0 100644 --- a/tracing-subscriber/src/registry/extensions.rs +++ b/tracing-subscriber/src/registry/extensions.rs @@ -113,14 +113,16 @@ impl<'a> ExtensionsMut<'a> { pub(crate) struct ExtensionsInner { // If extensions are never used, no need to carry around an empty HashMap. // That's 3 words. Instead, this is only 1 word. - map: Option>, + map: AnyMap, } impl ExtensionsInner { /// Create an empty `Extensions`. #[inline] pub(crate) fn new() -> ExtensionsInner { - ExtensionsInner { map: None } + ExtensionsInner { + map: AnyMap::default(), + } } /// Insert a type into this `Extensions`. @@ -129,7 +131,6 @@ impl ExtensionsInner { /// be returned. pub(crate) fn insert(&mut self, val: T) -> Option { self.map - .get_or_insert_with(|| Box::new(HashMap::default())) .insert(TypeId::of::(), Box::new(val)) .and_then(|boxed| { #[allow(warnings)] @@ -145,16 +146,14 @@ impl ExtensionsInner { /// Get a reference to a type previously inserted on this `Extensions`. pub(crate) fn get(&self) -> Option<&T> { self.map - .as_ref() - .and_then(|map| map.get(&TypeId::of::())) + .get(&TypeId::of::()) .and_then(|boxed| (&**boxed as &(dyn Any + 'static)).downcast_ref()) } /// Get a mutable reference to a type previously inserted on this `Extensions`. pub(crate) fn get_mut(&mut self) -> Option<&mut T> { self.map - .as_mut() - .and_then(|map| map.get_mut(&TypeId::of::())) + .get_mut(&TypeId::of::()) .and_then(|boxed| (&mut **boxed as &mut (dyn Any + 'static)).downcast_mut()) } @@ -162,18 +161,19 @@ impl ExtensionsInner { /// /// If a extension of this type existed, it will be returned. pub(crate) fn remove(&mut self) -> Option { - self.map - .as_mut() - .and_then(|map| map.remove(&TypeId::of::())) - .and_then(|boxed| { - #[allow(warnings)] - { - (boxed as Box) - .downcast() - .ok() - .map(|boxed| *boxed) - } - }) + self.map.remove(&TypeId::of::()).and_then(|boxed| { + #[allow(warnings)] + { + (boxed as Box) + .downcast() + .ok() + .map(|boxed| *boxed) + } + }) + } + + pub(crate) fn clear(&mut self) { + self.map.clear(); } } diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index 20e8bf71c0..0c016569d2 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -1,4 +1,4 @@ -use sharded_slab::{Entry, Slab}; +use sharded_slab::{pool::Ref, Clear, Pool}; use thread_local::ThreadLocal; use super::stack::SpanStack; @@ -47,7 +47,7 @@ use tracing_core::{ #[cfg_attr(docsrs, doc(cfg(feature = "registry")))] #[derive(Debug)] pub struct Registry { - spans: Slab, + spans: Pool, current_spans: ThreadLocal>, } @@ -65,7 +65,7 @@ pub struct Registry { #[cfg_attr(docsrs, doc(cfg(feature = "registry")))] #[derive(Debug)] pub struct Data<'a> { - inner: Entry<'a, DataInner>, + inner: Ref<'a, DataInner>, } #[derive(Debug)] @@ -81,7 +81,7 @@ struct DataInner { impl Default for Registry { fn default() -> Self { Self { - spans: Slab::new(), + spans: Pool::new(), current_spans: ThreadLocal::new(), } } @@ -126,11 +126,7 @@ pub(crate) struct CloseGuard<'a> { } impl Registry { - fn insert(&self, s: DataInner) -> Option { - self.spans.insert(s) - } - - fn get(&self, id: &Id) -> Option> { + fn get(&self, id: &Id) -> Option> { self.spans.get(id_to_idx(id)) } @@ -180,13 +176,13 @@ impl Subscriber for Registry { attrs.parent().map(|id| self.clone_span(id)) }; - let s = DataInner { - metadata: attrs.metadata(), - parent, - ref_count: AtomicUsize::new(1), - extensions: RwLock::new(ExtensionsInner::new()), - }; - let id = self.insert(s).expect("Unable to allocate another span"); + let id = self + .spans + .create_with(|data| { + data.metadata = attrs.metadata(); + data.parent = parent; + }) + .expect("Unable to allocate another span"); idx_to_id(id) } @@ -336,7 +332,7 @@ impl<'a> Drop for CloseGuard<'a> { // `on_close` call. If the span is closing, it's okay to remove the // span. if c == 1 && self.is_closing { - self.registry.spans.remove(id_to_idx(&self.id)); + self.registry.spans.clear(id_to_idx(&self.id)); } }); } @@ -366,6 +362,53 @@ impl<'a> SpanData<'a> for Data<'a> { } } +// === impl DataInner === + +struct NullCallsite; +static NULL_CALLSITE: NullCallsite = NullCallsite; +impl tracing_core::callsite::Callsite for NullCallsite { + fn set_interest(&self, _: tracing_core::subscriber::Interest) { + unreachable!("you somehow managed to register the null callsite?") + } + + fn metadata(&self) -> &Metadata<'_> { + unreachable!("you somehow managed to access the null callsite?") + } +} + +static NULL_METADATA: Metadata<'static> = tracing_core::metadata! { + name: "", + target: "", + level: tracing_core::Level::TRACE, + fields: &[], + callsite: &NULL_CALLSITE, + kind: tracing_core::metadata::Kind::SPAN, +}; + +impl Default for DataInner { + fn default() -> Self { + Self { + metadata: &NULL_METADATA, + parent: None, + ref_count: AtomicUsize::new(0), + extensions: RwLock::new(ExtensionsInner::new()), + } + } +} + +impl Clear for DataInner { + fn clear(&mut self) { + self.parent.take(); + let refs = self.ref_count.get_mut(); + debug_assert_eq!(*refs, 0); + *refs = 1; + self.extensions + .get_mut() + .unwrap_or_else(|l| l.into_inner()) + .clear(); + } +} + #[cfg(test)] mod tests { use super::Registry; From e03f83c8cc44e6cc6aed477113b50b85e9031c43 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 20 Oct 2020 13:32:13 -0700 Subject: [PATCH 05/13] wip --- tracing-subscriber/src/registry/sharded.rs | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index 0c016569d2..592bb746b0 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -181,6 +181,7 @@ impl Subscriber for Registry { .create_with(|data| { data.metadata = attrs.metadata(); data.parent = parent; + *data.ref_count.get_mut() = 1; }) .expect("Unable to allocate another span"); idx_to_id(id) @@ -226,7 +227,10 @@ impl Subscriber for Registry { // calls to `try_close`: we have to ensure that all threads have // dropped their refs to the span before the span is closed. let refs = span.ref_count.fetch_add(1, Ordering::Relaxed); - assert!(refs != 0, "tried to clone a span that already closed"); + assert!( + refs != 0, + "tried to clone a span ({:?}) that already closed" + ); id.clone() } @@ -401,7 +405,6 @@ impl Clear for DataInner { self.parent.take(); let refs = self.ref_count.get_mut(); debug_assert_eq!(*refs, 0); - *refs = 1; self.extensions .get_mut() .unwrap_or_else(|l| l.into_inner()) From bfb18d54b167ba15e24f3619ddac443933536cd3 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 22 Oct 2020 11:04:09 -0700 Subject: [PATCH 06/13] fix close relying on pooled values being dropped Signed-off-by: Eliza Weisman --- tracing-subscriber/src/registry/sharded.rs | 95 ++++++++++------------ 1 file changed, 44 insertions(+), 51 deletions(-) diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index 592bb746b0..09e457ddb1 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -181,7 +181,6 @@ impl Subscriber for Registry { .create_with(|data| { data.metadata = attrs.metadata(); data.parent = parent; - *data.ref_count.get_mut() = 1; }) .expect("Unable to allocate another span"); idx_to_id(id) @@ -284,33 +283,6 @@ impl<'a> LookupSpan<'a> for Registry { // === impl DataInner === -impl Drop for DataInner { - // A span is not considered closed until all of its children have closed. - // Therefore, each span's `DataInner` holds a "reference" to the parent - // span, keeping the parent span open until all its children have closed. - // When we close a span, we must then decrement the parent's ref count - // (potentially, allowing it to close, if this child is the last reference - // to that span). - fn drop(&mut self) { - // We have to actually unpack the option inside the `get_default` - // closure, since it is a `FnMut`, but testing that there _is_ a value - // here lets us avoid the thread-local access if we don't need the - // dispatcher at all. - if self.parent.is_some() { - // Note that --- because `Layered::try_close` works by calling - // `try_close` on the inner subscriber and using the return value to - // determine whether to call the `Layer`'s `on_close` callback --- - // we must call `try_close` on the entire subscriber stack, rather - // than just on the registry. If the registry called `try_close` on - // itself directly, the layers wouldn't see the close notification. - let subscriber = dispatcher::get_default(Dispatch::clone); - if let Some(parent) = self.parent.take() { - let _ = subscriber.try_close(parent); - } - } - } -} - impl<'a> CloseGuard<'a> { pub(crate) fn is_closing(&mut self) { self.is_closing = true; @@ -335,7 +307,7 @@ impl<'a> Drop for CloseGuard<'a> { // If the current close count is 1, this stack frame is the last // `on_close` call. If the span is closing, it's okay to remove the // span. - if c == 1 && self.is_closing { + if dbg!(c) == 1 && dbg!(self.is_closing) { self.registry.spans.clear(id_to_idx(&self.id)); } }); @@ -368,29 +340,28 @@ impl<'a> SpanData<'a> for Data<'a> { // === impl DataInner === -struct NullCallsite; -static NULL_CALLSITE: NullCallsite = NullCallsite; -impl tracing_core::callsite::Callsite for NullCallsite { - fn set_interest(&self, _: tracing_core::subscriber::Interest) { - unreachable!("you somehow managed to register the null callsite?") - } - - fn metadata(&self) -> &Metadata<'_> { - unreachable!("you somehow managed to access the null callsite?") - } -} - -static NULL_METADATA: Metadata<'static> = tracing_core::metadata! { - name: "", - target: "", - level: tracing_core::Level::TRACE, - fields: &[], - callsite: &NULL_CALLSITE, - kind: tracing_core::metadata::Kind::SPAN, -}; - impl Default for DataInner { fn default() -> Self { + struct NullCallsite; + static NULL_CALLSITE: NullCallsite = NullCallsite; + impl tracing_core::callsite::Callsite for NullCallsite { + fn set_interest(&self, _: tracing_core::subscriber::Interest) { + unreachable!("you somehow managed to register the null callsite?") + } + + fn metadata(&self) -> &Metadata<'_> { + unreachable!("you somehow managed to access the null callsite?") + } + } + + static NULL_METADATA: Metadata<'static> = tracing_core::metadata! { + name: "", + target: "", + level: tracing_core::Level::TRACE, + fields: &[], + callsite: &NULL_CALLSITE, + kind: tracing_core::metadata::Kind::SPAN, + }; Self { metadata: &NULL_METADATA, parent: None, @@ -402,9 +373,31 @@ impl Default for DataInner { impl Clear for DataInner { fn clear(&mut self) { - self.parent.take(); + // A span is not considered closed until all of its children have closed. + // Therefore, each span's `DataInner` holds a "reference" to the parent + // span, keeping the parent span open until all its children have closed. + // When we close a span, we must then decrement the parent's ref count + // (potentially, allowing it to close, if this child is the last reference + // to that span). + // We have to actually unpack the option inside the `get_default` + // closure, since it is a `FnMut`, but testing that there _is_ a value + // here lets us avoid the thread-local access if we don't need the + // dispatcher at all. + if self.parent.is_some() { + // Note that --- because `Layered::try_close` works by calling + // `try_close` on the inner subscriber and using the return value to + // determine whether to call the `Layer`'s `on_close` callback --- + // we must call `try_close` on the entire subscriber stack, rather + // than just on the registry. If the registry called `try_close` on + // itself directly, the layers wouldn't see the close notification. + let subscriber = dispatcher::get_default(Dispatch::clone); + if let Some(parent) = self.parent.take() { + let _ = subscriber.try_close(parent); + } + } let refs = self.ref_count.get_mut(); debug_assert_eq!(*refs, 0); + *refs = 1; self.extensions .get_mut() .unwrap_or_else(|l| l.into_inner()) From 157bf70c8ae18f68850d60a968c9084964c055a5 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 22 Oct 2020 11:31:35 -0700 Subject: [PATCH 07/13] gurgle Signed-off-by: Eliza Weisman --- tracing-subscriber/src/registry/sharded.rs | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index 09e457ddb1..bdcdc994c0 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -228,7 +228,8 @@ impl Subscriber for Registry { let refs = span.ref_count.fetch_add(1, Ordering::Relaxed); assert!( refs != 0, - "tried to clone a span ({:?}) that already closed" + "tried to clone a span ({:?}) that already closed", + id ); id.clone() } @@ -307,7 +308,7 @@ impl<'a> Drop for CloseGuard<'a> { // If the current close count is 1, this stack frame is the last // `on_close` call. If the span is closing, it's okay to remove the // span. - if dbg!(c) == 1 && dbg!(self.is_closing) { + if c == 1 && self.is_closing { self.registry.spans.clear(id_to_idx(&self.id)); } }); From 5a7724412c66d70640243a15c4f8eadb96038bc6 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 22 Oct 2020 11:40:44 -0700 Subject: [PATCH 08/13] set ref count to 1 when *creating* spans this fixes an issue where the first time a slot is used, it starts with 0 refs instead of 1 ref, because the ref count is set to 1 in `clear` instead. Signed-off-by: Eliza Weisman --- tracing-subscriber/src/registry/sharded.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index bdcdc994c0..ac0a05e5b2 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -181,6 +181,9 @@ impl Subscriber for Registry { .create_with(|data| { data.metadata = attrs.metadata(); data.parent = parent; + let refs = data.ref_count.get_mut(); + debug_assert_eq!(*refs, 0); + *refs = 1; }) .expect("Unable to allocate another span"); idx_to_id(id) @@ -396,9 +399,6 @@ impl Clear for DataInner { let _ = subscriber.try_close(parent); } } - let refs = self.ref_count.get_mut(); - debug_assert_eq!(*refs, 0); - *refs = 1; self.extensions .get_mut() .unwrap_or_else(|l| l.into_inner()) From 8312b44043e59c39324beee1e04af52feaac0e0c Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 22 Oct 2020 12:15:16 -0700 Subject: [PATCH 09/13] docs, etc Signed-off-by: Eliza Weisman --- tracing-subscriber/src/registry/extensions.rs | 7 ++- tracing-subscriber/src/registry/sharded.rs | 45 ++++++++++++++++--- 2 files changed, 44 insertions(+), 8 deletions(-) diff --git a/tracing-subscriber/src/registry/extensions.rs b/tracing-subscriber/src/registry/extensions.rs index e3cdf013d0..81ecf8aed5 100644 --- a/tracing-subscriber/src/registry/extensions.rs +++ b/tracing-subscriber/src/registry/extensions.rs @@ -111,8 +111,6 @@ impl<'a> ExtensionsMut<'a> { /// data that it is interested in recording and emitting. #[derive(Default)] pub(crate) struct ExtensionsInner { - // If extensions are never used, no need to carry around an empty HashMap. - // That's 3 words. Instead, this is only 1 word. map: AnyMap, } @@ -172,6 +170,11 @@ impl ExtensionsInner { }) } + /// Clear the `ExtensionsInner` in-place, dropping any elements in the map but + /// retaining allocated capacity. + /// + /// This permits the hash map allocation to be pooled by the registry so + /// that future spans will not need to allocate new hashmaps. pub(crate) fn clear(&mut self) { self.map.clear(); } diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index ac0a05e5b2..bffe952840 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -65,14 +65,23 @@ pub struct Registry { #[cfg_attr(docsrs, doc(cfg(feature = "registry")))] #[derive(Debug)] pub struct Data<'a> { + /// Immutable reference to the pooled `DataInner` entry. inner: Ref<'a, DataInner>, } +/// Stored data associated with a span. +/// +/// This type is pooled using `sharded_slab::Pool`; when a span is dropped, the +/// `DataInner` entry at that span's slab index is cleared in place and reused +/// by a future span. Thus, the `Default` and `sharded_slab::Clear` +/// implementations for this type are load-bearing. #[derive(Debug)] struct DataInner { metadata: &'static Metadata<'static>, parent: Option, ref_count: AtomicUsize, + // The span's `Extensions` typemap. Allocations for the `HashMap` backing + // this are pooled and reused in place. pub(crate) extensions: RwLock, } @@ -178,6 +187,10 @@ impl Subscriber for Registry { let id = self .spans + // Check out a `DataInner` entry from the pool for the new span. If + // there are free entries already allocated in the pool, this will + // preferentially reuse one; otherwise, a new `DataInner` is + // allocated and added to the pool. .create_with(|data| { data.metadata = attrs.metadata(); data.parent = parent; @@ -346,18 +359,30 @@ impl<'a> SpanData<'a> for Data<'a> { impl Default for DataInner { fn default() -> Self { + // Since `DataInner` owns a `&'static Callsite` pointer, we need + // something to use as the initial default value for that callsite. + // Since we can't access a `DataInner` until it has had actual span data + // inserted into it, the null metadata will never actually be accessed. struct NullCallsite; - static NULL_CALLSITE: NullCallsite = NullCallsite; impl tracing_core::callsite::Callsite for NullCallsite { - fn set_interest(&self, _: tracing_core::subscriber::Interest) { - unreachable!("you somehow managed to register the null callsite?") + fn set_interest(self: &Self, _: Interest) { + unreachable!( + "/!\\ Tried to register the null callsite /!\\\n \ + This should never have happened and is definitely a bug. \ + A `tracing` bug report would be appreciated." + ) } - fn metadata(&self) -> &Metadata<'_> { - unreachable!("you somehow managed to access the null callsite?") + fn metadata(self: &Self) -> &Metadata<'_> { + unreachable!( + "/!\\ Tried to access the null callsite's metadata /!\\\n \ + This should never have happened and is definitely a bug. \ + A `tracing` bug report would be appreciated." + ) } } + static NULL_CALLSITE: NullCallsite = NullCallsite; static NULL_METADATA: Metadata<'static> = tracing_core::metadata! { name: "", target: "", @@ -366,6 +391,7 @@ impl Default for DataInner { callsite: &NULL_CALLSITE, kind: tracing_core::metadata::Kind::SPAN, }; + Self { metadata: &NULL_METADATA, parent: None, @@ -376,6 +402,7 @@ impl Default for DataInner { } impl Clear for DataInner { + /// Clears the span's data in place, dropping the parent's reference count. fn clear(&mut self) { // A span is not considered closed until all of its children have closed. // Therefore, each span's `DataInner` holds a "reference" to the parent @@ -399,9 +426,15 @@ impl Clear for DataInner { let _ = subscriber.try_close(parent); } } + + // Clear (but do not deallocate!) the pooled `HashMap` for the span's extensions. self.extensions .get_mut() - .unwrap_or_else(|l| l.into_inner()) + .unwrap_or_else(|l| { + // This function can be called in a `Drop` impl, such as while + // panicking, so ignore lock poisoning. + l.into_inner() + }) .clear(); } } From 3b8ff80e4535ce7bab1a99eafd512745d7b964c6 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 22 Oct 2020 12:27:37 -0700 Subject: [PATCH 10/13] add tests that clear really does what i want Signed-off-by: Eliza Weisman --- tracing-subscriber/src/registry/extensions.rs | 79 ++++++++++++++++--- 1 file changed, 68 insertions(+), 11 deletions(-) diff --git a/tracing-subscriber/src/registry/extensions.rs b/tracing-subscriber/src/registry/extensions.rs index 81ecf8aed5..66285e75d9 100644 --- a/tracing-subscriber/src/registry/extensions.rs +++ b/tracing-subscriber/src/registry/extensions.rs @@ -186,22 +186,79 @@ impl fmt::Debug for ExtensionsInner { } } -#[test] -fn test_extensions() { +#[cfg(test)] +mod tests { + use super::*; + #[derive(Debug, PartialEq)] struct MyType(i32); - let mut extensions = ExtensionsInner::new(); + #[test] + fn test_extensions() { + let mut extensions = ExtensionsInner::new(); + + extensions.insert(5i32); + extensions.insert(MyType(10)); + + assert_eq!(extensions.get(), Some(&5i32)); + assert_eq!(extensions.get_mut(), Some(&mut 5i32)); + + assert_eq!(extensions.remove::(), Some(5i32)); + assert!(extensions.get::().is_none()); + + assert_eq!(extensions.get::(), None); + assert_eq!(extensions.get(), Some(&MyType(10))); + } + + #[test] + fn clear_retains_capacity() { + let mut extensions = ExtensionsInner::new(); + extensions.insert(5i32); + extensions.insert(MyType(10)); + extensions.insert(true); + + assert_eq!(extensions.map.len(), 3); + let prev_capacity = extensions.map.capacity(); + extensions.clear(); + + assert_eq!( + extensions.map.len(), + 0, + "after clear(), extensions map should have length 0" + ); + assert_eq!( + extensions.map.capacity(), + prev_capacity, + "after clear(), extensions map should retain prior capacity" + ); + } + + #[test] + fn clear_drops_elements() { + use std::sync::Arc; + struct DropMePlease(Arc<()>); + struct DropMeTooPlease(Arc<()>); - extensions.insert(5i32); - extensions.insert(MyType(10)); + let mut extensions = ExtensionsInner::new(); + let val1 = DropMePlease(Arc::new(())); + let val2 = DropMeTooPlease(Arc::new(())); - assert_eq!(extensions.get(), Some(&5i32)); - assert_eq!(extensions.get_mut(), Some(&mut 5i32)); + let val1_dropped = Arc::downgrade(&val1.0); + let val2_dropped = Arc::downgrade(&val2.0); + extensions.insert(val1); + extensions.insert(val2); - assert_eq!(extensions.remove::(), Some(5i32)); - assert!(extensions.get::().is_none()); + assert!(val1_dropped.upgrade().is_some()); + assert!(val2_dropped.upgrade().is_some()); - assert_eq!(extensions.get::(), None); - assert_eq!(extensions.get(), Some(&MyType(10))); + extensions.clear(); + assert!( + val1_dropped.upgrade().is_none(), + "after clear(), val1 should be dropped" + ); + assert!( + val2_dropped.upgrade().is_none(), + "after clear(), val2 should be dropped" + ); + } } From 2ef8e0cfb121eccb10dca846691b91b239911c72 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 22 Oct 2020 12:28:34 -0700 Subject: [PATCH 11/13] give `Extensions` a slightly nicer debug Signed-off-by: Eliza Weisman --- tracing-subscriber/src/registry/extensions.rs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/tracing-subscriber/src/registry/extensions.rs b/tracing-subscriber/src/registry/extensions.rs index 66285e75d9..cfe87a6459 100644 --- a/tracing-subscriber/src/registry/extensions.rs +++ b/tracing-subscriber/src/registry/extensions.rs @@ -182,7 +182,10 @@ impl ExtensionsInner { impl fmt::Debug for ExtensionsInner { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - f.debug_struct("Extensions").finish() + f.debug_struct("Extensions") + .field("len", &self.map.len()) + .field("capacity", &self.map.capacity()) + .finish() } } From a7d61bac4679b6043ebf9dfad85abe31c18444b6 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 22 Oct 2020 12:32:57 -0700 Subject: [PATCH 12/13] fix missing `RwLock::get_mut` for `parking_lot` Signed-off-by: Eliza Weisman --- tracing-subscriber/src/sync.rs | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/tracing-subscriber/src/sync.rs b/tracing-subscriber/src/sync.rs index e89a8087e8..f09731f50b 100644 --- a/tracing-subscriber/src/sync.rs +++ b/tracing-subscriber/src/sync.rs @@ -33,6 +33,11 @@ mod parking_lot_impl { } } + #[inline] + pub(crate) fn get_mut(&mut self) -> LockResult<&mut T> { + Ok(self.inner.get_mut()) + } + #[inline] pub(crate) fn read<'a>(&'a self) -> LockResult> { Ok(self.inner.read()) From 23ec7e75334a0b73d33c74a22f8da2db64995c7b Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 22 Oct 2020 13:57:48 -0700 Subject: [PATCH 13/13] @manishearth thanks for helping me notice im dumb clippy was INNOCENT Signed-off-by: Eliza Weisman --- tracing-subscriber/src/registry/sharded.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index bffe952840..95a131ffee 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -365,7 +365,7 @@ impl Default for DataInner { // inserted into it, the null metadata will never actually be accessed. struct NullCallsite; impl tracing_core::callsite::Callsite for NullCallsite { - fn set_interest(self: &Self, _: Interest) { + fn set_interest(&self, _: Interest) { unreachable!( "/!\\ Tried to register the null callsite /!\\\n \ This should never have happened and is definitely a bug. \ @@ -373,7 +373,7 @@ impl Default for DataInner { ) } - fn metadata(self: &Self) -> &Metadata<'_> { + fn metadata(&self) -> &Metadata<'_> { unreachable!( "/!\\ Tried to access the null callsite's metadata /!\\\n \ This should never have happened and is definitely a bug. \