From 0a45309d53c9fdf2a7ead5fd2c045ad8f8df9270 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 21 Oct 2020 14:40:16 -0700 Subject: [PATCH 1/6] chore: add enter/exit benchmarks Signed-off-by: Eliza Weisman --- tracing-subscriber/Cargo.toml | 4 ++++ tracing-subscriber/benches/enter.rs | 37 +++++++++++++++++++++++++++++ 2 files changed, 41 insertions(+) create mode 100644 tracing-subscriber/benches/enter.rs diff --git a/tracing-subscriber/Cargo.toml b/tracing-subscriber/Cargo.toml index ca5db4db07..3510bfce5c 100644 --- a/tracing-subscriber/Cargo.toml +++ b/tracing-subscriber/Cargo.toml @@ -83,3 +83,7 @@ harness = false [[bench]] name = "fmt" harness = false + +[[bench]] +name = "enter" +harness = false diff --git a/tracing-subscriber/benches/enter.rs b/tracing-subscriber/benches/enter.rs new file mode 100644 index 0000000000..0e57f109cf --- /dev/null +++ b/tracing-subscriber/benches/enter.rs @@ -0,0 +1,37 @@ +use criterion::{criterion_group, criterion_main, Criterion}; +use tracing_subscriber::prelude::*; + +fn enter(c: &mut Criterion) { + let mut group = c.benchmark_group("enter"); + let _subscriber = tracing_subscriber::fmt() + .with_max_level(tracing::Level::INFO) + .finish() + .set_default(); + group.bench_function("enabled", |b| { + let span = tracing::info_span!("foo"); + b.iter_with_large_drop(|| span.enter()) + }); + group.bench_function("disabled", |b| { + let span = tracing::debug_span!("foo"); + b.iter_with_large_drop(|| span.enter()) + }); +} + +fn enter_exit(c: &mut Criterion) { + let mut group = c.benchmark_group("enter_exit"); + let _subscriber = tracing_subscriber::fmt() + .with_max_level(tracing::Level::INFO) + .finish() + .set_default(); + group.bench_function("enabled", |b| { + let span = tracing::info_span!("foo"); + b.iter(|| span.enter()) + }); + group.bench_function("disabled", |b| { + let span = tracing::debug_span!("foo"); + b.iter(|| span.enter()) + }); +} + +criterion_group!(benches, enter, enter_exit); +criterion_main!(benches); From d10c6e99483c505755f83e912e7be393c69b3ec8 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 21 Oct 2020 14:49:55 -0700 Subject: [PATCH 2/6] don't do actual hashing for span IDs Signed-off-by: Eliza Weisman --- tracing-subscriber/src/registry/stack.rs | 31 +++++++++++++++++++++--- 1 file changed, 28 insertions(+), 3 deletions(-) diff --git a/tracing-subscriber/src/registry/stack.rs b/tracing-subscriber/src/registry/stack.rs index e85cb7c3cf..f4e8e0af1e 100644 --- a/tracing-subscriber/src/registry/stack.rs +++ b/tracing-subscriber/src/registry/stack.rs @@ -1,4 +1,7 @@ -use std::collections::HashSet; +use std::{ + collections::HashSet, + hash::{BuildHasherDefault, Hasher}, +}; pub(crate) use tracing_core::span::Id; @@ -15,16 +18,22 @@ struct ContextId { #[derive(Debug, Default)] pub(crate) struct SpanStack { stack: Vec, - ids: HashSet, + ids: HashSet>, } +#[derive(Default)] +struct IdHasher(u64); + impl SpanStack { pub(crate) fn push(&mut self, id: Id) { let duplicate = self.ids.contains(&id); if !duplicate { self.ids.insert(id.clone()); } - self.stack.push(ContextId { id, duplicate }) + self.stack.push(ContextId { + id, + duplicate: false, + }) } pub(crate) fn pop(&mut self, expected_id: &Id) -> Option { @@ -55,6 +64,22 @@ impl SpanStack { } } +impl Hasher for IdHasher { + fn write(&mut self, _: &[u8]) { + unreachable!("span Id calls write_u64"); + } + + #[inline] + fn write_u64(&mut self, id: u64) { + self.0 = id; + } + + #[inline] + fn finish(&self) -> u64 { + self.0 + } +} + #[cfg(test)] mod tests { use super::{Id, SpanStack}; From 2d4dfaf143b222c049353c144d51c3797d863910 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 21 Oct 2020 14:51:37 -0700 Subject: [PATCH 3/6] linear search may actually be faster? Signed-off-by: Eliza Weisman --- tracing-subscriber/src/registry/stack.rs | 18 ++++++------------ 1 file changed, 6 insertions(+), 12 deletions(-) diff --git a/tracing-subscriber/src/registry/stack.rs b/tracing-subscriber/src/registry/stack.rs index f4e8e0af1e..812bea0c95 100644 --- a/tracing-subscriber/src/registry/stack.rs +++ b/tracing-subscriber/src/registry/stack.rs @@ -26,14 +26,8 @@ struct IdHasher(u64); impl SpanStack { pub(crate) fn push(&mut self, id: Id) { - let duplicate = self.ids.contains(&id); - if !duplicate { - self.ids.insert(id.clone()); - } - self.stack.push(ContextId { - id, - duplicate: false, - }) + let duplicate = self.stack.iter().any(|i| &i.id == &id); + self.stack.push(ContextId { id, duplicate }) } pub(crate) fn pop(&mut self, expected_id: &Id) -> Option { @@ -44,10 +38,10 @@ impl SpanStack { .rev() .find(|(_, ctx_id)| ctx_id.id == *expected_id) { - let ContextId { id, duplicate } = self.stack.remove(idx); - if !duplicate { - self.ids.remove(&id); - } + let ContextId { id, duplicate: _ } = self.stack.remove(idx); + // if !duplicate { + // self.ids.remove(&id); + // } Some(id) } else { None From b83cd36bb8ec3d9c2983bc924a43454b199326c0 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 21 Oct 2020 15:22:53 -0700 Subject: [PATCH 4/6] elide refcount changes when already in the stack Signed-off-by: Eliza Weisman --- tracing-subscriber/src/registry/sharded.rs | 18 ++++---- tracing-subscriber/src/registry/stack.rs | 48 +++++----------------- 2 files changed, 21 insertions(+), 45 deletions(-) diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index c55b8081ce..d26a3e70e3 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -202,19 +202,21 @@ impl Subscriber for Registry { fn event(&self, _: &Event<'_>) {} fn enter(&self, id: &span::Id) { - self.current_spans + if self + .current_spans .get_or_default() .borrow_mut() - .push(self.clone_span(id)); + .push(id.clone()) + { + self.clone_span(id); + } } fn exit(&self, id: &span::Id) { - if let Some(id) = self - .current_spans - .get() - .and_then(|spans| spans.borrow_mut().pop(id)) - { - dispatcher::get_default(|dispatch| dispatch.try_close(id.clone())); + if let Some(spans) = self.current_spans.get() { + if spans.borrow_mut().pop(id) { + dispatcher::get_default(|dispatch| dispatch.try_close(id.clone())); + } } } diff --git a/tracing-subscriber/src/registry/stack.rs b/tracing-subscriber/src/registry/stack.rs index 812bea0c95..e30d15d7a6 100644 --- a/tracing-subscriber/src/registry/stack.rs +++ b/tracing-subscriber/src/registry/stack.rs @@ -1,8 +1,3 @@ -use std::{ - collections::HashSet, - hash::{BuildHasherDefault, Hasher}, -}; - pub(crate) use tracing_core::span::Id; #[derive(Debug)] @@ -18,19 +13,18 @@ struct ContextId { #[derive(Debug, Default)] pub(crate) struct SpanStack { stack: Vec, - ids: HashSet>, } -#[derive(Default)] -struct IdHasher(u64); - impl SpanStack { - pub(crate) fn push(&mut self, id: Id) { + #[inline] + pub(crate) fn push(&mut self, id: Id) -> bool { let duplicate = self.stack.iter().any(|i| &i.id == &id); - self.stack.push(ContextId { id, duplicate }) + self.stack.push(ContextId { id, duplicate }); + !duplicate } - pub(crate) fn pop(&mut self, expected_id: &Id) -> Option { + #[inline] + pub(crate) fn pop(&mut self, expected_id: &Id) -> bool { if let Some((idx, _)) = self .stack .iter() @@ -38,14 +32,10 @@ impl SpanStack { .rev() .find(|(_, ctx_id)| ctx_id.id == *expected_id) { - let ContextId { id, duplicate: _ } = self.stack.remove(idx); - // if !duplicate { - // self.ids.remove(&id); - // } - Some(id) - } else { - None + let ContextId { id: _, duplicate } = self.stack.remove(idx); + return !duplicate; } + false } #[inline] @@ -58,22 +48,6 @@ impl SpanStack { } } -impl Hasher for IdHasher { - fn write(&mut self, _: &[u8]) { - unreachable!("span Id calls write_u64"); - } - - #[inline] - fn write_u64(&mut self, id: u64) { - self.0 = id; - } - - #[inline] - fn finish(&self) -> u64 { - self.0 - } -} - #[cfg(test)] mod tests { use super::{Id, SpanStack}; @@ -84,7 +58,7 @@ mod tests { let id = Id::from_u64(1); stack.push(id.clone()); - assert_eq!(Some(id.clone()), stack.pop(&id)); + assert!(stack.pop(&id)); } #[test] @@ -94,6 +68,6 @@ mod tests { stack.push(Id::from_u64(2)); let id = Id::from_u64(1); - assert_eq!(Some(id.clone()), stack.pop(&id)); + assert!(stack.pop(&id)); } } From 7daf1db998c3515dab58356da27472fc34773e40 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 21 Oct 2020 15:52:48 -0700 Subject: [PATCH 5/6] add bench for deeper stacks Signed-off-by: Eliza Weisman --- tracing-subscriber/benches/enter.rs | 29 ++++++++++++++++++++++++++++- 1 file changed, 28 insertions(+), 1 deletion(-) diff --git a/tracing-subscriber/benches/enter.rs b/tracing-subscriber/benches/enter.rs index 0e57f109cf..49c6e730a8 100644 --- a/tracing-subscriber/benches/enter.rs +++ b/tracing-subscriber/benches/enter.rs @@ -33,5 +33,32 @@ fn enter_exit(c: &mut Criterion) { }); } -criterion_group!(benches, enter, enter_exit); +fn enter_many(c: &mut Criterion) { + let mut group = c.benchmark_group("enter_many"); + let _subscriber = tracing_subscriber::fmt() + .with_max_level(tracing::Level::INFO) + .finish() + .set_default(); + group.bench_function("enabled", |b| { + let span1 = tracing::info_span!("span1"); + let _e1 = span1.enter(); + let span2 = tracing::info_span!("span2"); + let _e2 = span2.enter(); + let span3 = tracing::info_span!("span3"); + let _e3 = span3.enter(); + let span = tracing::info_span!("foo"); + b.iter_with_large_drop(|| span.enter()) + }); + group.bench_function("disabled", |b| { + let span1 = tracing::info_span!("span1"); + let _e1 = span1.enter(); + let span2 = tracing::info_span!("span2"); + let _e2 = span2.enter(); + let span3 = tracing::info_span!("span3"); + let _e3 = span3.enter(); + let span = tracing::debug_span!("foo"); + b.iter_with_large_drop(|| span.enter()) + }); +} +criterion_group!(benches, enter, enter_exit, enter_many); criterion_main!(benches); From 5cf3114f69458985fb354e77e935d1fd64d6fcdb Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 21 Oct 2020 16:26:09 -0700 Subject: [PATCH 6/6] whrhghghghgjgjkg clippy fakldslkflk Signed-off-by: Eliza Weisman --- tracing-subscriber/src/registry/stack.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tracing-subscriber/src/registry/stack.rs b/tracing-subscriber/src/registry/stack.rs index e30d15d7a6..b0b372c13f 100644 --- a/tracing-subscriber/src/registry/stack.rs +++ b/tracing-subscriber/src/registry/stack.rs @@ -18,7 +18,7 @@ pub(crate) struct SpanStack { impl SpanStack { #[inline] pub(crate) fn push(&mut self, id: Id) -> bool { - let duplicate = self.stack.iter().any(|i| &i.id == &id); + let duplicate = self.stack.iter().any(|i| i.id == id); self.stack.push(ContextId { id, duplicate }); !duplicate }