diff --git a/Cargo.lock b/Cargo.lock index 377059ba220c0..397cc10e623d3 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1,5 +1,7 @@ # This file is automatically @generated by Cargo. # It is not intended for manual editing. +version = 3 + [[package]] name = "Inflector" version = "0.11.4" @@ -10348,9 +10350,9 @@ dependencies = [ [[package]] name = "tracing-subscriber" -version = "0.2.16" +version = "0.2.18" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "8ab8966ac3ca27126141f7999361cc97dd6fb4b71da04c02044fa9045d98bb96" +checksum = "aa5553bf0883ba7c9cbe493b085c29926bd41b66afc31ff72cf17ff4fb60dcd5" dependencies = [ "ansi_term 0.12.1", "chrono", diff --git a/client/executor/Cargo.toml b/client/executor/Cargo.toml index f9ebfd9bd5de5..7cb2e12fd3913 100644 --- a/client/executor/Cargo.toml +++ b/client/executor/Cargo.toml @@ -48,7 +48,7 @@ sp-runtime = { version = "3.0.0", path = "../../primitives/runtime" } sp-tracing = { version = "3.0.0", path = "../../primitives/tracing" } sc-tracing = { version = "3.0.0", path = "../tracing" } tracing = "0.1.25" -tracing-subscriber = "0.2.15" +tracing-subscriber = "0.2.18" paste = "1.0" [features] diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index a455cd8ab95c3..1121b922494c9 100644 --- a/client/tracing/Cargo.toml +++ b/client/tracing/Cargo.toml @@ -26,8 +26,8 @@ serde = "1.0.101" serde_json = "1.0.41" thiserror = "1.0.21" tracing = "0.1.25" -tracing-log = "0.1.1" -tracing-subscriber = "0.2.15" +tracing-log = "0.1.2" +tracing-subscriber = "0.2.18" sp-tracing = { version = "3.0.0", path = "../../primitives/tracing" } sp-rpc = { version = "3.0.0", path = "../../primitives/rpc" } sp-block-builder = { version = "3.0.0", path = "../../primitives/block-builder" } diff --git a/client/tracing/src/block/mod.rs b/client/tracing/src/block/mod.rs index 70e74b1d82788..bc5342c859980 100644 --- a/client/tracing/src/block/mod.rs +++ b/client/tracing/src/block/mod.rs @@ -20,7 +20,6 @@ use std::{collections::HashMap, sync::{Arc, atomic::{AtomicU64, Ordering}}, time use parking_lot::Mutex; use tracing::{Dispatch, dispatcher, Subscriber, Level, span::{Attributes, Record, Id}}; -use tracing_subscriber::CurrentSpan; use sc_client_api::BlockBackend; use sc_rpc_server::MAX_PAYLOAD; @@ -75,7 +74,6 @@ pub enum Error { struct BlockSubscriber { targets: Vec<(String, Level)>, next_id: AtomicU64, - current_span: CurrentSpan, spans: Mutex>, events: Mutex>, } @@ -93,7 +91,6 @@ impl BlockSubscriber { BlockSubscriber { targets, next_id, - current_span: CurrentSpan::default(), spans: Mutex::new(HashMap::new()), events: Mutex::new(Vec::new()), } @@ -117,8 +114,7 @@ impl Subscriber for BlockSubscriber { let id = Id::from_u64(self.next_id.fetch_add(1, Ordering::Relaxed)); let mut values = Values::default(); attrs.record(&mut values); - let parent_id = attrs.parent().cloned() - .or_else(|| self.current_span.id()); + let parent_id = attrs.parent().cloned(); let span = SpanDatum { id: id.clone(), parent_id, @@ -150,8 +146,7 @@ impl Subscriber for BlockSubscriber { fn event(&self, event: &tracing::Event<'_>) { let mut values = crate::Values::default(); event.record(&mut values); - let parent_id = event.parent().cloned() - .or_else(|| self.current_span.id()); + let parent_id = event.parent().cloned(); let trace_event = TraceEvent { name: event.metadata().name().to_owned(), target: event.metadata().target().to_owned(), @@ -162,14 +157,10 @@ impl Subscriber for BlockSubscriber { self.events.lock().push(trace_event); } - fn enter(&self, id: &Id) { - self.current_span.enter(id.clone()); + fn enter(&self, _id: &Id) { } - fn exit(&self, span: &Id) { - if self.spans.lock().contains_key(span) { - self.current_span.exit(); - } + fn exit(&self, _span: &Id) { } } diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 72992a9ab05fa..9f02bb96e4f77 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -28,26 +28,23 @@ #![warn(missing_docs)] -pub mod logging; pub mod block; +pub mod logging; use rustc_hash::FxHashMap; +use serde::ser::{Serialize, SerializeMap, Serializer}; +use sp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER}; use std::fmt; use std::time::{Duration, Instant}; -use parking_lot::Mutex; -use serde::ser::{Serialize, Serializer, SerializeMap}; use tracing::{ event::Event, - field::{Visit, Field}, - Level, + field::{Field, Visit}, span::{Attributes, Id, Record}, subscriber::Subscriber, + Level, }; -use tracing_subscriber::{ - CurrentSpan, - layer::{Layer, Context}, -}; -use sp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER}; +use tracing_subscriber::layer::{Context, Layer}; +use tracing_subscriber::registry::LookupSpan; #[doc(hidden)] pub use tracing; @@ -58,8 +55,6 @@ const ZERO_DURATION: Duration = Duration::from_nanos(0); pub struct ProfilingLayer { targets: Vec<(String, Level)>, trace_handler: Box, - span_data: Mutex>, - current_span: CurrentSpan, } /// Used to configure how to receive the metrics @@ -142,10 +137,10 @@ impl Values { /// Checks if all individual collections are empty pub fn is_empty(&self) -> bool { - self.bool_values.is_empty() && - self.i64_values.is_empty() && - self.u64_values.is_empty() && - self.string_values.is_empty() + self.bool_values.is_empty() + && self.i64_values.is_empty() + && self.u64_values.is_empty() + && self.string_values.is_empty() } } @@ -225,8 +220,6 @@ impl ProfilingLayer { Self { targets, trace_handler, - span_data: Mutex::new(FxHashMap::default()), - current_span: Default::default(), } } @@ -257,32 +250,56 @@ fn parse_target(s: &str) -> (String, Level) { } } -impl Layer for ProfilingLayer { - fn new_span(&self, attrs: &Attributes<'_>, id: &Id, _ctx: Context) { - let mut values = Values::default(); - attrs.record(&mut values); - let span_datum = SpanDatum { - id: id.clone(), - parent_id: attrs.parent().cloned().or_else(|| self.current_span.id()), - name: attrs.metadata().name().to_owned(), - target: attrs.metadata().target().to_owned(), - level: *attrs.metadata().level(), - line: attrs.metadata().line().unwrap_or(0), - start_time: Instant::now(), - overall_time: ZERO_DURATION, - values, - }; - self.span_data.lock().insert(id.clone(), span_datum); +impl Layer for ProfilingLayer +where + S: Subscriber + for<'span> LookupSpan<'span>, +{ + fn 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(|| { + if attrs.is_contextual() { + ctx.lookup_current().map(|span| span.id()) + } else { + None + } + }); + + let mut values = Values::default(); + attrs.record(&mut values); + let span_datum = SpanDatum { + id: id.clone(), + parent_id, + name: attrs.metadata().name().to_owned(), + target: attrs.metadata().target().to_owned(), + level: *attrs.metadata().level(), + line: attrs.metadata().line().unwrap_or(0), + start_time: Instant::now(), + overall_time: ZERO_DURATION, + values, + }; + extension.insert(span_datum); + } } - fn on_record(&self, span: &Id, values: &Record<'_>, _ctx: Context) { - let mut span_data = self.span_data.lock(); - if let Some(s) = span_data.get_mut(span) { - values.record(&mut s.values); + fn on_record(&self, id: &Id, values: &Record<'_>, ctx: Context) { + if let Some(span) = ctx.span(id) { + let mut extensions = span.extensions_mut(); + if let Some(s) = extensions.get_mut::() { + values.record(&mut s.values); + } } } - fn on_event(&self, event: &Event<'_>, _ctx: Context) { + fn on_event(&self, event: &Event<'_>, ctx: Context) { + let parent_id = event.parent().cloned().or_else(|| { + if event.is_contextual() { + ctx.lookup_current().map(|span| span.id()) + } else { + None + } + }); + let mut values = Values::default(); event.record(&mut values); let trace_event = TraceEvent { @@ -290,46 +307,46 @@ impl Layer for ProfilingLayer { target: event.metadata().target().to_owned(), level: *event.metadata().level(), values, - parent_id: event.parent().cloned().or_else(|| self.current_span.id()), + parent_id, }; self.trace_handler.handle_event(trace_event); } - fn on_enter(&self, span: &Id, _ctx: Context) { - self.current_span.enter(span.clone()); - let mut span_data = self.span_data.lock(); - let start_time = Instant::now(); - if let Some(mut s) = span_data.get_mut(&span) { - s.start_time = start_time; + fn on_enter(&self, span: &Id, ctx: Context) { + if let Some(span) = ctx.span(span) { + let mut extensions = span.extensions_mut(); + if let Some(s) = extensions.get_mut::() { + let start_time = Instant::now(); + s.start_time = start_time; + } } } - fn on_exit(&self, span: &Id, _ctx: Context) { - let end_time = Instant::now(); - let span_datum = { - let mut span_data = self.span_data.lock(); - span_data.remove(&span) - }; - - if let Some(mut span_datum) = span_datum { - // If `span_datum` is `None` we don't exit (we'd be exiting the parent span) - self.current_span.exit(); - span_datum.overall_time += end_time - span_datum.start_time; - if span_datum.name == WASM_TRACE_IDENTIFIER { - span_datum.values.bool_values.insert("wasm".to_owned(), true); - if let Some(n) = span_datum.values.string_values.remove(WASM_NAME_KEY) { - span_datum.name = n; - } - if let Some(t) = span_datum.values.string_values.remove(WASM_TARGET_KEY) { - span_datum.target = t; - } - if self.check_target(&span_datum.target, &span_datum.level) { + fn on_exit(&self, span: &Id, ctx: Context) { + if let Some(span) = ctx.span(span) { + let end_time = Instant::now(); + let mut extensions = span.extensions_mut(); + if let Some(mut span_datum) = extensions.remove::() { + span_datum.overall_time += end_time - span_datum.start_time; + if span_datum.name == WASM_TRACE_IDENTIFIER { + span_datum + .values + .bool_values + .insert("wasm".to_owned(), true); + if let Some(n) = span_datum.values.string_values.remove(WASM_NAME_KEY) { + span_datum.name = n; + } + if let Some(t) = span_datum.values.string_values.remove(WASM_TARGET_KEY) { + span_datum.target = t; + } + if self.check_target(&span_datum.target, &span_datum.level) { + self.trace_handler.handle_span(span_datum); + } + } else { self.trace_handler.handle_span(span_datum); } - } else { - self.trace_handler.handle_span(span_datum); } - }; + } } fn on_close(&self, _span: Id, _ctx: Context) {} @@ -414,6 +431,7 @@ impl From for sp_rpc::tracing::Span { #[cfg(test)] mod tests { use super::*; + use parking_lot::Mutex; use std::sync::Arc; use tracing_subscriber::layer::SubscriberExt; diff --git a/client/tracing/src/logging/mod.rs b/client/tracing/src/logging/mod.rs index 49bcfc4abfb4d..d9fc95bd0d4dc 100644 --- a/client/tracing/src/logging/mod.rs +++ b/client/tracing/src/logging/mod.rs @@ -395,7 +395,7 @@ mod tests { #[test] fn prefix_in_log_lines() { let re = regex::Regex::new(&format!( - r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}} \[{}\] {}$", + r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}} \[{}\] {}$", EXPECTED_NODE_NAME, EXPECTED_LOG_MESSAGE, )) .unwrap(); @@ -445,7 +445,7 @@ mod tests { #[test] fn do_not_write_with_colors_on_tty() { let re = regex::Regex::new(&format!( - r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}} {}$", + r"^\d{{4}}-\d{{2}}-\d{{2}} \d{{2}}:\d{{2}}:\d{{2}} {}$", EXPECTED_LOG_MESSAGE, )) .unwrap(); diff --git a/primitives/tracing/Cargo.toml b/primitives/tracing/Cargo.toml index 6c4d70b109cd7..2c4b7dc12c744 100644 --- a/primitives/tracing/Cargo.toml +++ b/primitives/tracing/Cargo.toml @@ -23,7 +23,7 @@ codec = { version = "2.0.0", package = "parity-scale-codec", default-features = tracing = { version = "0.1.25", default-features = false } tracing-core = { version = "0.1.17", default-features = false } log = { version = "0.4.8", optional = true } -tracing-subscriber = { version = "0.2.15", optional = true, features = ["tracing-log"] } +tracing-subscriber = { version = "0.2.18", optional = true, features = ["tracing-log"] } parking_lot = { version = "0.10.0", optional = true } erased-serde = { version = "0.3.9", optional = true } serde = { version = "1.0.101", optional = true }