diff --git a/Cargo.lock b/Cargo.lock index c82803d7bc9be..97b9ddca3e3d9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3222,6 +3222,15 @@ dependencies = [ "libc", ] +[[package]] +name = "matchers" +version = "0.0.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f099785f7595cc4b4553a174ce30dd7589ef93391ff414dbb67f62392b9e0ce1" +dependencies = [ + "regex-automata", +] + [[package]] name = "matches" version = "0.1.8" @@ -5818,6 +5827,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ae1ded71d66a4a97f5e961fd0cb25a5f366a42a41570d16a763a69c092c26ae4" dependencies = [ "byteorder", + "regex-syntax", ] [[package]] @@ -7090,7 +7100,7 @@ dependencies = [ "slog", "sp-tracing", "tracing", - "tracing-core", + "tracing-subscriber", ] [[package]] @@ -7375,6 +7385,15 @@ dependencies = [ "opaque-debug 0.2.3", ] +[[package]] +name = "sharded-slab" +version = "0.0.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "06d5a3f5166fb5b42a5439f2eee8b9de149e235961e3eb21c5808fc3ea17ff3e" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "0.1.1" @@ -9144,9 +9163,9 @@ checksum = "e987b6bf443f4b5b3b6f38704195592cca41c5bb7aedd3c3693c7081f8289860" [[package]] name = "tracing" -version = "0.1.14" +version = "0.1.18" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a7c6b59d116d218cb2d990eb06b77b64043e0268ef7323aae63d8b30ae462923" +checksum = "f0aae59226cf195d8e74d4b34beae1859257efb4e5fed3f147d2dc2c7d372178" dependencies = [ "cfg-if", "tracing-attributes", @@ -9155,9 +9174,9 @@ dependencies = [ [[package]] name = "tracing-attributes" -version = "0.1.8" +version = "0.1.9" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "99bbad0de3fd923c9c3232ead88510b783e5a4d16a6154adffa3d53308de984c" +checksum = "f0693bf8d6f2bf22c690fc61a9d21ac69efdbb894a17ed596b9af0f01e64b84b" dependencies = [ "proc-macro2", "quote", @@ -9166,11 +9185,52 @@ dependencies = [ [[package]] name = "tracing-core" -version = "0.1.10" +version = "0.1.12" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b2734b5a028fa697686f16c6d18c2c6a3c7e41513f9a213abb6754c4acb3c8d7" +dependencies = [ + "lazy_static", +] + +[[package]] +name = "tracing-log" +version = "0.1.1" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "0aa83a9a47081cd522c09c81b31aec2c9273424976f922ad61c053b58350b715" +checksum = "5e0f8c7178e13481ff6765bd169b33e8d554c5d2bbede5e32c356194be02b9b9" dependencies = [ "lazy_static", + "log", + "tracing-core", +] + +[[package]] +name = "tracing-serde" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b6ccba2f8f16e0ed268fc765d9b7ff22e965e7185d32f8f1ec8294fe17d86e79" +dependencies = [ + "serde", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.2.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f7b33f8b2ef2ab0c3778c12646d9c42a24f7772bee4cdafc72199644a9f58fdc" +dependencies = [ + "ansi_term 0.12.1", + "chrono", + "lazy_static", + "matchers", + "regex", + "serde", + "serde_json", + "sharded-slab", + "smallvec 1.4.1", + "tracing-core", + "tracing-log", + "tracing-serde", ] [[package]] diff --git a/bin/node/cli/Cargo.toml b/bin/node/cli/Cargo.toml index 2f0124482e22b..16ab9bbe80641 100644 --- a/bin/node/cli/Cargo.toml +++ b/bin/node/cli/Cargo.toml @@ -43,7 +43,7 @@ jsonrpc-pubsub = "14.2.0" log = "0.4.8" rand = "0.7.2" structopt = { version = "0.3.8", optional = true } -tracing = "0.1.10" +tracing = "0.1.18" parking_lot = "0.10.0" # primitives diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 7899e48b0a261..f940ab0b95d71 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -240,7 +240,7 @@ pub fn init_logger(pattern: &str) { builder.filter(Some("hyper"), log::LevelFilter::Warn); builder.filter(Some("cranelift_wasm"), log::LevelFilter::Warn); // Always log the special target `sc_tracing`, overrides global level - builder.filter(Some("sc_tracing"), log::LevelFilter::Info); + builder.filter(Some("sc_tracing"), log::LevelFilter::Trace); // Enable info for others. builder.filter(None, log::LevelFilter::Info); diff --git a/client/executor/Cargo.toml b/client/executor/Cargo.toml index 2a6844c31f323..f59c89a9d70e3 100644 --- a/client/executor/Cargo.toml +++ b/client/executor/Cargo.toml @@ -46,7 +46,7 @@ test-case = "0.3.3" sp-runtime = { version = "2.0.0-rc5", path = "../../primitives/runtime" } sp-tracing = { version = "2.0.0-rc5", path = "../../primitives/tracing" } sc-tracing = { version = "2.0.0-rc5", path = "../tracing" } -tracing = "0.1.14" +tracing = "0.1.18" [features] default = [ "std" ] diff --git a/client/executor/src/integration_tests/mod.rs b/client/executor/src/integration_tests/mod.rs index 5276884e92319..a9ac0d0f30c23 100644 --- a/client/executor/src/integration_tests/mod.rs +++ b/client/executor/src/integration_tests/mod.rs @@ -661,7 +661,8 @@ fn parallel_execution(wasm_method: WasmExecutionMethod) { fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { use std::sync::{Arc, Mutex}; - use sc_tracing::SpanDatum; + + use sc_tracing::{SpanDatum, TraceEvent}; struct TestTraceHandler(Arc>>); @@ -669,6 +670,8 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { fn handle_span(&self, sd: SpanDatum) { self.0.lock().unwrap().push(sd); } + + fn handle_event(&self, _event: TraceEvent) {} } let traces = Arc::new(Mutex::new(Vec::new())); diff --git a/client/service/Cargo.toml b/client/service/Cargo.toml index 212d4e4b59edc..3ad91dc3ea39b 100644 --- a/client/service/Cargo.toml +++ b/client/service/Cargo.toml @@ -72,7 +72,7 @@ sc-telemetry = { version = "2.0.0-rc5", path = "../telemetry" } sc-offchain = { version = "2.0.0-rc5", path = "../offchain" } prometheus-endpoint = { package = "substrate-prometheus-endpoint", path = "../../utils/prometheus", version = "0.8.0-rc5"} sc-tracing = { version = "2.0.0-rc5", path = "../tracing" } -tracing = "0.1.10" +tracing = "0.1.18" parity-util-mem = { version = "0.7.0", default-features = false, features = ["primitive-types"] } [target.'cfg(not(target_os = "unknown"))'.dependencies] diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index 998dfb94de0c7..0a692cbe57f84 100644 --- a/client/tracing/Cargo.toml +++ b/client/tracing/Cargo.toml @@ -19,10 +19,8 @@ rustc-hash = "1.1.0" serde = "1.0.101" serde_json = "1.0.41" slog = { version = "2.5.2", features = ["nested-values"] } -tracing-core = "0.1.7" +tracing = "0.1.18" +tracing-subscriber = "0.2.10" sp-tracing = { version = "2.0.0-rc2", path = "../../primitives/tracing" } sc-telemetry = { version = "2.0.0-rc5", path = "../telemetry" } - -[dev-dependencies] -tracing = "0.1.10" diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index c2b036e218f15..f642b00720f1a 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -31,7 +31,7 @@ use std::time::{Duration, Instant}; use parking_lot::Mutex; use serde::ser::{Serialize, Serializer, SerializeMap}; -use tracing_core::{ +use tracing::{ event::Event, field::{Visit, Field}, Level, @@ -39,6 +39,7 @@ use tracing_core::{ span::{Attributes, Id, Record}, subscriber::Subscriber, }; +use tracing_subscriber::CurrentSpan; use sc_telemetry::{telemetry, SUBSTRATE_INFO}; use sp_tracing::proxy::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER}; @@ -46,6 +47,15 @@ use sp_tracing::proxy::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER}; const ZERO_DURATION: Duration = Duration::from_nanos(0); const PROXY_TARGET: &'static str = "sp_tracing::proxy"; +/// Responsible for assigning ids to new spans, which are not re-used. +pub struct ProfilingSubscriber { + next_id: AtomicU64, + targets: Vec<(String, Level)>, + trace_handler: Box, + span_data: Mutex>, + current_span: CurrentSpan, +} + /// Used to configure how to receive the metrics #[derive(Debug, Clone)] pub enum TracingReceiver { @@ -65,14 +75,28 @@ impl Default for TracingReceiver { pub trait TraceHandler: Send + Sync { /// Process a `SpanDatum` fn handle_span(&self, span: SpanDatum); + /// Process a `TraceEvent` + fn handle_event(&self, event: TraceEvent); +} + +/// Represents a tracing event, complete with values +#[derive(Debug)] +pub struct TraceEvent { + pub name: &'static str, + pub target: String, + pub level: Level, + pub values: Values, + pub parent_id: Option, } /// Represents a single instance of a tracing span #[derive(Debug)] pub struct SpanDatum { /// id for this span - pub id: u64, - /// Name of the span + pub id: Id, + /// id of the parent span, if any + pub parent_id: Option, + /// Name of this span pub name: String, /// Target, typically module pub target: String, @@ -192,14 +216,6 @@ impl slog::Value for Values { } } -/// Responsible for assigning ids to new spans, which are not re-used. -pub struct ProfilingSubscriber { - next_id: AtomicU64, - targets: Vec<(String, Level)>, - trace_handler: Box, - span_data: Mutex>, -} - impl ProfilingSubscriber { /// Takes a `TracingReceiver` and a comma separated list of targets, /// either with a level: "pallet=trace,frame=debug" @@ -229,6 +245,7 @@ impl ProfilingSubscriber { targets, trace_handler, span_data: Mutex::new(FxHashMap::default()), + current_span: Default::default() } } @@ -271,17 +288,18 @@ impl Subscriber for ProfilingSubscriber { } fn new_span(&self, attrs: &Attributes<'_>) -> Id { - let id = self.next_id.fetch_add(1, Ordering::Relaxed); + let id = Id::from_u64(self.next_id.fetch_add(1, Ordering::Relaxed)); let mut values = Values::default(); attrs.record(&mut values); // If this is a wasm trace, check if target/level is enabled if let Some(wasm_target) = values.string_values.get(WASM_TARGET_KEY) { if !self.check_target(wasm_target, attrs.metadata().level()) { - return Id::from_u64(id); + return id } } let span_datum = SpanDatum { - id, + 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().clone(), @@ -290,33 +308,46 @@ impl Subscriber for ProfilingSubscriber { overall_time: ZERO_DURATION, values, }; - self.span_data.lock().insert(id, span_datum); - Id::from_u64(id) + self.span_data.lock().insert(id.clone(), span_datum); + id } fn record(&self, span: &Id, values: &Record<'_>) { let mut span_data = self.span_data.lock(); - if let Some(s) = span_data.get_mut(&span.into_u64()) { + if let Some(s) = span_data.get_mut(span) { values.record(&mut s.values); } } fn record_follows_from(&self, _span: &Id, _follows: &Id) {} - fn event(&self, _event: &Event<'_>) {} + fn event(&self, event: &Event<'_>) { + let mut values = Values::default(); + event.record(&mut values); + let trace_event = TraceEvent { + name: event.metadata().name(), + target: event.metadata().target().to_owned(), + level: event.metadata().level().clone(), + values, + parent_id: event.parent().cloned().or_else(|| self.current_span.id()), + }; + self.trace_handler.handle_event(trace_event); + } fn enter(&self, span: &Id) { + 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.into_u64()) { + if let Some(mut s) = span_data.get_mut(&span) { s.start_time = start_time; } } fn exit(&self, span: &Id) { + self.current_span.exit(); let end_time = Instant::now(); let mut span_data = self.span_data.lock(); - if let Some(mut s) = span_data.get_mut(&span.into_u64()) { + if let Some(mut s) = span_data.get_mut(&span) { s.overall_time = end_time - s.start_time + s.overall_time; } } @@ -324,7 +355,7 @@ impl Subscriber for ProfilingSubscriber { fn try_close(&self, span: Id) -> bool { let span_datum = { let mut span_data = self.span_data.lock(); - span_data.remove(&span.into_u64()) + span_data.remove(&span) }; if let Some(mut span_datum) = span_datum { if span_datum.name == WASM_TRACE_IDENTIFIER { @@ -335,8 +366,10 @@ impl Subscriber for ProfilingSubscriber { 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) { + 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); } }; @@ -361,23 +394,37 @@ impl TraceHandler for LogTraceHandler { fn handle_span(&self, span_datum: SpanDatum) { if span_datum.values.is_empty() { log::log!( - log_level(span_datum.level), - "{}: {}, time: {}", + log_level(span_datum.level), + "{}: {}, time: {}, id: {}, parent_id: {:?}", span_datum.target, span_datum.name, span_datum.overall_time.as_nanos(), + span_datum.id.into_u64(), + span_datum.parent_id.map(|s| s.into_u64()), ); } else { log::log!( log_level(span_datum.level), - "{}: {}, time: {}, {}", + "{}: {}, time: {}, id: {}, parent_id: {:?}, values: {}", span_datum.target, span_datum.name, span_datum.overall_time.as_nanos(), + span_datum.id.into_u64(), + span_datum.parent_id.map(|s| s.into_u64()), span_datum.values, ); } } + + fn handle_event(&self, event: TraceEvent) { + log::log!( + log_level(event.level), + "{}, parent_id: {:?}, {}", + event.target, + event.parent_id.map(|s| s.into_u64()), + event.values, + ); + } } /// TraceHandler for sending span data to telemetry, @@ -390,11 +437,21 @@ impl TraceHandler for TelemetryTraceHandler { telemetry!(SUBSTRATE_INFO; "tracing.profiling"; "name" => span_datum.name, "target" => span_datum.target, - "line" => span_datum.line, "time" => span_datum.overall_time.as_nanos(), + "id" => span_datum.id.into_u64(), + "parent_id" => span_datum.parent_id.map(|i| i.into_u64()), "values" => span_datum.values ); } + + fn handle_event(&self, event: TraceEvent) { + telemetry!(SUBSTRATE_INFO; "tracing.event"; + "name" => event.name, + "target" => event.target, + "parent_id" => event.parent_id.map(|i| i.into_u64()), + "values" => event.values + ); + } } #[cfg(test)] @@ -404,37 +461,47 @@ mod tests { struct TestTraceHandler { spans: Arc>>, + events: Arc>>, } impl TraceHandler for TestTraceHandler { fn handle_span(&self, sd: SpanDatum) { self.spans.lock().push(sd); } + + fn handle_event(&self, event: TraceEvent) { + self.events.lock().push(event); + } } - fn setup_subscriber() -> (ProfilingSubscriber, Arc>>) { + fn setup_subscriber() -> (ProfilingSubscriber, Arc>>, Arc>>) { let spans = Arc::new(Mutex::new(Vec::new())); + let events = Arc::new(Mutex::new(Vec::new())); let handler = TestTraceHandler { spans: spans.clone(), + events: events.clone(), }; let test_subscriber = ProfilingSubscriber::new_with_handler( Box::new(handler), "test_target" ); - (test_subscriber, spans) + (test_subscriber, spans, events) } #[test] fn test_span() { - let (sub, spans) = setup_subscriber(); + let (sub, spans, events) = setup_subscriber(); let _sub_guard = tracing::subscriber::set_default(sub); let span = tracing::info_span!(target: "test_target", "test_span1"); assert_eq!(spans.lock().len(), 0); + assert_eq!(events.lock().len(), 0); let _guard = span.enter(); assert_eq!(spans.lock().len(), 0); + assert_eq!(events.lock().len(), 0); drop(_guard); drop(span); assert_eq!(spans.lock().len(), 1); + assert_eq!(events.lock().len(), 0); let sd = spans.lock().remove(0); assert_eq!(sd.name, "test_span1"); assert_eq!(sd.target, "test_target"); @@ -442,9 +509,26 @@ mod tests { assert!(time > 0); } + #[test] + fn test_span_parent_id() { + let (sub, spans, _events) = setup_subscriber(); + let _sub_guard = tracing::subscriber::set_default(sub); + let span1 = tracing::info_span!(target: "test_target", "test_span1"); + let _guard1 = span1.enter(); + let span2 = tracing::info_span!(target: "test_target", "test_span2"); + let _guard2 = span2.enter(); + drop(_guard2); + drop(span2); + let sd2 = spans.lock().remove(0); + drop(_guard1); + drop(span1); + let sd1 = spans.lock().remove(0); + assert_eq!(sd1.id, sd2.parent_id.unwrap()) + } + #[test] fn test_span_values() { - let (sub, spans) = setup_subscriber(); + let (sub, spans, _events) = setup_subscriber(); let _sub_guard = tracing::subscriber::set_default(sub); let test_bool = true; let test_u64 = 1u64; @@ -470,4 +554,98 @@ mod tests { assert_eq!(values.i64_values.get("test_i64").unwrap(), &test_i64); assert_eq!(values.string_values.get("test_str").unwrap(), &test_str.to_owned()); } + + #[test] + fn test_event() { + let (sub, _spans, events) = setup_subscriber(); + let _sub_guard = tracing::subscriber::set_default(sub); + tracing::event!(target: "test_target", tracing::Level::INFO, "test_event"); + let mut te1 = events.lock().remove(0); + assert_eq!(te1.values.string_values.remove(&"message".to_owned()).unwrap(), "test_event".to_owned()); + } + + #[test] + fn test_event_parent_id() { + let (sub, spans, events) = setup_subscriber(); + let _sub_guard = tracing::subscriber::set_default(sub); + + // enter span + let span1 = tracing::info_span!(target: "test_target", "test_span1"); + let _guard1 = span1.enter(); + + // emit event + tracing::event!(target: "test_target", tracing::Level::INFO, "test_event"); + + //exit span + drop(_guard1); + drop(span1); + + let sd1 = spans.lock().remove(0); + let te1 = events.lock().remove(0); + + assert_eq!(sd1.id, te1.parent_id.unwrap()); + } + + #[test] + fn test_parent_id_with_threads() { + use std::sync::mpsc; + use std::thread; + + let (sub, spans, events) = setup_subscriber(); + let _sub_guard = tracing::subscriber::set_global_default(sub); + let span1 = tracing::info_span!(target: "test_target", "test_span1"); + let _guard1 = span1.enter(); + + let (tx, rx) = mpsc::channel(); + let handle = thread::spawn(move || { + let span2 = tracing::info_span!(target: "test_target", "test_span2"); + let _guard2 = span2.enter(); + // emit event + tracing::event!(target: "test_target", tracing::Level::INFO, "test_event1"); + for msg in rx.recv() { + if msg == false { + break; + } + } + // gard2 and span2 dropped / exited + }); + + // wait for Event to be dispatched and stored + while events.lock().is_empty() { + thread::sleep(Duration::from_millis(1)); + } + + // emit new event (will be second item in Vec) while span2 still active in other thread + tracing::event!(target: "test_target", tracing::Level::INFO, "test_event2"); + + // stop thread and drop span + let _ = tx.send(false); + let _ = handle.join(); + + // wait for Span to be dispatched and stored + while spans.lock().is_empty() { + thread::sleep(Duration::from_millis(1)); + } + let span2 = spans.lock().remove(0); + let event1 = events.lock().remove(0); + drop(_guard1); + drop(span1); + + // emit event with no parent + tracing::event!(target: "test_target", tracing::Level::INFO, "test_event3"); + + let span1 = spans.lock().remove(0); + let event2 = events.lock().remove(0); + + assert_eq!(event1.values.string_values.get("message").unwrap(), "test_event1"); + assert_eq!(event2.values.string_values.get("message").unwrap(), "test_event2"); + assert!(span1.parent_id.is_none()); + assert!(span2.parent_id.is_none()); + assert_eq!(span2.id, event1.parent_id.unwrap()); + assert_eq!(span1.id, event2.parent_id.unwrap()); + assert_ne!(span2.id, span1.id); + + let event3 = events.lock().remove(0); + assert!(event3.parent_id.is_none()); + } } diff --git a/primitives/runtime-interface/test/Cargo.toml b/primitives/runtime-interface/test/Cargo.toml index 5e2ea5a62349b..48dbeedbdad3a 100644 --- a/primitives/runtime-interface/test/Cargo.toml +++ b/primitives/runtime-interface/test/Cargo.toml @@ -20,4 +20,4 @@ sp-state-machine = { version = "0.8.0-rc5", path = "../../../primitives/state-ma sp-runtime = { version = "2.0.0-rc5", path = "../../runtime" } sp-core = { version = "2.0.0-rc5", path = "../../core" } sp-io = { version = "2.0.0-rc5", path = "../../io" } -tracing = "0.1.13" +tracing = "0.1.18" diff --git a/primitives/tracing/Cargo.toml b/primitives/tracing/Cargo.toml index fc3d311298dde..03bec79685eda 100644 --- a/primitives/tracing/Cargo.toml +++ b/primitives/tracing/Cargo.toml @@ -12,7 +12,7 @@ description = "Instrumentation primitives and macros for Substrate." targets = ["x86_64-unknown-linux-gnu"] [dependencies] -tracing = { version = "0.1.13", optional = true } +tracing = { version = "0.1.18", optional = true } rental = { version = "0.5.5", optional = true } log = { version = "0.4.8", optional = true }