From 994003854363b3c5fd0d7343f93aa1e54edb1ad0 Mon Sep 17 00:00:00 2001 From: Squirrel Date: Sat, 6 Apr 2024 14:54:09 +0100 Subject: [PATCH] Major bump of tracing-subscriber version (#3891) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit I don't think there are any more releases to the 0.2.x versions, so best we're on the 0.3.x release. No change on the benchmarks, fast local time is still just as fast as before: new version bench: ``` fast_local_time time: [30.551 ns 30.595 ns 30.668 ns] ``` old version bench: ``` fast_local_time time: [30.598 ns 30.646 ns 30.723 ns] ``` --------- Co-authored-by: Bastian Köcher --- Cargo.lock | 9 ++--- Cargo.toml | 1 + substrate/client/executor/Cargo.toml | 2 +- substrate/client/tracing/Cargo.toml | 3 +- substrate/client/tracing/benches/bench.rs | 13 ++++--- substrate/client/tracing/src/lib.rs | 2 +- .../tracing/src/logging/event_format.rs | 35 ++++++++++--------- .../tracing/src/logging/fast_local_time.rs | 8 ++--- .../src/logging/layers/prefix_layer.rs | 2 +- substrate/client/tracing/src/logging/mod.rs | 2 +- .../tracing/src/logging/stderr_writer.rs | 2 +- substrate/primitives/tracing/Cargo.toml | 3 +- 12 files changed, 46 insertions(+), 36 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 307a6a5232..19b32dc7aa 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -16200,7 +16200,7 @@ dependencies = [ "substrate-test-runtime", "tempfile", "tracing", - "tracing-subscriber 0.2.25", + "tracing-subscriber 0.3.18", "wat", ] @@ -16961,7 +16961,7 @@ dependencies = [ "thiserror", "tracing", "tracing-log 0.1.3", - "tracing-subscriber 0.2.25", + "tracing-subscriber 0.3.18", ] [[package]] @@ -19262,7 +19262,7 @@ dependencies = [ "parity-scale-codec", "tracing", "tracing-core", - "tracing-subscriber 0.2.25", + "tracing-subscriber 0.3.18", ] [[package]] @@ -20939,7 +20939,6 @@ dependencies = [ "chrono", "lazy_static", "matchers 0.0.1", - "parking_lot 0.11.2", "regex", "serde", "serde_json", @@ -20958,9 +20957,11 @@ version = "0.3.18" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b" dependencies = [ + "chrono", "matchers 0.1.0", "nu-ansi-term", "once_cell", + "parking_lot 0.12.1", "regex", "sharded-slab", "smallvec", diff --git a/Cargo.toml b/Cargo.toml index 067b65ff22..252fe4fe4d 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -558,6 +558,7 @@ serde_json = { version = "1.0.114", default-features = false } serde_yaml = { version = "0.9" } syn = { version = "2.0.53" } thiserror = { version = "1.0.48" } +tracing-subscriber = { version = "0.3.18" } [profile.release] # Polkadot runtime requires unwinding. diff --git a/substrate/client/executor/Cargo.toml b/substrate/client/executor/Cargo.toml index cb0befe987..efe8cc3069 100644 --- a/substrate/client/executor/Cargo.toml +++ b/substrate/client/executor/Cargo.toml @@ -47,7 +47,7 @@ sp-runtime = { path = "../../primitives/runtime" } sp-maybe-compressed-blob = { path = "../../primitives/maybe-compressed-blob" } sc-tracing = { path = "../tracing" } sp-tracing = { path = "../../primitives/tracing" } -tracing-subscriber = "0.2.19" +tracing-subscriber = { workspace = true } paste = "1.0" regex = "1.6.0" criterion = "0.4.0" diff --git a/substrate/client/tracing/Cargo.toml b/substrate/client/tracing/Cargo.toml index 61e6f7d0ba..ba1a7c51ab 100644 --- a/substrate/client/tracing/Cargo.toml +++ b/substrate/client/tracing/Cargo.toml @@ -30,7 +30,7 @@ serde = { workspace = true, default-features = true } thiserror = { workspace = true } tracing = "0.1.29" tracing-log = "0.1.3" -tracing-subscriber = { version = "0.2.25", features = ["parking_lot"] } +tracing-subscriber = { workspace = true, features = ["parking_lot"] } sc-client-api = { path = "../api" } sc-tracing-proc-macro = { path = "proc-macro" } sp-api = { path = "../../primitives/api" } @@ -42,6 +42,7 @@ sp-tracing = { path = "../../primitives/tracing" } [dev-dependencies] criterion = "0.4.0" +tracing-subscriber = { workspace = true, features = ["chrono", "parking_lot"] } [[bench]] name = "bench" diff --git a/substrate/client/tracing/benches/bench.rs b/substrate/client/tracing/benches/bench.rs index 1379023ddf..0f581f6471 100644 --- a/substrate/client/tracing/benches/bench.rs +++ b/substrate/client/tracing/benches/bench.rs @@ -16,7 +16,10 @@ // limitations under the License. use criterion::{criterion_group, criterion_main, Criterion}; -use tracing_subscriber::fmt::time::{ChronoLocal, FormatTime}; +use tracing_subscriber::fmt::{ + format, + time::{ChronoLocal, FormatTime}, +}; fn bench_fast_local_time(c: &mut Criterion) { c.bench_function("fast_local_time", |b| { @@ -24,7 +27,8 @@ fn bench_fast_local_time(c: &mut Criterion) { let t = sc_tracing::logging::FastLocalTime { with_fractional: true }; b.iter(|| { buffer.clear(); - t.format_time(&mut buffer).unwrap(); + let mut writer = format::Writer::new(&mut buffer); + t.format_time(&mut writer).unwrap(); }) }); } @@ -33,10 +37,11 @@ fn bench_fast_local_time(c: &mut Criterion) { fn bench_chrono_local(c: &mut Criterion) { c.bench_function("chrono_local", |b| { let mut buffer = String::new(); - let t = ChronoLocal::with_format("%Y-%m-%d %H:%M:%S%.3f".to_string()); + let t = ChronoLocal::new("%Y-%m-%d %H:%M:%S%.3f".to_string()); b.iter(|| { buffer.clear(); - t.format_time(&mut buffer).unwrap(); + let mut writer: format::Writer<'_> = format::Writer::new(&mut buffer); + t.format_time(&mut writer).unwrap(); }) }); } diff --git a/substrate/client/tracing/src/lib.rs b/substrate/client/tracing/src/lib.rs index 2107943cf6..ba4d1a15cc 100644 --- a/substrate/client/tracing/src/lib.rs +++ b/substrate/client/tracing/src/lib.rs @@ -290,7 +290,7 @@ impl Layer for ProfilingLayer where S: Subscriber + for<'span> LookupSpan<'span>, { - fn new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context) { + fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context) { if let Some(span) = ctx.span(id) { let mut extension = span.extensions_mut(); let parent_id = attrs.parent().cloned().or_else(|| { diff --git a/substrate/client/tracing/src/logging/event_format.rs b/substrate/client/tracing/src/logging/event_format.rs index f4579f006c..235d66cadc 100644 --- a/substrate/client/tracing/src/logging/event_format.rs +++ b/substrate/client/tracing/src/logging/event_format.rs @@ -24,7 +24,7 @@ use tracing::{Event, Level, Subscriber}; use tracing_log::NormalizeEvent; use tracing_subscriber::{ field::RecordFields, - fmt::{time::FormatTime, FmtContext, FormatEvent, FormatFields}, + fmt::{format, time::FormatTime, FmtContext, FormatEvent, FormatFields}, layer::Context, registry::{LookupSpan, SpanRef}, }; @@ -52,20 +52,20 @@ where // NOTE: the following code took inspiration from tracing-subscriber // // https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/format/mod.rs#L449 - pub(crate) fn format_event_custom<'b, S, N>( + pub(crate) fn format_event_custom<'b, 'w, S, N>( &self, ctx: CustomFmtContext<'b, S, N>, - writer: &mut dyn fmt::Write, + writer: format::Writer<'w>, event: &Event, ) -> fmt::Result where S: Subscriber + for<'a> LookupSpan<'a>, N: for<'a> FormatFields<'a> + 'static, { - let writer = &mut ControlCodeSanitizer::new(!self.enable_color, writer); + let mut writer = &mut ControlCodeSanitizer::new(!self.enable_color, writer); let normalized_meta = event.normalized_metadata(); let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata()); - time::write(&self.timer, writer, self.enable_color)?; + time::write(&self.timer, &mut format::Writer::new(&mut writer), self.enable_color)?; if self.display_level { let fmt_level = { FmtLevel::new(meta.level(), self.enable_color) }; @@ -108,7 +108,7 @@ where writer.sanitize = true; } - ctx.format_fields(writer, event)?; + ctx.format_fields(format::Writer::new(writer), event)?; writeln!(writer)?; writer.flush() @@ -127,7 +127,7 @@ where fn format_event( &self, ctx: &FmtContext, - writer: &mut dyn fmt::Write, + mut writer: format::Writer<'_>, event: &Event, ) -> fmt::Result { if self.dup_to_stdout && @@ -136,7 +136,8 @@ where event.metadata().level() == &Level::ERROR) { let mut out = String::new(); - self.format_event_custom(CustomFmtContext::FmtContext(ctx), &mut out, event)?; + let buf_writer = format::Writer::new(&mut out); + self.format_event_custom(CustomFmtContext::FmtContext(ctx), buf_writer, event)?; writer.write_str(&out)?; print!("{}", out); Ok(()) @@ -237,9 +238,13 @@ impl<'a> fmt::Display for FmtThreadName<'a> { mod time { use ansi_term::Style; use std::fmt; - use tracing_subscriber::fmt::time::FormatTime; + use tracing_subscriber::fmt::{format, time::FormatTime}; - pub(crate) fn write(timer: T, writer: &mut dyn fmt::Write, with_ansi: bool) -> fmt::Result + pub(crate) fn write( + timer: T, + writer: &mut format::Writer<'_>, + with_ansi: bool, + ) -> fmt::Result where T: FormatTime, { @@ -269,11 +274,7 @@ where S: Subscriber + for<'lookup> LookupSpan<'lookup>, N: for<'writer> FormatFields<'writer> + 'static, { - fn format_fields( - &self, - writer: &'a mut dyn fmt::Write, - fields: R, - ) -> fmt::Result { + fn format_fields(&self, writer: format::Writer<'_>, fields: R) -> fmt::Result { match self { CustomFmtContext::FmtContext(fmt_ctx) => fmt_ctx.format_fields(writer, fields), CustomFmtContext::ContextWithFormatFields(_ctx, fmt_fields) => @@ -312,7 +313,7 @@ where struct ControlCodeSanitizer<'a> { sanitize: bool, buffer: String, - inner_writer: &'a mut dyn fmt::Write, + inner_writer: format::Writer<'a>, } impl<'a> fmt::Write for ControlCodeSanitizer<'a> { @@ -342,7 +343,7 @@ fn strip_control_codes(input: &str) -> std::borrow::Cow { impl<'a> ControlCodeSanitizer<'a> { /// Creates a new instance. - fn new(sanitize: bool, inner_writer: &'a mut dyn fmt::Write) -> Self { + fn new(sanitize: bool, inner_writer: format::Writer<'a>) -> Self { Self { sanitize, inner_writer, buffer: String::new() } } diff --git a/substrate/client/tracing/src/logging/fast_local_time.rs b/substrate/client/tracing/src/logging/fast_local_time.rs index 7be7bec836..ac4d14d956 100644 --- a/substrate/client/tracing/src/logging/fast_local_time.rs +++ b/substrate/client/tracing/src/logging/fast_local_time.rs @@ -18,7 +18,7 @@ use chrono::{Datelike, Timelike}; use std::{cell::RefCell, fmt::Write, time::SystemTime}; -use tracing_subscriber::fmt::time::FormatTime; +use tracing_subscriber::fmt::{format, time::FormatTime}; /// A structure which, when `Display`d, will print out the current local time. #[derive(Debug, Clone, Copy, Eq, PartialEq, Default)] @@ -76,7 +76,7 @@ thread_local! { } impl FormatTime for FastLocalTime { - fn format_time(&self, w: &mut dyn Write) -> std::fmt::Result { + fn format_time(&self, w: &mut format::Writer<'_>) -> std::fmt::Result { const TIMESTAMP_PARTIAL_LENGTH: usize = "0000-00-00 00:00:00".len(); let elapsed = SystemTime::now() @@ -128,8 +128,8 @@ impl FormatTime for FastLocalTime { } impl std::fmt::Display for FastLocalTime { - fn fmt(&self, w: &mut std::fmt::Formatter) -> std::fmt::Result { - self.format_time(w) + fn fmt(&self, mut w: &mut std::fmt::Formatter) -> std::fmt::Result { + self.format_time(&mut format::Writer::new(&mut w)) } } diff --git a/substrate/client/tracing/src/logging/layers/prefix_layer.rs b/substrate/client/tracing/src/logging/layers/prefix_layer.rs index fc444257bd..f73f06bb53 100644 --- a/substrate/client/tracing/src/logging/layers/prefix_layer.rs +++ b/substrate/client/tracing/src/logging/layers/prefix_layer.rs @@ -32,7 +32,7 @@ impl Layer for PrefixLayer where S: Subscriber + for<'a> LookupSpan<'a>, { - fn new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { + fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) { let span = match ctx.span(id) { Some(span) => span, None => { diff --git a/substrate/client/tracing/src/logging/mod.rs b/substrate/client/tracing/src/logging/mod.rs index 403839390d..8b2ad9b598 100644 --- a/substrate/client/tracing/src/logging/mod.rs +++ b/substrate/client/tracing/src/logging/mod.rs @@ -104,7 +104,7 @@ fn prepare_subscriber( where N: for<'writer> FormatFields<'writer> + 'static, E: FormatEvent + 'static, - W: MakeWriter + 'static, + W: for<'writer> MakeWriter<'writer> + 'static, F: layer::Layer> + Send + Sync + 'static, FmtLayer: layer::Layer + Send + Sync + 'static, { diff --git a/substrate/client/tracing/src/logging/stderr_writer.rs b/substrate/client/tracing/src/logging/stderr_writer.rs index 80df2f1fe7..481efd32e5 100644 --- a/substrate/client/tracing/src/logging/stderr_writer.rs +++ b/substrate/client/tracing/src/logging/stderr_writer.rs @@ -148,7 +148,7 @@ impl Default for MakeStderrWriter { } } -impl tracing_subscriber::fmt::MakeWriter for MakeStderrWriter { +impl tracing_subscriber::fmt::MakeWriter<'_> for MakeStderrWriter { type Writer = StderrWriter; fn make_writer(&self) -> Self::Writer { diff --git a/substrate/primitives/tracing/Cargo.toml b/substrate/primitives/tracing/Cargo.toml index 368f8c096d..ce30302d4b 100644 --- a/substrate/primitives/tracing/Cargo.toml +++ b/substrate/primitives/tracing/Cargo.toml @@ -26,7 +26,8 @@ codec = { version = "3.6.1", package = "parity-scale-codec", default-features = ] } tracing = { version = "0.1.29", default-features = false } tracing-core = { version = "0.1.32", default-features = false } -tracing-subscriber = { version = "0.2.25", optional = true, features = [ +tracing-subscriber = { workspace = true, optional = true, features = [ + "env-filter", "tracing-log", ] }