From b5b26beb33127416fd2bc0f9c6aa01df9e13d3c9 Mon Sep 17 00:00:00 2001 From: Guilherme Souza <19gui94@gmail.com> Date: Sat, 17 Oct 2020 21:52:34 +0200 Subject: [PATCH 01/10] chore: remove duplicated section from tracing/README.md (#1046) In `tracing/README.md`, the section "Supported Rust Versions" was presented twice with the same content. --- tracing/README.md | 14 -------------- 1 file changed, 14 deletions(-) diff --git a/tracing/README.md b/tracing/README.md index 408a475c7a..072a68b3fe 100644 --- a/tracing/README.md +++ b/tracing/README.md @@ -324,20 +324,6 @@ be invoked with the same syntax as the similarly-named macros from the `log` crate. Often, the process of converting a project to use `tracing` can begin with a simple drop-in replacement. -## Supported Rust Versions - -Tracing is built against the latest stable release. The minimum supported -version is 1.42. The current Tracing version is not guaranteed to build on Rust -versions earlier than the minimum supported version. - -Tracing follows the same compiler support policies as the rest of the Tokio -project. The current stable Rust compiler and the three most recent minor -versions before it will always be supported. For example, if the current stable -compiler version is 1.45, the minimum supported version will not be increased -past 1.42, three minor versions prior. Increasing the minimum supported compiler -version is not considered a semver breaking change as long as doing so complies -with this policy. - ## Ecosystem ### Related Crates From cd911e069e4f7761b95a215d409792bcde32e15a Mon Sep 17 00:00:00 2001 From: "dependabot-preview[bot]" <27856297+dependabot-preview[bot]@users.noreply.github.com> Date: Sun, 18 Oct 2020 13:57:44 -0700 Subject: [PATCH 02/10] chore(deps): update pin-project requirement from 0.4 to 1.0 (#1038) Updates the requirements on [pin-project](https://github.com/taiki-e/pin-project) to permit the latest version. - [Release notes](https://github.com/taiki-e/pin-project/releases) - [Changelog](https://github.com/taiki-e/pin-project/blob/master/CHANGELOG.md) - [Commits](https://github.com/taiki-e/pin-project/compare/v0.4.0...v1.0.0) Signed-off-by: dependabot-preview[bot] Co-authored-by: dependabot-preview[bot] <27856297+dependabot-preview[bot]@users.noreply.github.com> --- tracing-futures/Cargo.toml | 2 +- tracing-tower/Cargo.toml | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/tracing-futures/Cargo.toml b/tracing-futures/Cargo.toml index 4f0c603e49..edacd59468 100644 --- a/tracing-futures/Cargo.toml +++ b/tracing-futures/Cargo.toml @@ -28,7 +28,7 @@ std = ["tracing/std"] futures_01 = { package = "futures", version = "0.1", optional = true } futures = { version = "0.3.0", optional = true } futures-task = { version = "0.3", optional = true } -pin-project = { version = "0.4", optional = true } +pin-project = { version = "1.0", optional = true } tracing = { path = "../tracing", version = "0.2", default-features = false } tokio-executor = { version = "0.1", optional = true } tokio = { version = "0.1", optional = true } diff --git a/tracing-tower/Cargo.toml b/tracing-tower/Cargo.toml index 7b0c9e695c..9441c2391f 100644 --- a/tracing-tower/Cargo.toml +++ b/tracing-tower/Cargo.toml @@ -30,7 +30,7 @@ futures = "0.3" tower-service = "0.3" tower-layer = { version = "0.3", optional = true } tower_make = { package = "tower-make", version = "0.3", optional = true } -pin-project = { version = "0.4", optional = true } +pin-project = { version = "1.0", optional = true } http = { version = "0.2", optional = true } [badges] From b3bec865aeee77220403f63ccda909fe43ff7378 Mon Sep 17 00:00:00 2001 From: David Palm Date: Mon, 19 Oct 2020 22:34:44 +0200 Subject: [PATCH 03/10] Feature gate usage of Cow in Metadata --- tracing-core/src/metadata.rs | 22 ++++++++++++++++++++++ 1 file changed, 22 insertions(+) diff --git a/tracing-core/src/metadata.rs b/tracing-core/src/metadata.rs index 816c9cd28d..18a6e69847 100644 --- a/tracing-core/src/metadata.rs +++ b/tracing-core/src/metadata.rs @@ -1,5 +1,6 @@ //! Metadata describing trace data. use super::{callsite, field}; +#[cfg(feature = "alloc")] use alloc::borrow::Cow; use core::{ cmp, fmt, @@ -61,22 +62,34 @@ use core::{ /// [callsite identifier]: super::callsite::Identifier pub struct Metadata<'a> { /// The name of the span described by this metadata. + #[cfg(feature = "alloc")] name: Cow<'a, str>, + #[cfg(not(feature = "alloc"))] + name: &'a str, /// The part of the system that the span that this metadata describes /// occurred in. + #[cfg(feature = "alloc")] target: Cow<'a, str>, + #[cfg(not(feature = "alloc"))] + target: &'a str, /// The level of verbosity of the described span. level: Level, /// The name of the Rust module where the span occurred, or `None` if this /// could not be determined. + #[cfg(feature = "alloc")] module_path: Option>, + #[cfg(not(feature = "alloc"))] + module_path: Option<&'a str>, /// The name of the source code file where the span occurred, or `None` if /// this could not be determined. + #[cfg(feature = "alloc")] file: Option>, + #[cfg(not(feature = "alloc"))] + file: Option<&'a str>, /// The line number in the source code file where the span occurred, or /// `None` if this could not be determined. @@ -132,6 +145,7 @@ impl<'a> Metadata<'a> { fields: field::FieldSet, kind: Kind, ) -> Self { + #[cfg(feature = "alloc")] let file = { if let Some(file) = file { Some(Cow::Borrowed(file)) @@ -139,6 +153,7 @@ impl<'a> Metadata<'a> { None } }; + #[cfg(feature = "alloc")] let module_path = { if let Some(module_path) = module_path { Some(Cow::Borrowed(module_path)) @@ -146,9 +161,16 @@ impl<'a> Metadata<'a> { None } }; + Metadata { + #[cfg(feature = "alloc")] name: Cow::Borrowed(name), + #[cfg(not(feature = "alloc"))] + name, + #[cfg(feature = "alloc")] target: Cow::Borrowed(target), + #[cfg(not(feature = "alloc"))] + target, level, module_path, file, From 19af2924f1bcf9c458264a420adc5b77ae17e93e Mon Sep 17 00:00:00 2001 From: David Date: Mon, 19 Oct 2020 23:39:57 +0200 Subject: [PATCH 04/10] chore: fix tracing-macros::dbg (#1054) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit …and the `factorial` example. --- tracing-macros/Cargo.toml | 5 ++--- tracing-macros/examples/factorial.rs | 4 +--- 2 files changed, 3 insertions(+), 6 deletions(-) diff --git a/tracing-macros/Cargo.toml b/tracing-macros/Cargo.toml index c49adb98c5..82fb8b579e 100644 --- a/tracing-macros/Cargo.toml +++ b/tracing-macros/Cargo.toml @@ -17,11 +17,10 @@ keywords = ["logging", "tracing"] license = "MIT" [dependencies] -tracing = "0.1.18" +tracing = "0.1.20" [dev-dependencies] -tracing-log = "0.1" -env_logger = "0.7" +tracing-subscriber = "0.2" [badges] maintenance = { status = "experimental" } diff --git a/tracing-macros/examples/factorial.rs b/tracing-macros/examples/factorial.rs index c5257f08f8..a089e019e1 100644 --- a/tracing-macros/examples/factorial.rs +++ b/tracing-macros/examples/factorial.rs @@ -12,9 +12,7 @@ fn factorial(n: u32) -> u32 { } fn main() { - env_logger::Builder::new().parse_filters("trace").init(); - #[allow(deprecated)] - let subscriber = tracing_log::TraceLogger::new(); + let subscriber = tracing_subscriber::fmt().finish(); tracing::subscriber::with_default(subscriber, || dbg!(factorial(4))); } From fda189b976dc7bf42f6ef2e7b61e64f0077f7838 Mon Sep 17 00:00:00 2001 From: David Palm Date: Mon, 19 Oct 2020 23:44:51 +0200 Subject: [PATCH 05/10] Add constructor for dynamic data --- tracing-core/src/metadata.rs | 80 ++++++++++++++++++++++++++++++++++++ 1 file changed, 80 insertions(+) diff --git a/tracing-core/src/metadata.rs b/tracing-core/src/metadata.rs index 18a6e69847..1255726840 100644 --- a/tracing-core/src/metadata.rs +++ b/tracing-core/src/metadata.rs @@ -180,6 +180,35 @@ impl<'a> Metadata<'a> { } } + /// Construct new metadata for a span or event, with a name, target, level, field + /// names, and optional source code location using dynamically allocated data. + #[cfg(feature = "alloc")] + #[cfg_attr(docsrs, doc(cfg(any(feature = "std", feature = "alloc"))))] + pub fn from_cow( + name: S, + target: S, + level: Level, + file: Option, + line: Option, + module_path: Option, + fields: field::FieldSet, + kind: Kind, + ) -> Self + where + S: Into>, + { + Metadata { + name: name.into(), + target: target.into(), + level, + module_path: module_path.map(Into::into), + file: file.map(Into::into), + line, + fields, + kind + } + } + /// Returns the names of the fields on the described span or event. pub fn fields(&self) -> &field::FieldSet { &self.fields @@ -837,6 +866,13 @@ impl PartialOrd for LevelFilter { mod tests { use super::*; use core::mem; + #[cfg(feature = "alloc")] + use crate::{ + callsite::{Callsite, Identifier}, + field::FieldSet, + Interest, + }; + #[test] fn level_from_str() { @@ -900,4 +936,48 @@ mod tests { assert_eq!(expected, repr, "repr changed for {:?}", filter) } } + + #[cfg(feature = "alloc")] + #[test] + fn create_metadata_from_dynamic_data() { + struct TestCallsite; + static CS1: TestCallsite = TestCallsite; + + impl Callsite for TestCallsite { + fn set_interest(&self, _interest: Interest) {} + fn metadata(&self) -> &Metadata<'_> { + unimplemented!("not needed for this test") + } + } + let callsite_id = Identifier(&CS1); + let field_set = FieldSet::new(&["one", "fine", "day"], callsite_id); + + // Use `String`s + let _metadata = Metadata::from_cow( + "a name".to_string(), + "a target".to_string(), + Level::TRACE, + None, + None, + None, + field_set, + Kind::EVENT, + ); + + let callsite_id = Identifier(&CS1); + let field_set = FieldSet::new(&["one", "fine", "day"], callsite_id); + // Use `str`s + let _metadata = Metadata::from_cow( + "a name", + "a target", + Level::TRACE, + None, + None, + None, + field_set, + Kind::EVENT, + ); + + // TODO dp: come up with a test that makes sense. + } } From c46c352b035e279edd2e304f5479a1230e1d4362 Mon Sep 17 00:00:00 2001 From: David Palm Date: Mon, 19 Oct 2020 23:54:13 +0200 Subject: [PATCH 06/10] No need for extra lifetime --- tracing-log/src/lib.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tracing-log/src/lib.rs b/tracing-log/src/lib.rs index 90fe0650d5..3c696eea49 100644 --- a/tracing-log/src/lib.rs +++ b/tracing-log/src/lib.rs @@ -213,7 +213,7 @@ pub trait AsLog<'a>: crate::sealed::Sealed { /// The `log` type that this type can be converted into. type Log; /// Returns the `log` equivalent of `self`. - fn as_log<'b: 'a>(&'b self) -> Self::Log; + fn as_log(&'a self) -> Self::Log; } /// Trait implemented for `log` types that can be converted to a `tracing` @@ -229,7 +229,7 @@ impl<'a> crate::sealed::Sealed for Metadata<'a> {} impl<'a> AsLog<'a> for Metadata<'a> { type Log = log::Metadata<'a>; - fn as_log<'b: 'a>(&'b self) -> Self::Log { + fn as_log(&'a self) -> Self::Log { log::Metadata::builder() .level(self.level().as_log()) .target(&self.target()) @@ -354,7 +354,7 @@ impl crate::sealed::Sealed for tracing_core::Level {} impl<'a> AsLog<'a> for tracing_core::Level { type Log = log::Level; - fn as_log<'b: 'a>(&'b self) -> log::Level { + fn as_log(&self) -> log::Level { match *self { tracing_core::Level::ERROR => log::Level::Error, tracing_core::Level::WARN => log::Level::Warn, From 499d3da19c4b36008bcfd934fa0ff3224921f909 Mon Sep 17 00:00:00 2001 From: "dependabot-preview[bot]" <27856297+dependabot-preview[bot]@users.noreply.github.com> Date: Mon, 19 Oct 2020 15:46:18 -0700 Subject: [PATCH 07/10] chore(deps): update env_logger requirement from 0.7 to 0.8 (#1050) Updates the requirements on [env_logger](https://github.com/env-logger-rs/env_logger) to permit the latest version. - [Release notes](https://github.com/env-logger-rs/env_logger/releases) - [Changelog](https://github.com/env-logger-rs/env_logger/blob/master/CHANGELOG.md) - [Commits](https://github.com/env-logger-rs/env_logger/compare/v0.7.0...v0.8.1) Signed-off-by: dependabot-preview[bot] Co-authored-by: dependabot-preview[bot] <27856297+dependabot-preview[bot]@users.noreply.github.com> --- examples/Cargo.toml | 2 +- tracing-log/Cargo.toml | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/examples/Cargo.toml b/examples/Cargo.toml index d3de6c941c..cb2f199119 100644 --- a/examples/Cargo.toml +++ b/examples/Cargo.toml @@ -30,7 +30,7 @@ futures = "0.3" tokio = { version = "0.2.12", features = ["full"] } # env-logger example -env_logger = "0.7" +env_logger = "0.8" # tower examples tower = "0.3" diff --git a/tracing-log/Cargo.toml b/tracing-log/Cargo.toml index b109c114ad..0b5ffa01c0 100644 --- a/tracing-log/Cargo.toml +++ b/tracing-log/Cargo.toml @@ -26,7 +26,7 @@ trace-logger = [] tracing-core = { path = "../tracing-core", version = "0.2"} log = { version = "0.4" } lazy_static = "1.3.0" -env_logger = { version = "0.7", optional = true } +env_logger = { version = "0.8", optional = true } [dev-dependencies] tracing = { path = "../tracing", version = "0.2"} From 280f0bfd1dcfdae4823e8b7e0d784fcfaa7fe637 Mon Sep 17 00:00:00 2001 From: David Palm Date: Tue, 20 Oct 2020 09:30:10 +0200 Subject: [PATCH 08/10] Use impl Into --- tracing-core/src/metadata.rs | 45 ++++++++++-------------------------- 1 file changed, 12 insertions(+), 33 deletions(-) diff --git a/tracing-core/src/metadata.rs b/tracing-core/src/metadata.rs index 1255726840..a8de8bfa1e 100644 --- a/tracing-core/src/metadata.rs +++ b/tracing-core/src/metadata.rs @@ -184,19 +184,16 @@ impl<'a> Metadata<'a> { /// names, and optional source code location using dynamically allocated data. #[cfg(feature = "alloc")] #[cfg_attr(docsrs, doc(cfg(any(feature = "std", feature = "alloc"))))] - pub fn from_cow( - name: S, - target: S, + pub fn from_cow( + name: impl Into>, + target: impl Into>, level: Level, - file: Option, + file: Option>>, line: Option, - module_path: Option, + module_path: Option>>, fields: field::FieldSet, kind: Kind, - ) -> Self - where - S: Into>, - { + ) -> Self { Metadata { name: name.into(), target: target.into(), @@ -205,7 +202,7 @@ impl<'a> Metadata<'a> { file: file.map(Into::into), line, fields, - kind + kind, } } @@ -236,13 +233,13 @@ impl<'a> Metadata<'a> { /// Returns the path to the Rust module where the span occurred, or /// `None` if the module path is unknown. pub fn module_path(&'a self) -> Option<&'a str> { - self.module_path.as_ref().map(|p| p.as_ref() ) + self.module_path.as_ref().map(|p| p.as_ref()) } /// Returns the name of the source code file where the span /// occurred, or `None` if the file is unknown pub fn file(&'a self) -> Option<&'a str> { - self.file.as_ref().map(|f| f.as_ref() ) + self.file.as_ref().map(|f| f.as_ref()) } /// Returns the line number in the source code file where the span @@ -865,14 +862,13 @@ impl PartialOrd for LevelFilter { #[cfg(test)] mod tests { use super::*; - use core::mem; #[cfg(feature = "alloc")] use crate::{ callsite::{Callsite, Identifier}, field::FieldSet, Interest, }; - + use core::mem; #[test] fn level_from_str() { @@ -952,32 +948,15 @@ mod tests { let callsite_id = Identifier(&CS1); let field_set = FieldSet::new(&["one", "fine", "day"], callsite_id); - // Use `String`s let _metadata = Metadata::from_cow( "a name".to_string(), - "a target".to_string(), - Level::TRACE, - None, - None, - None, - field_set, - Kind::EVENT, - ); - - let callsite_id = Identifier(&CS1); - let field_set = FieldSet::new(&["one", "fine", "day"], callsite_id); - // Use `str`s - let _metadata = Metadata::from_cow( - "a name", "a target", Level::TRACE, + Some("a file".to_string()), None, - None, - None, + None::>, field_set, Kind::EVENT, ); - - // TODO dp: come up with a test that makes sense. } } From 67340e911f8362209940836741b38c9295a3d040 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 21 Oct 2020 16:52:25 -0700 Subject: [PATCH 09/10] subscriber: make Registry::enter/exit much faster (#1058) ## Motivation We've tried very hard to make sure that entering and exiting spans is lightweight...in the `tracing-core` core machinery. Unfortunately, we haven't done any benchmarking of how subscriber implementations actually handle enter/exit events. It turns out that in `tracing-subscriber`'s `Registry`, there's actually significant overhead for entering a span: calling `span.enter()` may take as long as 69 ns (on my machine). ## Solution I've written some microbenchmarks for entering and exiting enabled spans using `tracing-subscriber::fmt`, comparing them with the overhead of calling `enter` on an enabled span. Based on this, I've made some performance improvements. These optimizations include: - Removing the `HashSet` that's used for tracking previously entered span IDs, in favor of linear search. Span stacks probably never deep enough for a hashmap to be faster than iterating over a couple of vec indices. - Preallocating the vec used for the span stack to hold at least 64 elements. This means we'll never have a lag spike from reallocating, as I think it'll almost never be deeper than 64 IDs. - Only cloning/dropping an ID's ref count for the _first_ ID in the stack. This makes entering and exiting enabled spans significantly faster: ![image](https://user-images.githubusercontent.com/2796466/96798681-3fc85000-13b6-11eb-9e85-7602d918ee09.png) It would be nice to continue optimizing this, but this might be about the best it gets given the other requirements that we're now making assertions about. Signed-off-by: Eliza Weisman --- tracing-subscriber/Cargo.toml | 4 ++ tracing-subscriber/benches/enter.rs | 64 ++++++++++++++++++++++ tracing-subscriber/src/registry/sharded.rs | 18 +++--- tracing-subscriber/src/registry/stack.rs | 31 ++++------- 4 files changed, 90 insertions(+), 27 deletions(-) create mode 100644 tracing-subscriber/benches/enter.rs diff --git a/tracing-subscriber/Cargo.toml b/tracing-subscriber/Cargo.toml index 9448fff3ba..e79ca3d17a 100644 --- a/tracing-subscriber/Cargo.toml +++ b/tracing-subscriber/Cargo.toml @@ -84,3 +84,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..49c6e730a8 --- /dev/null +++ b/tracing-subscriber/benches/enter.rs @@ -0,0 +1,64 @@ +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()) + }); +} + +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); 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 e85cb7c3cf..b0b372c13f 100644 --- a/tracing-subscriber/src/registry/stack.rs +++ b/tracing-subscriber/src/registry/stack.rs @@ -1,5 +1,3 @@ -use std::collections::HashSet; - pub(crate) use tracing_core::span::Id; #[derive(Debug)] @@ -15,19 +13,18 @@ struct ContextId { #[derive(Debug, Default)] pub(crate) struct SpanStack { stack: Vec, - ids: HashSet, } 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 }) + #[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 }); + !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() @@ -35,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] @@ -65,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] @@ -75,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 0dc8ef2da97f605689fff17f6c38b69e105a5281 Mon Sep 17 00:00:00 2001 From: David Date: Thu, 22 Oct 2020 01:55:42 +0200 Subject: [PATCH 10/10] subscriber: remove TraceLogger (#1052) * Remove TraceLogger The `TraceLogger` implementation is deprecated and this PR removes it completely. --- tracing-log/Cargo.toml | 3 +- tracing-log/src/lib.rs | 23 +- tracing-log/src/trace_logger.rs | 467 -------------------------------- 3 files changed, 4 insertions(+), 489 deletions(-) delete mode 100644 tracing-log/src/trace_logger.rs diff --git a/tracing-log/Cargo.toml b/tracing-log/Cargo.toml index 0b5ffa01c0..e7c7078db9 100644 --- a/tracing-log/Cargo.toml +++ b/tracing-log/Cargo.toml @@ -17,10 +17,9 @@ license = "MIT" readme = "README.md" [features] -default = ["log-tracer", "trace-logger", "std"] +default = ["log-tracer", "std"] std = ["log/std"] log-tracer = [] -trace-logger = [] [dependencies] tracing-core = { path = "../tracing-core", version = "0.2"} diff --git a/tracing-log/src/lib.rs b/tracing-log/src/lib.rs index b7773dd018..4bf352a8a4 100644 --- a/tracing-log/src/lib.rs +++ b/tracing-log/src/lib.rs @@ -59,9 +59,9 @@ //! //! Note that logger implementations that convert log records to trace events //! should not be used with `Subscriber`s that convert trace events _back_ into -//! log records (such as the `TraceLogger`), as doing so will result in the -//! event recursing between the subscriber and the logger forever (or, in real -//! life, probably overflowing the call stack). +//! log records, as doing so will result in the event recursing between the +//! subscriber and the logger forever (or, in real life, probably overflowing +//! the call stack). //! //! If the logging of trace events generated from log records produced by the //! `log` crate is desired, either the `log` crate should not be used to @@ -69,8 +69,6 @@ //! required to avoid infinitely converting between `Event` and `log::Record`. //! //! # Feature Flags -//! * `trace-logger`: enables an experimental `log` subscriber, deprecated since -//! version 0.1.1. //! * `log-tracer`: enables the `LogTracer` type (on by default) //! * `env_logger`: enables the `env_logger` module, with helpers for working //! with the [`env_logger` crate]. @@ -94,7 +92,6 @@ //! [`AsTrace`]: trait.AsTrace.html //! [`AsLog`]: trait.AsLog.html //! [`LogTracer`]: struct.LogTracer.html -//! [`TraceLogger`]: struct.TraceLogger.html //! [`env_logger`]: env_logger/index.html //! [`tracing`]: https://crates.io/crates/tracing //! [`log`]: https://crates.io/crates/log @@ -151,25 +148,11 @@ use tracing_core::{ #[cfg_attr(docsrs, doc(cfg(feature = "log-tracer")))] pub mod log_tracer; -#[cfg(feature = "trace-logger")] -#[cfg_attr(docsrs, doc(cfg(feature = "trace-logger")))] -pub mod trace_logger; - #[cfg(feature = "log-tracer")] #[cfg_attr(docsrs, doc(cfg(feature = "log-tracer")))] #[doc(inline)] pub use self::log_tracer::LogTracer; -#[cfg(feature = "trace-logger")] -#[cfg_attr(docsrs, doc(cfg(feature = "trace-logger")))] -#[deprecated( - since = "0.1.1", - note = "use the `tracing` crate's \"log\" feature flag instead" -)] -#[allow(deprecated)] -#[doc(inline)] -pub use self::trace_logger::TraceLogger; - #[cfg(feature = "env_logger")] #[cfg_attr(docsrs, doc(cfg(feature = "env_logger")))] pub mod env_logger; diff --git a/tracing-log/src/trace_logger.rs b/tracing-log/src/trace_logger.rs deleted file mode 100644 index a2c931c68f..0000000000 --- a/tracing-log/src/trace_logger.rs +++ /dev/null @@ -1,467 +0,0 @@ -//! A `tracing` [`Subscriber`] that uses the [`log`] crate as a backend for -//! formatting `tracing` spans and events. -//! -//! When a [`TraceLogger`] is set as the current subscriber, it will record -//! traces by emitting [`log::Record`]s that can be collected by a logger. -//! -//! **Note**: This API has been deprecated since version 0.1.1. In order to emit -//! `tracing` events as `log` records, the ["log" and "log-always" feature -//! flags][flags] on the `tracing` crate should be used instead. -//! -//! [`log`]: https://docs.rs/log/0.4.8/log/index.html -//! [`Subscriber`]: https://docs.rs/tracing/0.1.7/tracing/subscriber/trait.Subscriber.html -//! [`TraceLogger`]: struct.TraceLogger.html -//! [`log::Record`]: https://docs.rs/log/0.4.8/log/struct.Record.html -//! [flags]: https://docs.rs/tracing/latest/tracing/#crate-feature-flags -#![deprecated( - since = "0.1.1", - note = "use the `tracing` crate's \"log\" feature flag instead" -)] -use crate::AsLog; -use std::{ - cell::RefCell, - collections::HashMap, - fmt::{self, Write}, - sync::{ - atomic::{AtomicUsize, Ordering}, - Mutex, - }, -}; -use tracing_core::{ - field, - span::{self, Id}, - Event, Metadata, Subscriber, -}; - -/// A `tracing` [`Subscriber`] implementation that logs all recorded -/// trace events. -/// -/// **Note**: This API has been deprecated since version 0.1.1. In order to emit -/// `tracing` events as `log` records, the ["log" and "log-always" feature -/// flags][flags] on the `tracing` crate should be used instead. -/// -/// [`Subscriber`]: https://docs.rs/tracing/0.1.7/tracing/subscriber/trait.Subscriber.html -/// [flags]: https://docs.rs/tracing/latest/tracing/#crate-feature-flags -pub struct TraceLogger { - settings: Builder, - spans: Mutex>, - next_id: AtomicUsize, -} - -thread_local! { - static CURRENT: RefCell> = RefCell::new(Vec::new()); -} -/// Configures and constructs a [`TraceLogger`]. -/// -/// [`TraceLogger`]: struct.TraceLogger.html -#[derive(Debug)] -pub struct Builder { - log_span_closes: bool, - log_enters: bool, - log_exits: bool, - log_ids: bool, - parent_fields: bool, - log_parent: bool, -} - -// ===== impl TraceLogger ===== - -impl TraceLogger { - /// Returns a new `TraceLogger` with the default configuration. - pub fn new() -> Self { - Self::builder().finish() - } - - /// Returns a `Builder` for configuring a `TraceLogger`. - pub fn builder() -> Builder { - Default::default() - } - - fn from_builder(settings: Builder) -> Self { - Self { - settings, - ..Default::default() - } - } - - fn next_id(&self) -> Id { - Id::from_u64(self.next_id.fetch_add(1, Ordering::SeqCst) as u64) - } -} - -// ===== impl Builder ===== - -impl Builder { - /// Configures whether or not the [`TraceLogger`] being constructed will log - /// when a span closes. - /// - /// [`TraceLogger`]: struct.TraceLogger.html - pub fn with_span_closes(self, log_span_closes: bool) -> Self { - Self { - log_span_closes, - ..self - } - } - - /// Configures whether or not the [`TraceLogger`] being constructed will - /// include the fields of parent spans when formatting events. - /// - /// [`TraceLogger`]: struct.TraceLogger.html - pub fn with_parent_fields(self, parent_fields: bool) -> Self { - Self { - parent_fields, - ..self - } - } - - /// Configures whether or not the [`TraceLogger`] being constructed will log - /// when a span is entered. - /// - /// If this is set to false, fields from the current span will still be - /// recorded as context, but the actual entry will not create a log record. - /// - /// [`TraceLogger`]: struct.TraceLogger.html - pub fn with_span_entry(self, log_enters: bool) -> Self { - Self { log_enters, ..self } - } - - /// Configures whether or not the [`TraceLogger`] being constructed will log - /// when a span is exited. - /// - /// [`TraceLogger`]: struct.TraceLogger.html - pub fn with_span_exits(self, log_exits: bool) -> Self { - Self { log_exits, ..self } - } - - /// Configures whether or not the [`TraceLogger`] being constructed will - /// include span IDs when formatting log output. - /// - /// [`TraceLogger`]: struct.TraceLogger.html - pub fn with_ids(self, log_ids: bool) -> Self { - Self { log_ids, ..self } - } - - /// Configures whether or not the [`TraceLogger`] being constructed will - /// include the names of parent spans as context when formatting events. - /// - /// [`TraceLogger`]: struct.TraceLogger.html - pub fn with_parent_names(self, log_parent: bool) -> Self { - Self { log_parent, ..self } - } - - /// Complete the builder, returning a configured [`TraceLogger`]. - /// - /// [`TraceLogger`]: struct.TraceLogger.html - pub fn finish(self) -> TraceLogger { - TraceLogger::from_builder(self) - } -} - -impl Default for Builder { - fn default() -> Self { - Builder { - log_span_closes: false, - parent_fields: true, - log_exits: false, - log_ids: false, - log_parent: true, - log_enters: false, - } - } -} - -impl Default for TraceLogger { - fn default() -> Self { - TraceLogger { - settings: Default::default(), - spans: Default::default(), - next_id: AtomicUsize::new(1), - } - } -} - -#[derive(Debug)] -struct SpanLineBuilder { - parent: Option, - ref_count: usize, - fields: String, - file: Option, - line: Option, - module_path: Option, - target: String, - level: log::Level, - name: &'static str, -} - -impl SpanLineBuilder { - fn new(parent: Option, meta: &Metadata<'_>, fields: String) -> Self { - Self { - parent, - ref_count: 1, - fields, - file: meta.file().map(String::from), - line: meta.line(), - module_path: meta.module_path().map(String::from), - target: String::from(meta.target()), - level: meta.level().as_log(), - name: meta.name(), - } - } - - fn log_meta(&self) -> log::Metadata<'_> { - log::MetadataBuilder::new() - .level(self.level) - .target(self.target.as_ref()) - .build() - } - - fn finish(self) { - let log_meta = self.log_meta(); - let logger = log::logger(); - if logger.enabled(&log_meta) { - logger.log( - &log::Record::builder() - .metadata(log_meta) - .target(self.target.as_ref()) - .module_path(self.module_path.as_ref().map(String::as_ref)) - .file(self.file.as_ref().map(String::as_ref)) - .line(self.line) - .args(format_args!("close {}; {}", self.name, self.fields)) - .build(), - ); - } - } -} - -impl field::Visit for SpanLineBuilder { - fn record_debug(&mut self, field: &field::Field, value: &dyn fmt::Debug) { - write!(self.fields, " {}={:?};", field.name(), value) - .expect("write to string should never fail") - } -} - -impl Subscriber for TraceLogger { - fn enabled(&self, metadata: &Metadata<'_>) -> bool { - log::logger().enabled(&metadata.as_log()) - } - - fn new_span(&self, attrs: &span::Attributes<'_>) -> Id { - let id = self.next_id(); - let mut spans = self.spans.lock().unwrap(); - let mut fields = String::new(); - let parent = self.current_id(); - if self.settings.parent_fields { - let mut next_parent = parent.as_ref(); - while let Some(ref parent) = next_parent.and_then(|p| spans.get(&p)) { - write!(&mut fields, "{}", parent.fields).expect("write to string cannot fail"); - next_parent = parent.parent.as_ref(); - } - } - let mut span = SpanLineBuilder::new(parent, attrs.metadata(), fields); - attrs.record(&mut span); - spans.insert(id.clone(), span); - id - } - - fn record(&self, span: &Id, values: &span::Record<'_>) { - let mut spans = self.spans.lock().unwrap(); - if let Some(span) = spans.get_mut(span) { - values.record(span); - } - } - - fn record_follows_from(&self, span: &Id, follows: &Id) { - // TODO: this should eventually track the relationship? - log::logger().log( - &log::Record::builder() - .level(log::Level::Trace) - .args(format_args!("span {:?} follows_from={:?};", span, follows)) - .build(), - ); - } - - fn enter(&self, id: &Id) { - let _ = CURRENT.try_with(|current| { - let mut current = current.borrow_mut(); - if current.contains(id) { - // Ignore duplicate enters. - return; - } - current.push(id.clone()); - }); - let spans = self.spans.lock().unwrap(); - if self.settings.log_enters { - if let Some(span) = spans.get(id) { - let log_meta = span.log_meta(); - let logger = log::logger(); - if logger.enabled(&log_meta) { - let current_id = self.current_id(); - let current_fields = current_id - .as_ref() - .and_then(|id| spans.get(&id)) - .map(|span| span.fields.as_ref()) - .unwrap_or(""); - if self.settings.log_ids { - logger.log( - &log::Record::builder() - .metadata(log_meta) - .target(span.target.as_ref()) - .module_path(span.module_path.as_ref().map(String::as_ref)) - .file(span.file.as_ref().map(String::as_ref)) - .line(span.line) - .args(format_args!( - "enter {}; in={:?}; {}", - span.name, current_id, current_fields - )) - .build(), - ); - } else { - logger.log( - &log::Record::builder() - .metadata(log_meta) - .target(span.target.as_ref()) - .module_path(span.module_path.as_ref().map(String::as_ref)) - .file(span.file.as_ref().map(String::as_ref)) - .line(span.line) - .args(format_args!("enter {}; {}", span.name, current_fields)) - .build(), - ); - } - } - } - } - } - - fn exit(&self, id: &Id) { - let _ = CURRENT.try_with(|current| { - let mut current = current.borrow_mut(); - if current.last() == Some(id) { - current.pop() - } else { - None - } - }); - if self.settings.log_exits { - let spans = self.spans.lock().unwrap(); - if let Some(span) = spans.get(id) { - let log_meta = span.log_meta(); - let logger = log::logger(); - if logger.enabled(&log_meta) { - logger.log( - &log::Record::builder() - .metadata(log_meta) - .target(span.target.as_ref()) - .module_path(span.module_path.as_ref().map(String::as_ref)) - .file(span.file.as_ref().map(String::as_ref)) - .line(span.line) - .args(format_args!("exit {}", span.name)) - .build(), - ); - } - } - } - } - - fn event(&self, event: &Event<'_>) { - let meta = event.metadata(); - let log_meta = meta.as_log(); - let logger = log::logger(); - if logger.enabled(&log_meta) { - let spans = self.spans.lock().unwrap(); - let current = self.current_id().and_then(|id| spans.get(&id)); - let (current_fields, parent) = current - .map(|span| { - let fields = span.fields.as_ref(); - let parent = if self.settings.log_parent { - Some(span.name) - } else { - None - }; - (fields, parent) - }) - .unwrap_or(("", None)); - logger.log( - &log::Record::builder() - .metadata(log_meta) - .target(meta.target()) - .module_path(meta.module_path().as_ref().cloned()) - .file(meta.file().as_ref().cloned()) - .line(meta.line()) - .args(format_args!( - "{}{}{}{}", - parent.unwrap_or(""), - if parent.is_some() { ": " } else { "" }, - LogEvent(event), - current_fields, - )) - .build(), - ); - } - } - - fn clone_span(&self, id: &Id) -> Id { - let mut spans = self.spans.lock().unwrap(); - if let Some(span) = spans.get_mut(id) { - span.ref_count += 1; - } - id.clone() - } - - fn try_close(&self, id: Id) -> bool { - let mut spans = self.spans.lock().unwrap(); - if spans.contains_key(&id) { - if spans.get(&id).unwrap().ref_count == 1 { - let span = spans.remove(&id).unwrap(); - if self.settings.log_span_closes { - span.finish(); - } - return true; - } else { - spans.get_mut(&id).unwrap().ref_count -= 1; - } - } - false - } -} - -impl TraceLogger { - #[inline] - fn current_id(&self) -> Option { - CURRENT - .try_with(|current| current.borrow().last().map(|span| self.clone_span(span))) - .ok()? - } -} - -struct LogEvent<'a>(&'a Event<'a>); - -impl<'a> fmt::Display for LogEvent<'a> { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - let mut has_logged = false; - let mut format_fields = |field: &field::Field, value: &dyn fmt::Debug| { - let name = field.name(); - let leading = if has_logged { " " } else { "" }; - // TODO: handle fmt error? - let _ = if name == "message" { - write!(f, "{}{:?};", leading, value) - } else { - write!(f, "{}{}={:?};", leading, name, value) - }; - has_logged = true; - }; - - self.0.record(&mut format_fields); - Ok(()) - } -} - -impl fmt::Debug for TraceLogger { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - f.debug_struct("TraceLogger") - .field("settings", &self.settings) - .field("spans", &self.spans) - .field("current", &self.current_id()) - .field("next_id", &self.next_id) - .finish() - } -}