From e43faebadc74137e7e76fd6ac94f68b584b8b871 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 16 Jul 2020 13:31:46 +0100 Subject: [PATCH 01/21] implement events handling, implement parent_id for spans & events --- Cargo.lock | 74 ++++++++++++++++++++-- client/tracing/Cargo.toml | 1 + client/tracing/src/lib.rs | 112 +++++++++++++++++++++++++++++----- primitives/tracing/src/lib.rs | 18 ++++++ 4 files changed, 185 insertions(+), 20 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 6cdc764d9d0f2..4500250c5dcd9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3157,6 +3157,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" @@ -5782,6 +5791,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ae1ded71d66a4a97f5e961fd0cb25a5f366a42a41570d16a763a69c092c26ae4" dependencies = [ "byteorder", + "regex-syntax", ] [[package]] @@ -7029,6 +7039,7 @@ dependencies = [ "sp-tracing", "tracing", "tracing-core", + "tracing-subscriber", ] [[package]] @@ -7299,6 +7310,15 @@ dependencies = [ "opaque-debug", ] +[[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" @@ -7822,6 +7842,7 @@ dependencies = [ "sp-tracing", "sp-trie", "sp-wasm-interface", + "tracing", ] [[package]] @@ -9161,9 +9182,9 @@ checksum = "e987b6bf443f4b5b3b6f38704195592cca41c5bb7aedd3c3693c7081f8289860" [[package]] name = "tracing" -version = "0.1.14" +version = "0.1.16" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a7c6b59d116d218cb2d990eb06b77b64043e0268ef7323aae63d8b30ae462923" +checksum = "c2e2a2de6b0d5cbb13fc21193a2296888eaab62b6044479aafb3c54c01c29fcd" dependencies = [ "cfg-if", "tracing-attributes", @@ -9172,9 +9193,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 1.0.6", @@ -9183,11 +9204,52 @@ dependencies = [ [[package]] name = "tracing-core" -version = "0.1.10" +version = "0.1.11" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "94ae75f0d28ae10786f3b1895c55fe72e79928fd5ccdebb5438c75e93fec178f" +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.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c72c8cf3ec4ed69fef614d011a5ae4274537a8a8c59133558029bd731eb71659" +dependencies = [ + "ansi_term 0.11.0", + "chrono", + "lazy_static", + "matchers", + "regex", + "serde", + "serde_json", + "sharded-slab", + "smallvec 1.4.1", + "tracing-core", + "tracing-log", + "tracing-serde", ] [[package]] diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index c4564e5fe53f5..a1c846f67bf8c 100644 --- a/client/tracing/Cargo.toml +++ b/client/tracing/Cargo.toml @@ -20,6 +20,7 @@ serde = "1.0.101" serde_json = "1.0.41" slog = { version = "2.5.2", features = ["nested-values"] } tracing-core = "0.1.7" +tracing-subscriber = "0.2.7" sp-tracing = { version = "2.0.0-rc2", path = "../../primitives/tracing" } sc-telemetry = { version = "2.0.0-rc4", path = "../telemetry" } diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index c62b8d5b1e9c9..0b5f3c9d4d4b3 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -40,12 +40,15 @@ 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}; const ZERO_DURATION: Duration = Duration::from_nanos(0); const PROXY_TARGET: &'static str = "sp_tracing::proxy"; +// To ensure we don't accumulate too many associated events +const LEN_LIMIT: usize = 128; /// Used to configure how to receive the metrics #[derive(Debug, Clone)] @@ -66,12 +69,25 @@ impl Default for TracingReceiver { pub trait TraceHandler: Send + Sync { /// Process a `SpanDatum` fn process_span(&self, span: SpanDatum); + /// Process a `TraceEvent` + fn process_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 visitor: Visitor, + pub parent_id: Option, } /// Represents a single instance of a tracing span #[derive(Debug)] pub struct SpanDatum { pub id: u64, + pub parent_id: Option, pub name: String, pub target: String, pub level: Level, @@ -79,6 +95,16 @@ pub struct SpanDatum { pub start_time: Instant, pub overall_time: Duration, pub values: Visitor, + pub events: Vec, +} + +/// 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, } /// Holds associated values for a tracing span @@ -154,14 +180,6 @@ impl Value for Visitor { } } -/// 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" @@ -191,6 +209,7 @@ impl ProfilingSubscriber { targets, trace_handler, span_data: Mutex::new(FxHashMap::default()), + current_span: Default::default() } } @@ -244,6 +263,7 @@ impl Subscriber for ProfilingSubscriber { } let span_datum = SpanDatum { id, + parent_id: self.current_span.id().map(|p| p.into_u64()), name: attrs.metadata().name().to_owned(), target: attrs.metadata().target().to_owned(), level: attrs.metadata().level().clone(), @@ -251,6 +271,7 @@ impl Subscriber for ProfilingSubscriber { start_time: Instant::now(), overall_time: ZERO_DURATION, values, + events: Vec::new(), }; self.span_data.lock().insert(id, span_datum); Id::from_u64(id) @@ -265,9 +286,44 @@ impl Subscriber for ProfilingSubscriber { fn record_follows_from(&self, _span: &Id, _follows: &Id) {} - fn event(&self, _event: &Event<'_>) {} + fn event(&self, event: &Event<'_>) { + let mut visitor = Visitor(FxHashMap::default()); + event.record(&mut visitor); + let trace_event = TraceEvent { + name: event.metadata().name(), + target: event.metadata().target().to_owned(), + level: event.metadata().level().clone(), + visitor, + parent_id: self.current_span.id().map(|id| id.into_u64()), + }; + // Q: Should all events be emitted immediately, rather than grouping with parent span? + match trace_event.parent_id { + Some(parent_id) => { + if let Some(span) = self.span_data.lock().get_mut(&parent_id) { + if span.events.len() > LEN_LIMIT { + log::warn!( + target: "tracing", + "Accumulated too many events for span id: {}, sending event separately", + parent_id + ); + self.trace_handler.process_event(trace_event); + } else { + span.events.push(trace_event); + } + } else { + log::warn!( + target: "tracing", + "Parent span missing" + ); + self.trace_handler.process_event(trace_event); + } + } + None => self.trace_handler.process_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()) { @@ -276,6 +332,7 @@ impl Subscriber for ProfilingSubscriber { } 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()) { @@ -323,23 +380,40 @@ impl TraceHandler for LogTraceHandler { fn process_span(&self, span_datum: SpanDatum) { if span_datum.values.0.is_empty() { log::log!( - log_level(span_datum.level), - "{}: {}, time: {}", + log_level(span_datum.level), + "{}: {}, time: {}, id: {}, parent_id: {:?}, events: {:?}", span_datum.target, span_datum.name, span_datum.overall_time.as_nanos(), + span_datum.id, + span_datum.parent_id, + span_datum.events, ); } else { log::log!( log_level(span_datum.level), - "{}: {}, time: {}, {}", + "{}: {}, time: {}, id: {}, parent_id: {:?}, values: {}, events: {:?}", span_datum.target, span_datum.name, span_datum.overall_time.as_nanos(), + span_datum.id, + span_datum.parent_id, span_datum.values, + span_datum.events, ); } } + + fn process_event(&self, event: TraceEvent) { + log::log!( + log_level(event.level), + "{}: {}, parent_id: {:?}, values: {}", + event.name, + event.target, + event.parent_id, + event.visitor + ); + } } /// TraceHandler for sending span data to telemetry, @@ -349,12 +423,22 @@ pub struct TelemetryTraceHandler; impl TraceHandler for TelemetryTraceHandler { fn process_span(&self, span_datum: SpanDatum) { - telemetry!(SUBSTRATE_INFO; "tracing.profiling"; + telemetry!(SUBSTRATE_INFO; "tracing.span"; "name" => span_datum.name, "target" => span_datum.target, - "line" => span_datum.line, "time" => span_datum.overall_time.as_nanos(), + "id" => span_datum.id, + "parent_id" => span_datum.parent_id, "values" => span_datum.values ); } + + fn process_event(&self, event: TraceEvent) { + telemetry!(SUBSTRATE_INFO; "tracing.event"; + "name" => event.name, + "target" => event.target, + "parent_id" => event.parent_id, + "values" => event.visitor + ); + } } diff --git a/primitives/tracing/src/lib.rs b/primitives/tracing/src/lib.rs index e82d8861cd3f5..0469ec1c49137 100644 --- a/primitives/tracing/src/lib.rs +++ b/primitives/tracing/src/lib.rs @@ -93,6 +93,24 @@ macro_rules! enter_span { } } +/// Create a tracing Event +/// +/// See the documentation for the tracing::event! macro for details +/// +/// # Example +/// +/// ``` +/// sp_tracing::tracing_event!(key = "value", "test-event"); +/// ``` +#[macro_export] +macro_rules! tracing_event { + ( $( $code:tt )* ) => { + $crate::if_tracing!( + $crate::tracing::event!( $( $code )* ) + ); + } +} + /// Generates the given code if the tracing dependency is enabled. #[macro_export] #[cfg(feature = "std")] From 5d0d25a2e4e0e32a5c13467af32f5e3041f8d652 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 16 Jul 2020 14:26:23 +0100 Subject: [PATCH 02/21] add events to sp_io::storage --- primitives/io/Cargo.toml | 2 ++ primitives/io/src/lib.rs | 56 ++++++++++++++++++++++++++++++++++++++-- 2 files changed, 56 insertions(+), 2 deletions(-) diff --git a/primitives/io/Cargo.toml b/primitives/io/Cargo.toml index 06df2cc5ed6c4..2dbe44a2c470d 100644 --- a/primitives/io/Cargo.toml +++ b/primitives/io/Cargo.toml @@ -25,6 +25,7 @@ sp-runtime-interface = { version = "2.0.0-rc4", default-features = false, path = sp-trie = { version = "2.0.0-rc4", optional = true, path = "../../primitives/trie" } sp-externalities = { version = "0.8.0-rc4", optional = true, path = "../externalities" } sp-tracing = { version = "2.0.0-rc4", default-features = false, path = "../tracing" } +tracing = { version = "0.1.16", optional = true } log = { version = "0.4.8", optional = true } futures = { version = "0.3.1", features = ["thread-pool"], optional = true } parking_lot = { version = "0.10.0", optional = true } @@ -45,6 +46,7 @@ std = [ "log", "futures", "parking_lot", + "tracing" ] # These two features are used for `no_std` builds for the environments which already provides diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index 6c99a5c75195b..4d86d8e5f2e9c 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -100,12 +100,25 @@ pub trait Storage { /// Set `key` to `value` in the storage. fn set(&mut self, key: &[u8], value: &[u8]) { + #[cfg(feature = "std")] + tracing::event!( + tracing::Level::INFO, + ?key, + ?value, + "set" + ); self.set_storage(key.to_vec(), value.to_vec()); } /// Clear the storage of the given `key` and its value. fn clear(&mut self, key: &[u8]) { - self.clear_storage(key) + #[cfg(feature = "std")] + tracing::event!( + tracing::Level::INFO, + ?key, + "clear" + ); + self.clear_storage(key); } /// Check whether the given `key` exists in storage. @@ -115,7 +128,13 @@ pub trait Storage { /// Clear the storage of each key-value pair where the key starts with the given `prefix`. fn clear_prefix(&mut self, prefix: &[u8]) { - Externalities::clear_prefix(*self, prefix) + #[cfg(feature = "std")] + tracing::event!( + tracing::Level::INFO, + ?prefix, + "clear_prefix" + ); + Externalities::clear_prefix(*self, prefix); } /// Append the encoded `value` to the storage item at `key`. @@ -127,6 +146,13 @@ pub trait Storage { /// If the storage item does not support [`EncodeAppend`](codec::EncodeAppend) or /// something else fails at appending, the storage item will be set to `[value]`. fn append(&mut self, key: &[u8], value: Vec) { + #[cfg(feature = "std")] + tracing::event!( + tracing::Level::INFO, + ?key, + ?value, + "append" + ); self.storage_append(key.to_vec(), value); } @@ -136,6 +162,11 @@ pub trait Storage { /// /// Returns a `Vec` that holds the SCALE encoded hash. fn root(&mut self) -> Vec { + #[cfg(feature = "std")] + tracing::event!( + tracing::Level::INFO, + "root" + ); self.storage_root() } @@ -147,6 +178,12 @@ pub trait Storage { /// Returns `Some(Vec)` which holds the SCALE encoded hash or `None` when /// changes trie is disabled. fn changes_root(&mut self, parent_hash: &[u8]) -> Option> { + #[cfg(feature = "std")] + tracing::event!( + tracing::Level::INFO, + ?parent_hash, + "changes_root" + ); self.storage_changes_root(parent_hash) .expect("Invalid `parent_hash` given to `changes_root`.") } @@ -169,6 +206,11 @@ pub trait Storage { /// in unbalanced transactions. For example, FRAME users should use high level storage /// abstractions. fn start_transaction(&mut self) { + #[cfg(feature = "std")] + tracing::event!( + tracing::Level::INFO, + "start_transaction" + ); self.storage_start_transaction(); } @@ -180,6 +222,11 @@ pub trait Storage { /// /// Will panic if there is no open transaction. fn rollback_transaction(&mut self) { + #[cfg(feature = "std")] + tracing::event!( + tracing::Level::INFO, + "rollback_transaction" + ); self.storage_rollback_transaction() .expect("No open transaction that can be rolled back."); } @@ -192,6 +239,11 @@ pub trait Storage { /// /// Will panic if there is no open transaction. fn commit_transaction(&mut self) { + #[cfg(feature = "std")] + tracing::event!( + tracing::Level::INFO, + "commit_transaction" + ); self.storage_commit_transaction() .expect("No open transaction that can be committed."); } From 0b7f4f8cc5a0dc02587f2c2614adc8177ccce3d4 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 16 Jul 2020 14:33:13 +0100 Subject: [PATCH 03/21] update test --- client/executor/src/integration_tests/mod.rs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/client/executor/src/integration_tests/mod.rs b/client/executor/src/integration_tests/mod.rs index 21924270b8c1e..c0019e8dc70a3 100644 --- a/client/executor/src/integration_tests/mod.rs +++ b/client/executor/src/integration_tests/mod.rs @@ -662,12 +662,14 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { use std::sync::{Arc, Mutex}; - use sc_tracing::SpanDatum; + use sc_tracing::{SpanDatum, TraceEvent}; impl sc_tracing::TraceHandler for TestTraceHandler { fn process_span(&self, sd: SpanDatum) { self.0.lock().unwrap().push(sd); } + + fn process_event(&self, _event: TraceEvent) {} } struct TestTraceHandler(Arc>>); From f7981fcdca6e35f49928194ac862994c4583ecd2 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 16 Jul 2020 15:15:45 +0100 Subject: [PATCH 04/21] add tests --- client/tracing/Cargo.toml | 2 +- client/tracing/src/lib.rs | 107 ++++++++++++++++++++++++++++++++++ primitives/tracing/src/lib.rs | 18 ------ 3 files changed, 108 insertions(+), 19 deletions(-) diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index a1c846f67bf8c..77a8967eca259 100644 --- a/client/tracing/Cargo.toml +++ b/client/tracing/Cargo.toml @@ -26,4 +26,4 @@ sp-tracing = { version = "2.0.0-rc2", path = "../../primitives/tracing" } sc-telemetry = { version = "2.0.0-rc4", path = "../telemetry" } [dev-dependencies] -tracing = "0.1.10" +tracing = "0.1.16" diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 0b5f3c9d4d4b3..e8c322439fb05 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -442,3 +442,110 @@ impl TraceHandler for TelemetryTraceHandler { ); } } + +#[cfg(test)] +mod tests { + use super::*; + use std::sync::Arc; + + struct TestTraceHandler{ + spans: Arc>>, + events: Arc>>, + } + + impl TraceHandler for TestTraceHandler { + fn process_span(&self, sd: SpanDatum) { + self.spans.lock().push(sd); + } + + fn process_event(&self, event: TraceEvent) { + self.events.lock().push(event); + } + } + + 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, events) + } + + #[test] + fn test_span() { + 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"); + let time: u128 = sd.overall_time.as_nanos(); + 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_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.visitor.0.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); + + // check span is not emitted separately + assert!(events.lock().is_empty()); + + let sd1 = spans.lock().remove(0); + + // Check span contains the event + assert_eq!(sd1.events.len(), 1); + } +} \ No newline at end of file diff --git a/primitives/tracing/src/lib.rs b/primitives/tracing/src/lib.rs index 0469ec1c49137..e82d8861cd3f5 100644 --- a/primitives/tracing/src/lib.rs +++ b/primitives/tracing/src/lib.rs @@ -93,24 +93,6 @@ macro_rules! enter_span { } } -/// Create a tracing Event -/// -/// See the documentation for the tracing::event! macro for details -/// -/// # Example -/// -/// ``` -/// sp_tracing::tracing_event!(key = "value", "test-event"); -/// ``` -#[macro_export] -macro_rules! tracing_event { - ( $( $code:tt )* ) => { - $crate::if_tracing!( - $crate::tracing::event!( $( $code )* ) - ); - } -} - /// Generates the given code if the tracing dependency is enabled. #[macro_export] #[cfg(feature = "std")] From f892b57dd218b96d04449623c3a969a42372d7f4 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 16 Jul 2020 15:28:29 +0100 Subject: [PATCH 05/21] adjust limit --- client/tracing/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index e8c322439fb05..bd02b41fc39be 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -48,7 +48,7 @@ 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"; // To ensure we don't accumulate too many associated events -const LEN_LIMIT: usize = 128; +const LEN_LIMIT: usize = 256; /// Used to configure how to receive the metrics #[derive(Debug, Clone)] From ffb871374138f1f6dfddbe3c78d855a64484b1c5 Mon Sep 17 00:00:00 2001 From: Benjamin Kampmann Date: Wed, 22 Jul 2020 14:54:45 +0200 Subject: [PATCH 06/21] let tracing crate handle parent_ids --- client/tracing/src/lib.rs | 105 ++++++++++++++++---------------------- 1 file changed, 45 insertions(+), 60 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 3a6bac73fa18c..a10b57e7e5271 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -39,15 +39,12 @@ 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}; const ZERO_DURATION: Duration = Duration::from_nanos(0); const PROXY_TARGET: &'static str = "sp_tracing::proxy"; -// To ensure we don't accumulate too many associated events -const LEN_LIMIT: usize = 256; /// Used to configure how to receive the metrics #[derive(Debug, Clone)] @@ -79,15 +76,30 @@ pub struct TraceEvent { pub target: String, pub level: Level, pub values: Values, - pub parent_id: Option, + pub parent_id: Option, +} + +impl From<&Event<'_>> for TraceEvent { + fn from(event: &Event<'_>) -> TraceEvent { + let mut values = Values::new(); + event.record(&mut values); + TraceEvent { + name: event.metadata().name(), + target: event.metadata().target().to_owned(), + level: event.metadata().level().clone(), + parent_id: event.parent().cloned(), + values, + } + } } /// Represents a single instance of a tracing span #[derive(Debug)] pub struct SpanDatum { /// id for this span - pub id: u64, - pub parent_id: Option, + pub id: Id, + /// + pub parent_id: Option, /// Name of the span pub name: String, /// Target, typically module @@ -102,6 +114,7 @@ pub struct SpanDatum { pub overall_time: Duration, /// Values recorded to this span pub values: Values, + /// pub events: Vec, } @@ -110,8 +123,7 @@ pub struct ProfilingSubscriber { next_id: AtomicU64, targets: Vec<(String, Level)>, trace_handler: Box, - span_data: Mutex>, - current_span: CurrentSpan, + span_data: Mutex>, } /// Holds associated values for a tracing span @@ -246,8 +258,7 @@ impl ProfilingSubscriber { next_id: AtomicU64::new(1), targets, trace_handler, - span_data: Mutex::new(FxHashMap::default()), - current_span: Default::default() + span_data: Mutex::new(Default::default()), } } @@ -290,18 +301,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, - parent_id: self.current_span.id().map(|p| p.into_u64()), + id: id.clone(), + parent_id: attrs.parent().cloned(), name: attrs.metadata().name().to_owned(), target: attrs.metadata().target().to_owned(), level: attrs.metadata().level().clone(), @@ -311,13 +322,13 @@ impl Subscriber for ProfilingSubscriber { values, events: Vec::new(), }; - 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); } } @@ -325,55 +336,29 @@ impl Subscriber for ProfilingSubscriber { fn record_follows_from(&self, _span: &Id, _follows: &Id) {} fn event(&self, event: &Event<'_>) { - let mut values = Values::new(); - 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: self.current_span.id().map(|id| id.into_u64()), - }; - // Q: Should all events be emitted immediately, rather than grouping with parent span? - match trace_event.parent_id { - Some(parent_id) => { - if let Some(span) = self.span_data.lock().get_mut(&parent_id) { - if span.events.len() > LEN_LIMIT { - log::warn!( - target: "tracing", - "Accumulated too many events for span id: {}, sending event separately", - parent_id - ); - self.trace_handler.process_event(trace_event); - } else { - span.events.push(trace_event); - } - } else { - log::warn!( - target: "tracing", - "Parent span missing" - ); - self.trace_handler.process_event(trace_event); - } + let event : TraceEvent = event.into(); + if let Some(parent_id) = event.parent_id.as_ref() { + if let Some(span) = self.span_data.lock().get_mut(parent_id) { + span.events.push(event); + return; } - None => self.trace_handler.process_event(trace_event), } + + self.trace_handler.process_event(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; } } @@ -381,7 +366,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 { @@ -423,8 +408,8 @@ impl TraceHandler for LogTraceHandler { span_datum.target, span_datum.name, span_datum.overall_time.as_nanos(), - span_datum.id, - span_datum.parent_id, + span_datum.id.into_u64(), + span_datum.parent_id.map(|s| s.into_u64()), span_datum.events, ); } else { @@ -434,8 +419,8 @@ impl TraceHandler for LogTraceHandler { span_datum.target, span_datum.name, span_datum.overall_time.as_nanos(), - span_datum.id, - span_datum.parent_id, + span_datum.id.into_u64(), + span_datum.parent_id.map(|s| s.into_u64()), span_datum.values, span_datum.events, ); @@ -465,8 +450,8 @@ impl TraceHandler for TelemetryTraceHandler { "name" => span_datum.name, "target" => span_datum.target, "time" => span_datum.overall_time.as_nanos(), - "id" => span_datum.id, - "parent_id" => span_datum.parent_id, + "id" => span_datum.id.into_u64(), + "parent_id" => span_datum.parent_id.map(|i| i.into_u64()), "values" => span_datum.values ); } @@ -475,7 +460,7 @@ impl TraceHandler for TelemetryTraceHandler { telemetry!(SUBSTRATE_INFO; "tracing.event"; "name" => event.name, "target" => event.target, - "parent_id" => event.parent_id, + "parent_id" => event.parent_id.map(|i| i.into_u64()), "values" => event.values ); } From cc3e5e3d6827d6a66c455c9609eb8a535797fa44 Mon Sep 17 00:00:00 2001 From: Benjamin Kampmann Date: Wed, 22 Jul 2020 15:27:09 +0200 Subject: [PATCH 07/21] re-enable current-id tracking --- client/tracing/src/lib.rs | 17 +++++++++++++---- 1 file changed, 13 insertions(+), 4 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index a10b57e7e5271..af245b2592b5f 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -29,7 +29,7 @@ use std::fmt; use std::sync::atomic::{AtomicU64, Ordering}; use std::time::{Duration, Instant}; -use parking_lot::Mutex; +use parking_lot::{RwLock, Mutex}; use serde::ser::{Serialize, Serializer, SerializeMap}; use tracing_core::{ event::Event, @@ -124,6 +124,7 @@ pub struct ProfilingSubscriber { targets: Vec<(String, Level)>, trace_handler: Box, span_data: Mutex>, + current_span: RwLock>, } /// Holds associated values for a tracing span @@ -259,6 +260,7 @@ impl ProfilingSubscriber { targets, trace_handler, span_data: Mutex::new(Default::default()), + current_span: RwLock::new(None), } } @@ -312,7 +314,7 @@ impl Subscriber for ProfilingSubscriber { } let span_datum = SpanDatum { id: id.clone(), - parent_id: attrs.parent().cloned(), + parent_id: attrs.parent().cloned().or_else(|| self.current_span.read().clone()), name: attrs.metadata().name().to_owned(), target: attrs.metadata().target().to_owned(), level: attrs.metadata().level().clone(), @@ -336,7 +338,10 @@ impl Subscriber for ProfilingSubscriber { fn record_follows_from(&self, _span: &Id, _follows: &Id) {} fn event(&self, event: &Event<'_>) { - let event : TraceEvent = event.into(); + let mut event : TraceEvent = event.into(); + if event.parent_id.is_none() { + event.parent_id = self.current_span.read().clone(); + } if let Some(parent_id) = event.parent_id.as_ref() { if let Some(span) = self.span_data.lock().get_mut(parent_id) { span.events.push(event); @@ -348,6 +353,7 @@ impl Subscriber for ProfilingSubscriber { } fn enter(&self, span: &Id) { + *self.current_span.write() = Some(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) { @@ -360,6 +366,9 @@ impl Subscriber for ProfilingSubscriber { let mut span_data = self.span_data.lock(); if let Some(mut s) = span_data.get_mut(&span) { s.overall_time = end_time - s.start_time + s.overall_time; + *self.current_span.write() = s.parent_id.clone() + } else { + *self.current_span.write() = None } } @@ -544,7 +553,7 @@ mod tests { 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.0.remove(&"message".to_owned()).unwrap(), "test_event".to_owned()); + assert_eq!(te1.values.string_values.remove(&"message".to_owned()).unwrap(), "test_event".to_owned()); } #[test] From 1855a9aecad44827866873f440d550add7cd73cf Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 22 Jul 2020 16:42:18 +0100 Subject: [PATCH 08/21] add test for threads with CurrentSpan --- client/tracing/src/lib.rs | 52 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 52 insertions(+) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 827015f211b7b..7def338fd60f4 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -599,4 +599,56 @@ mod tests { assert_eq!(sd1.id, te1.parent_id.unwrap()); } + #[test] + fn test_parent_id_with_threads() { + use std::sync::mpsc; + + 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 = std::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() { + std::thread::sleep(Duration::from_millis(1)); + } + + // emit new event while span2 still active in other thread - (will be second item in Vec) + 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() { + std::thread::sleep(Duration::from_millis(1)); + } + let span2 = spans.lock().remove(0); + let event1 = events.lock().remove(0); + drop(_guard1); + drop(span1); + 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_eq!(span2.id, event1.parent_id.unwrap()); + assert_eq!(span1.id, event2.parent_id.unwrap()); + assert_ne!(span2.id, span1.id); + } } From 2081e5d3da6fb038628dc838991090d31eb0be69 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 22 Jul 2020 17:06:53 +0100 Subject: [PATCH 09/21] fix log level --- client/cli/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index c7f48d2721468..51a16fc3efb1b 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -239,7 +239,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); From 8da1d7a1bd445392e7e95d1ac34c10975807bdc1 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 22 Jul 2020 17:07:56 +0100 Subject: [PATCH 10/21] remove redundant check for non wasm traces --- client/tracing/src/lib.rs | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 7def338fd60f4..447fe826da786 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -380,8 +380,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); } }; @@ -627,7 +629,7 @@ mod tests { std::thread::sleep(Duration::from_millis(1)); } - // emit new event while span2 still active in other thread - (will be second item in Vec) + // 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 From 64d9863f22be7df39bd6dc9a1be86fdf1290774b Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 22 Jul 2020 18:09:08 +0100 Subject: [PATCH 11/21] remove duplicate definition in test --- client/executor/src/integration_tests/mod.rs | 2 -- 1 file changed, 2 deletions(-) diff --git a/client/executor/src/integration_tests/mod.rs b/client/executor/src/integration_tests/mod.rs index 999886a2bb6d3..c2398a4a5886c 100644 --- a/client/executor/src/integration_tests/mod.rs +++ b/client/executor/src/integration_tests/mod.rs @@ -674,8 +674,6 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { fn handle_event(&self, _event: TraceEvent) {} } - struct TestTraceHandler(Arc>>); - let traces = Arc::new(Mutex::new(Vec::new())); let handler = TestTraceHandler(traces.clone()); From 4dfc683d5f3610f7939dd5ba6a3be77aa305d608 Mon Sep 17 00:00:00 2001 From: Benjamin Kampmann Date: Thu, 23 Jul 2020 11:57:00 +0200 Subject: [PATCH 12/21] Adding conditional events API --- client/transaction-pool/Cargo.toml | 2 +- frame/executive/Cargo.toml | 5 +- frame/executive/src/lib.rs | 25 +- frame/support/Cargo.toml | 5 +- primitives/tracing/Cargo.toml | 5 +- primitives/tracing/src/lib.rs | 406 +++++++++++++++++++++++++++-- 6 files changed, 419 insertions(+), 29 deletions(-) diff --git a/client/transaction-pool/Cargo.toml b/client/transaction-pool/Cargo.toml index 6ae3f5a8abbf3..8fd4c48a0e859 100644 --- a/client/transaction-pool/Cargo.toml +++ b/client/transaction-pool/Cargo.toml @@ -26,7 +26,7 @@ sc-transaction-graph = { version = "2.0.0-rc5", path = "./graph" } sp-api = { version = "2.0.0-rc5", path = "../../primitives/api" } sp-core = { version = "2.0.0-rc5", path = "../../primitives/core" } sp-runtime = { version = "2.0.0-rc5", path = "../../primitives/runtime" } -sp-tracing = { version = "2.0.0-rc5", path = "../../primitives/tracing" } +sp-tracing = { version = "2.0.0-rc5", features = ["with-tracing"], path = "../../primitives/tracing" } sp-transaction-pool = { version = "2.0.0-rc5", path = "../../primitives/transaction-pool" } sp-blockchain = { version = "2.0.0-rc5", path = "../../primitives/blockchain" } sp-utils = { version = "2.0.0-rc5", path = "../../primitives/utils" } diff --git a/frame/executive/Cargo.toml b/frame/executive/Cargo.toml index fdc49628a42cb..90f2cb6b671c1 100644 --- a/frame/executive/Cargo.toml +++ b/frame/executive/Cargo.toml @@ -31,7 +31,7 @@ pallet-transaction-payment = { version = "2.0.0-rc5", path = "../transaction-pay sp-version = { version = "2.0.0-rc5", path = "../../primitives/version" } [features] -default = ["std"] +default = ["std", "with-tracing"] std = [ "codec/std", "frame-support/std", @@ -41,3 +41,6 @@ std = [ "sp-tracing/std", "sp-std/std", ] +with-tracing = [ + "sp-tracing/with-tracing" +] diff --git a/frame/executive/src/lib.rs b/frame/executive/src/lib.rs index 24dccf8b0b4a4..e3ea70e4d7538 100644 --- a/frame/executive/src/lib.rs +++ b/frame/executive/src/lib.rs @@ -197,7 +197,7 @@ impl< COnRuntimeUpgrade: OnRuntimeUpgrade, > Executive where - Block::Extrinsic: Checkable + Codec, + Block::Extrinsic: Checkable + tg vbhghhhhggc, CheckedOf: Applyable + GetDispatchInfo, @@ -207,6 +207,7 @@ where { /// Start the execution of a particular block. pub fn initialize_block(header: &System::Header) { + sp_tracing::enter_span! { sp_tracing::Level::INFO, "initialize block" }; let digests = Self::extract_pre_digest(&header); Self::initialize_block_impl( header.number(), @@ -270,6 +271,7 @@ where } fn initial_checks(block: &Block) { + sp_tracing::enter_span! { sp_tracing::Level::INFO, "initial checks" }; let header = block.header(); // Check that `parent_hash` is correct. @@ -309,12 +311,19 @@ where /// Execute given extrinsics and take care of post-extrinsics book-keeping. fn execute_extrinsics_with_book_keeping(extrinsics: Vec, block_number: NumberFor) { - extrinsics.into_iter().for_each(Self::apply_extrinsic_no_note); + { + sp_tracing::enter_span! { sp_tracing::Level::INFO, "executing extrinsics" }; + extrinsics.into_iter().for_each(Self::apply_extrinsic_no_note); + } - // post-extrinsics book-keeping - >::note_finished_extrinsics(); - as OnFinalize>::on_finalize(block_number); - >::on_finalize(block_number); + { + sp_tracing::enter_span! { sp_tracing::Level::INFO, "finalizing" }; + // post-extrinsics book-keeping + >::note_finished_extrinsics(); + + as OnFinalize>::on_finalize(block_number); + >::on_finalize(block_number); + } } /// Finalize the block - it is up the caller to ensure that all header fields are valid @@ -355,6 +364,9 @@ where encoded_len: usize, to_note: Option>, ) -> ApplyExtrinsicResult { + sp_tracing::enter_span! { sp_tracing::Level::INFO, "applying extrinsic"}; + // FIXME: add support for Codec + // sp_tracing::event!(sp_tracing::Level::INFO, extrinsic = ?uxt); // Verify that the signature is good. let xt = uxt.check(&Default::default())?; @@ -377,6 +389,7 @@ where } fn final_checks(header: &System::Header) { + sp_tracing::enter_span! { sp_tracing::Level::INFO, "final checks" }; // remove temporaries let new_header = >::finalize(); diff --git a/frame/support/Cargo.toml b/frame/support/Cargo.toml index 24e898e1692fa..40867f316e4cb 100644 --- a/frame/support/Cargo.toml +++ b/frame/support/Cargo.toml @@ -37,7 +37,7 @@ frame-system = { version = "2.0.0-rc5", path = "../system" } parity-util-mem = { version = "0.7.0", features = ["primitive-types"] } [features] -default = ["std"] +default = ["std", "with-tracing"] std = [ "once_cell", "bitmask/std", @@ -52,6 +52,9 @@ std = [ "sp-inherents/std", "sp-state-machine", ] +with-tracing = [ + "sp-tracing/with-tracing" +] nightly = [] strict = [] runtime-benchmarks = [] diff --git a/primitives/tracing/Cargo.toml b/primitives/tracing/Cargo.toml index fc3d311298dde..e4fdf3cac780a 100644 --- a/primitives/tracing/Cargo.toml +++ b/primitives/tracing/Cargo.toml @@ -12,10 +12,11 @@ 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.13", optional = true, default-features = false } rental = { version = "0.5.5", optional = true } log = { version = "0.4.8", optional = true } [features] default = [ "std" ] -std = [ "tracing", "rental", "log" ] +with-tracing = [ "tracing" ] +std = [ "with-tracing", "tracing/std", "rental", "log" ] diff --git a/primitives/tracing/src/lib.rs b/primitives/tracing/src/lib.rs index e82d8861cd3f5..caf0eb76ab421 100644 --- a/primitives/tracing/src/lib.rs +++ b/primitives/tracing/src/lib.rs @@ -30,14 +30,20 @@ //! the associated Fields mentioned above. #![cfg_attr(not(feature = "std"), no_std)] +#[cfg(feature = "with-tracing")] +use core::{module_path, format_args}; + #[cfg(feature = "std")] #[macro_use] extern crate rental; -#[cfg(feature = "std")] +#[cfg(feature = "with-tracing")] #[doc(hidden)] pub use tracing; +#[cfg(feature = "with-tracing")] +pub use tracing::Level; + #[cfg(feature = "std")] pub mod proxy; @@ -55,7 +61,14 @@ static WASM_TRACING_ENABLED: AtomicBool = AtomicBool::new(false); /// # Example /// /// ``` -/// sp_tracing::tracing_span! { +/// sp_tracing::tracing_span! { // default level LEVEL:TRACE +/// "test-span"; +/// 1 + 1; +/// // some other complex code +/// } +/// +/// sp_tracing::tracing_span! { // specified log level +/// Level::DEBUG, /// "test-span"; /// 1 + 1; /// // some other complex code @@ -71,39 +84,396 @@ macro_rules! tracing_span { $crate::enter_span!($name); $( $code )* } - } + }; + ( + $lvl:expr, + $name:expr; + $( $code:tt )* + ) => { + { + $crate::enter_span!($lvl, $name); + $( $code )* + } + }; } /// Enter a span. /// -/// The span will be valid, until the scope is left. +/// The span will be valid, until the scope is left. noop unless `with-tracing`-feature is enabled /// /// # Example /// /// ``` -/// sp_tracing::enter_span!("test-span"); +/// sp_tracing::enter_span!("test-span"); // defaults to Level::TRACE +/// sp_tracing::enter_span!(sp_tracing::Level::DEBUG, "debug-span"); /// ``` #[macro_export] +#[cfg(feature = "with-tracing")] macro_rules! enter_span { - ( $name:expr ) => { - let __tracing_span__ = $crate::if_tracing!( - $crate::tracing::span!($crate::tracing::Level::TRACE, $name) - ); - let __tracing_guard__ = $crate::if_tracing!(__tracing_span__.enter()); - } + ( $name:expr ) => ({ + $crate::enter_span!($crate::tracing::Level::TRACE, $name); + }); + ( $lvl:expr, $name:expr ) => ({ + // FIXME: we need to make the variable names based on $name or they might overlap + let __tracing_span__ = $crate::tracing::span!($lvl, $name); + let __tracing_guard__ = __tracing_span__.enter(); + }); } -/// Generates the given code if the tracing dependency is enabled. + +/// Enter a span. +/// +/// The span will be valid, until the scope is left. noop unless `with-tracing`-feature is enabled +/// +/// # Example +/// +/// ``` +/// sp_tracing::enter_span!("test-span"); // defaults to Level::TRACE +/// sp_tracing::enter_span!(sp_tracing::Level::DEBUG, "debug-span"); +/// ``` #[macro_export] -#[cfg(feature = "std")] -macro_rules! if_tracing { - ( $if:expr ) => {{ $if }} +#[cfg(not(feature = "with-tracing"))] +macro_rules! enter_span { + ( $name:expr ) => ({ {} }); + ( $lvl:expr, $name:expr ) => ({ {} }); } +/// Trace an Event. +/// +/// see `tracing`-crate for details on usage +/// noop if `with-tracing`-feature is not enabled. +#[macro_export] +#[cfg(feature = "with-tracing")] +macro_rules! event { + + (target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* } )=> ({ + $crate::tracing::event!(target: $target:expr, parent: $parent:expr, $lvl:expr, { $($k).+ = $($fields)* }) + }); + + (target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ + $crate::tracing::event!( + target: $target, + parent: $parent, + $lvl, + { message = format_args!($($arg)+), $($fields)* } + ) + }); + (target: $target:expr, parent: $parent:expr, $lvl:expr, $($k:ident).+ = $($fields:tt)* ) => ( + $crate::tracing::event!(target: $target, parent: $parent, $lvl, { $($k).+ = $($fields)* }) + ); + (target: $target:expr, parent: $parent:expr, $lvl:expr, $($arg:tt)+) => ( + $crate::tracing::event!(target: $target, parent: $parent, $lvl, { $($arg)+ }) + ); + (target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({ + $crate::tracing::event!(target: $target, $lvl, { $($k).+ = $($fields)* }) + }); + (target: $target:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ + $crate::tracing::event!( + target: $target, + $lvl, + { message = format_args!($($arg)+), $($fields)* } + ) + }); + (target: $target:expr, $lvl:expr, $($k:ident).+ = $($fields:tt)* ) => ( + $crate::tracing::event!(target: $target, $lvl, { $($k).+ = $($fields)* }) + ); + (target: $target:expr, $lvl:expr, $($arg:tt)+ ) => ( + $crate::tracing::event!(target: $target, $lvl, { $($arg)+ }) + ); + (parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( + $crate::tracing::event!( + target: module_path!(), + parent: $parent, + $lvl, + { message = format_args!($($arg)+), $($fields)* } + ) + ); + (parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( + $crate::tracing::event!( + target: module_path!(), + $lvl, + parent: $parent, + { message = format_args!($($arg)+), $($fields)* } + ) + ); + (parent: $parent:expr, $lvl:expr, $($k:ident).+ = $($field:tt)*) => ( + $crate::tracing::event!( + target: module_path!(), + parent: $parent, + $lvl, + { $($k).+ = $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, ?$($k:ident).+ = $($field:tt)*) => ( + $crate::tracing::event!( + target: module_path!(), + parent: $parent, + $lvl, + { ?$($k).+ = $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, %$($k:ident).+ = $($field:tt)*) => ( + $crate::tracing::event!( + target: module_path!(), + parent: $parent, + $lvl, + { %$($k).+ = $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ( + $crate::tracing::event!( + target: module_path!(), + parent: $parent, + $lvl, + { $($k).+, $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, %$($k:ident).+, $($field:tt)*) => ( + $crate::tracing::event!( + target: module_path!(), + parent: $parent, + $lvl, + { %$($k).+, $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, ?$($k:ident).+, $($field:tt)*) => ( + $crate::tracing::event!( + target: module_path!(), + parent: $parent, + $lvl, + { ?$($k).+, $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, $($arg:tt)+ ) => ( + $crate::tracing::event!(target: module_path!(), parent: $parent, $lvl, { $($arg)+ }) + ); + ( $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( + $crate::tracing::event!( + target: module_path!(), + $lvl, + { message = format_args!($($arg)+), $($fields)* } + ) + ); + ( $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( + $crate::tracing::event!( + target: module_path!(), + $lvl, + { message = format_args!($($arg)+), $($fields)* } + ) + ); + ($lvl:expr, $($k:ident).+ = $($field:tt)*) => ( + $crate::tracing::event!( + target: module_path!(), + $lvl, + { $($k).+ = $($field)*} + ) + ); + ($lvl:expr, $($k:ident).+, $($field:tt)*) => ( + $crate::tracing::event!( + target: module_path!(), + $lvl, + { $($k).+, $($field)*} + ) + ); + ($lvl:expr, ?$($k:ident).+, $($field:tt)*) => ( + $crate::tracing::event!( + target: module_path!(), + $lvl, + { ?$($k).+, $($field)*} + ) + ); + ($lvl:expr, %$($k:ident).+, $($field:tt)*) => ( + $crate::tracing::event!( + target: module_path!(), + $lvl, + { %$($k).+, $($field)*} + ) + ); + ($lvl:expr, ?$($k:ident).+) => ( + $crate::tracing::event!($lvl, ?$($k).+,) + ); + ($lvl:expr, %$($k:ident).+) => ( + $crate::tracing::event!($lvl, %$($k).+,) + ); + ($lvl:expr, $($k:ident).+) => ( + $crate::tracing::event!($lvl, $($k).+,) + ); + ( $lvl:expr, $($arg:tt)+ ) => ( + $crate::tracing::event!(target: module_path!(), $lvl, { $($arg)+ }) + ); + + (target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ + $crate::tracing::event!(target: $target:expr, parent: $parent:expr, $lvl:expr, { $($k).+ = $($fields)* }, { $($arg)+ }) + }); + + (target: $target:expr, parent: $parent:expr, $lvl:expr, $($k:ident).+ = $($fields:tt)* ) => ( + $crate::tracing::event!(target: $target, parent: $parent, $lvl, { $($k).+ = $($fields)* }) + ); + (target: $target:expr, parent: $parent:expr, $lvl:expr, $($arg:tt)+) => ( + $crate::tracing::event!(target: $target, parent: $parent, $lvl, { $($arg)+ }) + ); + (target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({ + $crate::tracing::event!(target: $target, parent: $parent, $lvl, { $($k).+ = $($fields)* }) + }); + (target: $target:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ + $crate::tracing::event!( + target: $target, + $lvl, + { $($k).+ = $($fields)* }, + { $($arg)+ } + ) + }); + (target: $target:expr, $lvl:expr, $($k:ident).+ = $($fields:tt)* ) => ( + $crate::tracing::event!(target: $target, $lvl, { $($k).+ = $($fields)* }) + ); + (target: $target:expr, $lvl:expr, $($arg:tt)+ ) => ( + $crate::tracing::event!(target: $target, $lvl, { $($arg)+ }) + ); + (parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( + $crate::tracing::event!( + parent: $parent, + $lvl, + { $($k).+ = $($fields)* }, + { $($arg)+ } + ) + ); + (parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( + $crate::tracing::event!( + $lvl, + parent: $parent, + { $($k).+ = $($fields)* }, + { $($arg)+ } + ) + ); + (parent: $parent:expr, $lvl:expr, $($k:ident).+ = $($field:tt)*) => ( + $crate::tracing::event!( + parent: $parent, + $lvl, + { $($k).+ = $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, ?$($k:ident).+ = $($field:tt)*) => ( + $crate::tracing::event!( + parent: $parent, + $lvl, + { ?$($k).+ = $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, %$($k:ident).+ = $($field:tt)*) => ( + $crate::tracing::event!( + parent: $parent, + $lvl, + { %$($k).+ = $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ( + $crate::tracing::event!( + parent: $parent, + $lvl, + { $($k).+, $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, %$($k:ident).+, $($field:tt)*) => ( + $crate::tracing::event!( + parent: $parent, + $lvl, + { %$($k).+, $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, ?$($k:ident).+, $($field:tt)*) => ( + $crate::tracing::event!( + parent: $parent, + $lvl, + { ?$($k).+, $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, $($arg:tt)+ ) => ( + $crate::tracing::event!(parent: $parent, $lvl, { $($arg)+ }) + ); + ( $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( + $crate::tracing::event!( + $lvl, + { $($arg)+, $($fields)* } + ) + ); + ( $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( + $crate::tracing::event!( + $lvl, + { $($arg)+, $($fields)* } + ) + ); + ($lvl:expr, $($k:ident).+ = $($field:tt)*) => ( + $crate::tracing::event!( + $lvl, + { $($k).+ = $($field)*} + ) + ); + ($lvl:expr, $($k:ident).+, $($field:tt)*) => ( + $crate::tracing::event!( + $lvl, + { $($k).+, $($field)*} + ) + ); + ($lvl:expr, ?$($k:ident).+, $($field:tt)*) => ( + $crate::tracing::event!( + $lvl, + { ?$($k).+, $($field)*} + ) + ); + ($lvl:expr, %$($k:ident).+, $($field:tt)*) => ( + $crate::tracing::event!( + $lvl, + { %$($k).+, $($field)*} + ) + ); + ($lvl:expr, ?$($k:ident).+) => ( + $crate::tracing::event!($lvl, ?$($k).+,) + ); + ($lvl:expr, %$($k:ident).+) => ( + $crate::tracing::event!($lvl, %$($k).+,) + ); + ($lvl:expr, $($k:ident).+) => ( + $crate::tracing::event!($lvl, $($k).+,) + ); + ( $lvl:expr, $($arg:tt)+ ) => ( + $crate::tracing::event!($lvl, { $($arg)+ }) + ); +} + +/// Trace an Event. +/// +/// see `tracing`-crate for details on usage +/// noop if `with-tracing`-feature is not enabled. #[macro_export] -#[cfg(not(feature = "std"))] -macro_rules! if_tracing { - ( $if:expr ) => {{}} +#[cfg(not(feature = "with-tracing"))] +macro_rules! event { + (target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* } )=> ({ {} }); + (target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ {} }); + (target: $target:expr, parent: $parent:expr, $lvl:expr, $($k:ident).+ = $($fields:tt)* ) => ({ {} }); + (target: $target:expr, parent: $parent:expr, $lvl:expr, $($arg:tt)+) => ({ {} }); + (target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({ {} }); + (target: $target:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ {} }); + (target: $target:expr, $lvl:expr, $($k:ident).+ = $($fields:tt)* ) => ({ {} }); + (target: $target:expr, $lvl:expr, $($arg:tt)+ ) => ({ {} }); + (parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ {} }); + (parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ {} }); + (parent: $parent:expr, $lvl:expr, $($k:ident).+ = $($field:tt)*) => ({ {} }); + (parent: $parent:expr, $lvl:expr, ?$($k:ident).+ = $($field:tt)*) => ({ {} }); + (parent: $parent:expr, $lvl:expr, %$($k:ident).+ = $($field:tt)*) => ({ {} }); + (parent: $parent:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ({ {} }); + (parent: $parent:expr, $lvl:expr, %$($k:ident).+, $($field:tt)*) => ({ {} }); + (parent: $parent:expr, $lvl:expr, ?$($k:ident).+, $($field:tt)*) => ({ {} }); + (parent: $parent:expr, $lvl:expr, $($arg:tt)+ ) => ({ {} }); + ($lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ {} }); + ($lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ {} }); + ($lvl:expr, $($k:ident).+ = $($field:tt)*) => ({ {} }); + ($lvl:expr, $($k:ident).+, $($field:tt)*) => ({ {} }); + ($lvl:expr, ?$($k:ident).+, $($field:tt)*) => ({ {} }); + ($lvl:expr, %$($k:ident).+, $($field:tt)*) => ({ {} }); + ($lvl:expr, ?$($k:ident).+) => ({ {} }); + ($lvl:expr, %$($k:ident).+) => ({ {} }); + ($lvl:expr, $($k:ident).+) => ({ {} }); + ($lvl:expr, $($arg:tt)+ ) => ({ {} }); } #[cfg(feature = "std")] From c4bac2d1b12109b9763f2d5818c815e6f2f9fb4a Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 23 Jul 2020 11:36:56 +0100 Subject: [PATCH 13/21] prefer explicit parent_id over current, enhance test --- client/tracing/src/lib.rs | 26 +++++++++++++++++++++----- 1 file changed, 21 insertions(+), 5 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 447fe826da786..8cfaa7844cf80 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -313,7 +313,7 @@ impl Subscriber for ProfilingSubscriber { } let span_datum = SpanDatum { id: id.clone(), - parent_id: self.current_span.id(), + 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(), @@ -343,7 +343,7 @@ impl Subscriber for ProfilingSubscriber { target: event.metadata().target().to_owned(), level: event.metadata().level().clone(), values, - parent_id: self.current_span.id(), + parent_id: event.parent().cloned().or_else(|| self.current_span.id()), }; self.trace_handler.handle_event(trace_event); } @@ -604,6 +604,7 @@ mod tests { #[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); @@ -611,7 +612,7 @@ mod tests { let _guard1 = span1.enter(); let (tx, rx) = mpsc::channel(); - let handle = std::thread::spawn(move || { + let handle = thread::spawn(move || { let span2 = tracing::info_span!(target: "test_target", "test_span2"); let _guard2 = span2.enter(); // emit event @@ -626,7 +627,7 @@ mod tests { // wait for Event to be dispatched and stored while events.lock().is_empty() { - std::thread::sleep(Duration::from_millis(1)); + thread::sleep(Duration::from_millis(1)); } // emit new event (will be second item in Vec) while span2 still active in other thread @@ -638,19 +639,34 @@ mod tests { // wait for Span to be dispatched and stored while spans.lock().is_empty() { - std::thread::sleep(Duration::from_millis(1)); + 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()); } } + +struct WasmSpan<'a>{ + name: &'a str, + target: &'a str, + data: &'a +} From f4ee909b29386037bdaf424844877c7375011b73 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 23 Jul 2020 14:56:17 +0100 Subject: [PATCH 14/21] limit changes to client::tracing event implementation --- Cargo.lock | 1 - client/tracing/src/lib.rs | 6 - client/transaction-pool/Cargo.toml | 2 +- frame/executive/Cargo.toml | 5 +- frame/executive/src/lib.rs | 25 +- frame/support/Cargo.toml | 5 +- primitives/io/Cargo.toml | 2 - primitives/io/src/lib.rs | 56 +--- primitives/tracing/Cargo.toml | 5 +- primitives/tracing/src/lib.rs | 406 ++--------------------------- 10 files changed, 31 insertions(+), 482 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 4e928b0141f02..e9f8e7eefa4a1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -7965,7 +7965,6 @@ dependencies = [ "sp-tracing", "sp-trie", "sp-wasm-interface", - "tracing", ] [[package]] diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 8cfaa7844cf80..aae5395d53eb5 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -664,9 +664,3 @@ mod tests { assert!(event3.parent_id.is_none()); } } - -struct WasmSpan<'a>{ - name: &'a str, - target: &'a str, - data: &'a -} diff --git a/client/transaction-pool/Cargo.toml b/client/transaction-pool/Cargo.toml index 8fd4c48a0e859..6ae3f5a8abbf3 100644 --- a/client/transaction-pool/Cargo.toml +++ b/client/transaction-pool/Cargo.toml @@ -26,7 +26,7 @@ sc-transaction-graph = { version = "2.0.0-rc5", path = "./graph" } sp-api = { version = "2.0.0-rc5", path = "../../primitives/api" } sp-core = { version = "2.0.0-rc5", path = "../../primitives/core" } sp-runtime = { version = "2.0.0-rc5", path = "../../primitives/runtime" } -sp-tracing = { version = "2.0.0-rc5", features = ["with-tracing"], path = "../../primitives/tracing" } +sp-tracing = { version = "2.0.0-rc5", path = "../../primitives/tracing" } sp-transaction-pool = { version = "2.0.0-rc5", path = "../../primitives/transaction-pool" } sp-blockchain = { version = "2.0.0-rc5", path = "../../primitives/blockchain" } sp-utils = { version = "2.0.0-rc5", path = "../../primitives/utils" } diff --git a/frame/executive/Cargo.toml b/frame/executive/Cargo.toml index 90f2cb6b671c1..fdc49628a42cb 100644 --- a/frame/executive/Cargo.toml +++ b/frame/executive/Cargo.toml @@ -31,7 +31,7 @@ pallet-transaction-payment = { version = "2.0.0-rc5", path = "../transaction-pay sp-version = { version = "2.0.0-rc5", path = "../../primitives/version" } [features] -default = ["std", "with-tracing"] +default = ["std"] std = [ "codec/std", "frame-support/std", @@ -41,6 +41,3 @@ std = [ "sp-tracing/std", "sp-std/std", ] -with-tracing = [ - "sp-tracing/with-tracing" -] diff --git a/frame/executive/src/lib.rs b/frame/executive/src/lib.rs index e3ea70e4d7538..24dccf8b0b4a4 100644 --- a/frame/executive/src/lib.rs +++ b/frame/executive/src/lib.rs @@ -197,7 +197,7 @@ impl< COnRuntimeUpgrade: OnRuntimeUpgrade, > Executive where - Block::Extrinsic: Checkable + tg vbhghhhhggc, + Block::Extrinsic: Checkable + Codec, CheckedOf: Applyable + GetDispatchInfo, @@ -207,7 +207,6 @@ where { /// Start the execution of a particular block. pub fn initialize_block(header: &System::Header) { - sp_tracing::enter_span! { sp_tracing::Level::INFO, "initialize block" }; let digests = Self::extract_pre_digest(&header); Self::initialize_block_impl( header.number(), @@ -271,7 +270,6 @@ where } fn initial_checks(block: &Block) { - sp_tracing::enter_span! { sp_tracing::Level::INFO, "initial checks" }; let header = block.header(); // Check that `parent_hash` is correct. @@ -311,19 +309,12 @@ where /// Execute given extrinsics and take care of post-extrinsics book-keeping. fn execute_extrinsics_with_book_keeping(extrinsics: Vec, block_number: NumberFor) { - { - sp_tracing::enter_span! { sp_tracing::Level::INFO, "executing extrinsics" }; - extrinsics.into_iter().for_each(Self::apply_extrinsic_no_note); - } + extrinsics.into_iter().for_each(Self::apply_extrinsic_no_note); - { - sp_tracing::enter_span! { sp_tracing::Level::INFO, "finalizing" }; - // post-extrinsics book-keeping - >::note_finished_extrinsics(); - - as OnFinalize>::on_finalize(block_number); - >::on_finalize(block_number); - } + // post-extrinsics book-keeping + >::note_finished_extrinsics(); + as OnFinalize>::on_finalize(block_number); + >::on_finalize(block_number); } /// Finalize the block - it is up the caller to ensure that all header fields are valid @@ -364,9 +355,6 @@ where encoded_len: usize, to_note: Option>, ) -> ApplyExtrinsicResult { - sp_tracing::enter_span! { sp_tracing::Level::INFO, "applying extrinsic"}; - // FIXME: add support for Codec - // sp_tracing::event!(sp_tracing::Level::INFO, extrinsic = ?uxt); // Verify that the signature is good. let xt = uxt.check(&Default::default())?; @@ -389,7 +377,6 @@ where } fn final_checks(header: &System::Header) { - sp_tracing::enter_span! { sp_tracing::Level::INFO, "final checks" }; // remove temporaries let new_header = >::finalize(); diff --git a/frame/support/Cargo.toml b/frame/support/Cargo.toml index 40867f316e4cb..24e898e1692fa 100644 --- a/frame/support/Cargo.toml +++ b/frame/support/Cargo.toml @@ -37,7 +37,7 @@ frame-system = { version = "2.0.0-rc5", path = "../system" } parity-util-mem = { version = "0.7.0", features = ["primitive-types"] } [features] -default = ["std", "with-tracing"] +default = ["std"] std = [ "once_cell", "bitmask/std", @@ -52,9 +52,6 @@ std = [ "sp-inherents/std", "sp-state-machine", ] -with-tracing = [ - "sp-tracing/with-tracing" -] nightly = [] strict = [] runtime-benchmarks = [] diff --git a/primitives/io/Cargo.toml b/primitives/io/Cargo.toml index 6155dbca4b603..04ee4efd97a24 100644 --- a/primitives/io/Cargo.toml +++ b/primitives/io/Cargo.toml @@ -28,7 +28,6 @@ sp-tracing = { version = "2.0.0-rc5", default-features = false, path = "../traci log = { version = "0.4.8", optional = true } futures = { version = "0.3.1", features = ["thread-pool"], optional = true } parking_lot = { version = "0.10.0", optional = true } -tracing = { version = "0.1.16", optional = true } [features] default = ["std"] @@ -46,7 +45,6 @@ std = [ "log", "futures", "parking_lot", - "tracing" ] # These two features are used for `no_std` builds for the environments which already provides diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index 4d86d8e5f2e9c..6c99a5c75195b 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -100,25 +100,12 @@ pub trait Storage { /// Set `key` to `value` in the storage. fn set(&mut self, key: &[u8], value: &[u8]) { - #[cfg(feature = "std")] - tracing::event!( - tracing::Level::INFO, - ?key, - ?value, - "set" - ); self.set_storage(key.to_vec(), value.to_vec()); } /// Clear the storage of the given `key` and its value. fn clear(&mut self, key: &[u8]) { - #[cfg(feature = "std")] - tracing::event!( - tracing::Level::INFO, - ?key, - "clear" - ); - self.clear_storage(key); + self.clear_storage(key) } /// Check whether the given `key` exists in storage. @@ -128,13 +115,7 @@ pub trait Storage { /// Clear the storage of each key-value pair where the key starts with the given `prefix`. fn clear_prefix(&mut self, prefix: &[u8]) { - #[cfg(feature = "std")] - tracing::event!( - tracing::Level::INFO, - ?prefix, - "clear_prefix" - ); - Externalities::clear_prefix(*self, prefix); + Externalities::clear_prefix(*self, prefix) } /// Append the encoded `value` to the storage item at `key`. @@ -146,13 +127,6 @@ pub trait Storage { /// If the storage item does not support [`EncodeAppend`](codec::EncodeAppend) or /// something else fails at appending, the storage item will be set to `[value]`. fn append(&mut self, key: &[u8], value: Vec) { - #[cfg(feature = "std")] - tracing::event!( - tracing::Level::INFO, - ?key, - ?value, - "append" - ); self.storage_append(key.to_vec(), value); } @@ -162,11 +136,6 @@ pub trait Storage { /// /// Returns a `Vec` that holds the SCALE encoded hash. fn root(&mut self) -> Vec { - #[cfg(feature = "std")] - tracing::event!( - tracing::Level::INFO, - "root" - ); self.storage_root() } @@ -178,12 +147,6 @@ pub trait Storage { /// Returns `Some(Vec)` which holds the SCALE encoded hash or `None` when /// changes trie is disabled. fn changes_root(&mut self, parent_hash: &[u8]) -> Option> { - #[cfg(feature = "std")] - tracing::event!( - tracing::Level::INFO, - ?parent_hash, - "changes_root" - ); self.storage_changes_root(parent_hash) .expect("Invalid `parent_hash` given to `changes_root`.") } @@ -206,11 +169,6 @@ pub trait Storage { /// in unbalanced transactions. For example, FRAME users should use high level storage /// abstractions. fn start_transaction(&mut self) { - #[cfg(feature = "std")] - tracing::event!( - tracing::Level::INFO, - "start_transaction" - ); self.storage_start_transaction(); } @@ -222,11 +180,6 @@ pub trait Storage { /// /// Will panic if there is no open transaction. fn rollback_transaction(&mut self) { - #[cfg(feature = "std")] - tracing::event!( - tracing::Level::INFO, - "rollback_transaction" - ); self.storage_rollback_transaction() .expect("No open transaction that can be rolled back."); } @@ -239,11 +192,6 @@ pub trait Storage { /// /// Will panic if there is no open transaction. fn commit_transaction(&mut self) { - #[cfg(feature = "std")] - tracing::event!( - tracing::Level::INFO, - "commit_transaction" - ); self.storage_commit_transaction() .expect("No open transaction that can be committed."); } diff --git a/primitives/tracing/Cargo.toml b/primitives/tracing/Cargo.toml index e4fdf3cac780a..fc3d311298dde 100644 --- a/primitives/tracing/Cargo.toml +++ b/primitives/tracing/Cargo.toml @@ -12,11 +12,10 @@ description = "Instrumentation primitives and macros for Substrate." targets = ["x86_64-unknown-linux-gnu"] [dependencies] -tracing = { version = "0.1.13", optional = true, default-features = false } +tracing = { version = "0.1.13", optional = true } rental = { version = "0.5.5", optional = true } log = { version = "0.4.8", optional = true } [features] default = [ "std" ] -with-tracing = [ "tracing" ] -std = [ "with-tracing", "tracing/std", "rental", "log" ] +std = [ "tracing", "rental", "log" ] diff --git a/primitives/tracing/src/lib.rs b/primitives/tracing/src/lib.rs index caf0eb76ab421..e82d8861cd3f5 100644 --- a/primitives/tracing/src/lib.rs +++ b/primitives/tracing/src/lib.rs @@ -30,20 +30,14 @@ //! the associated Fields mentioned above. #![cfg_attr(not(feature = "std"), no_std)] -#[cfg(feature = "with-tracing")] -use core::{module_path, format_args}; - #[cfg(feature = "std")] #[macro_use] extern crate rental; -#[cfg(feature = "with-tracing")] +#[cfg(feature = "std")] #[doc(hidden)] pub use tracing; -#[cfg(feature = "with-tracing")] -pub use tracing::Level; - #[cfg(feature = "std")] pub mod proxy; @@ -61,14 +55,7 @@ static WASM_TRACING_ENABLED: AtomicBool = AtomicBool::new(false); /// # Example /// /// ``` -/// sp_tracing::tracing_span! { // default level LEVEL:TRACE -/// "test-span"; -/// 1 + 1; -/// // some other complex code -/// } -/// -/// sp_tracing::tracing_span! { // specified log level -/// Level::DEBUG, +/// sp_tracing::tracing_span! { /// "test-span"; /// 1 + 1; /// // some other complex code @@ -84,396 +71,39 @@ macro_rules! tracing_span { $crate::enter_span!($name); $( $code )* } - }; - ( - $lvl:expr, - $name:expr; - $( $code:tt )* - ) => { - { - $crate::enter_span!($lvl, $name); - $( $code )* - } - }; + } } /// Enter a span. /// -/// The span will be valid, until the scope is left. noop unless `with-tracing`-feature is enabled +/// The span will be valid, until the scope is left. /// /// # Example /// /// ``` -/// sp_tracing::enter_span!("test-span"); // defaults to Level::TRACE -/// sp_tracing::enter_span!(sp_tracing::Level::DEBUG, "debug-span"); +/// sp_tracing::enter_span!("test-span"); /// ``` #[macro_export] -#[cfg(feature = "with-tracing")] macro_rules! enter_span { - ( $name:expr ) => ({ - $crate::enter_span!($crate::tracing::Level::TRACE, $name); - }); - ( $lvl:expr, $name:expr ) => ({ - // FIXME: we need to make the variable names based on $name or they might overlap - let __tracing_span__ = $crate::tracing::span!($lvl, $name); - let __tracing_guard__ = __tracing_span__.enter(); - }); + ( $name:expr ) => { + let __tracing_span__ = $crate::if_tracing!( + $crate::tracing::span!($crate::tracing::Level::TRACE, $name) + ); + let __tracing_guard__ = $crate::if_tracing!(__tracing_span__.enter()); + } } - -/// Enter a span. -/// -/// The span will be valid, until the scope is left. noop unless `with-tracing`-feature is enabled -/// -/// # Example -/// -/// ``` -/// sp_tracing::enter_span!("test-span"); // defaults to Level::TRACE -/// sp_tracing::enter_span!(sp_tracing::Level::DEBUG, "debug-span"); -/// ``` -#[macro_export] -#[cfg(not(feature = "with-tracing"))] -macro_rules! enter_span { - ( $name:expr ) => ({ {} }); - ( $lvl:expr, $name:expr ) => ({ {} }); -} - -/// Trace an Event. -/// -/// see `tracing`-crate for details on usage -/// noop if `with-tracing`-feature is not enabled. +/// Generates the given code if the tracing dependency is enabled. #[macro_export] -#[cfg(feature = "with-tracing")] -macro_rules! event { - - (target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* } )=> ({ - $crate::tracing::event!(target: $target:expr, parent: $parent:expr, $lvl:expr, { $($k).+ = $($fields)* }) - }); - - (target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ - $crate::tracing::event!( - target: $target, - parent: $parent, - $lvl, - { message = format_args!($($arg)+), $($fields)* } - ) - }); - (target: $target:expr, parent: $parent:expr, $lvl:expr, $($k:ident).+ = $($fields:tt)* ) => ( - $crate::tracing::event!(target: $target, parent: $parent, $lvl, { $($k).+ = $($fields)* }) - ); - (target: $target:expr, parent: $parent:expr, $lvl:expr, $($arg:tt)+) => ( - $crate::tracing::event!(target: $target, parent: $parent, $lvl, { $($arg)+ }) - ); - (target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({ - $crate::tracing::event!(target: $target, $lvl, { $($k).+ = $($fields)* }) - }); - (target: $target:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ - $crate::tracing::event!( - target: $target, - $lvl, - { message = format_args!($($arg)+), $($fields)* } - ) - }); - (target: $target:expr, $lvl:expr, $($k:ident).+ = $($fields:tt)* ) => ( - $crate::tracing::event!(target: $target, $lvl, { $($k).+ = $($fields)* }) - ); - (target: $target:expr, $lvl:expr, $($arg:tt)+ ) => ( - $crate::tracing::event!(target: $target, $lvl, { $($arg)+ }) - ); - (parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( - $crate::tracing::event!( - target: module_path!(), - parent: $parent, - $lvl, - { message = format_args!($($arg)+), $($fields)* } - ) - ); - (parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( - $crate::tracing::event!( - target: module_path!(), - $lvl, - parent: $parent, - { message = format_args!($($arg)+), $($fields)* } - ) - ); - (parent: $parent:expr, $lvl:expr, $($k:ident).+ = $($field:tt)*) => ( - $crate::tracing::event!( - target: module_path!(), - parent: $parent, - $lvl, - { $($k).+ = $($field)*} - ) - ); - (parent: $parent:expr, $lvl:expr, ?$($k:ident).+ = $($field:tt)*) => ( - $crate::tracing::event!( - target: module_path!(), - parent: $parent, - $lvl, - { ?$($k).+ = $($field)*} - ) - ); - (parent: $parent:expr, $lvl:expr, %$($k:ident).+ = $($field:tt)*) => ( - $crate::tracing::event!( - target: module_path!(), - parent: $parent, - $lvl, - { %$($k).+ = $($field)*} - ) - ); - (parent: $parent:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ( - $crate::tracing::event!( - target: module_path!(), - parent: $parent, - $lvl, - { $($k).+, $($field)*} - ) - ); - (parent: $parent:expr, $lvl:expr, %$($k:ident).+, $($field:tt)*) => ( - $crate::tracing::event!( - target: module_path!(), - parent: $parent, - $lvl, - { %$($k).+, $($field)*} - ) - ); - (parent: $parent:expr, $lvl:expr, ?$($k:ident).+, $($field:tt)*) => ( - $crate::tracing::event!( - target: module_path!(), - parent: $parent, - $lvl, - { ?$($k).+, $($field)*} - ) - ); - (parent: $parent:expr, $lvl:expr, $($arg:tt)+ ) => ( - $crate::tracing::event!(target: module_path!(), parent: $parent, $lvl, { $($arg)+ }) - ); - ( $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( - $crate::tracing::event!( - target: module_path!(), - $lvl, - { message = format_args!($($arg)+), $($fields)* } - ) - ); - ( $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( - $crate::tracing::event!( - target: module_path!(), - $lvl, - { message = format_args!($($arg)+), $($fields)* } - ) - ); - ($lvl:expr, $($k:ident).+ = $($field:tt)*) => ( - $crate::tracing::event!( - target: module_path!(), - $lvl, - { $($k).+ = $($field)*} - ) - ); - ($lvl:expr, $($k:ident).+, $($field:tt)*) => ( - $crate::tracing::event!( - target: module_path!(), - $lvl, - { $($k).+, $($field)*} - ) - ); - ($lvl:expr, ?$($k:ident).+, $($field:tt)*) => ( - $crate::tracing::event!( - target: module_path!(), - $lvl, - { ?$($k).+, $($field)*} - ) - ); - ($lvl:expr, %$($k:ident).+, $($field:tt)*) => ( - $crate::tracing::event!( - target: module_path!(), - $lvl, - { %$($k).+, $($field)*} - ) - ); - ($lvl:expr, ?$($k:ident).+) => ( - $crate::tracing::event!($lvl, ?$($k).+,) - ); - ($lvl:expr, %$($k:ident).+) => ( - $crate::tracing::event!($lvl, %$($k).+,) - ); - ($lvl:expr, $($k:ident).+) => ( - $crate::tracing::event!($lvl, $($k).+,) - ); - ( $lvl:expr, $($arg:tt)+ ) => ( - $crate::tracing::event!(target: module_path!(), $lvl, { $($arg)+ }) - ); - - (target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ - $crate::tracing::event!(target: $target:expr, parent: $parent:expr, $lvl:expr, { $($k).+ = $($fields)* }, { $($arg)+ }) - }); - - (target: $target:expr, parent: $parent:expr, $lvl:expr, $($k:ident).+ = $($fields:tt)* ) => ( - $crate::tracing::event!(target: $target, parent: $parent, $lvl, { $($k).+ = $($fields)* }) - ); - (target: $target:expr, parent: $parent:expr, $lvl:expr, $($arg:tt)+) => ( - $crate::tracing::event!(target: $target, parent: $parent, $lvl, { $($arg)+ }) - ); - (target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({ - $crate::tracing::event!(target: $target, parent: $parent, $lvl, { $($k).+ = $($fields)* }) - }); - (target: $target:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ - $crate::tracing::event!( - target: $target, - $lvl, - { $($k).+ = $($fields)* }, - { $($arg)+ } - ) - }); - (target: $target:expr, $lvl:expr, $($k:ident).+ = $($fields:tt)* ) => ( - $crate::tracing::event!(target: $target, $lvl, { $($k).+ = $($fields)* }) - ); - (target: $target:expr, $lvl:expr, $($arg:tt)+ ) => ( - $crate::tracing::event!(target: $target, $lvl, { $($arg)+ }) - ); - (parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( - $crate::tracing::event!( - parent: $parent, - $lvl, - { $($k).+ = $($fields)* }, - { $($arg)+ } - ) - ); - (parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( - $crate::tracing::event!( - $lvl, - parent: $parent, - { $($k).+ = $($fields)* }, - { $($arg)+ } - ) - ); - (parent: $parent:expr, $lvl:expr, $($k:ident).+ = $($field:tt)*) => ( - $crate::tracing::event!( - parent: $parent, - $lvl, - { $($k).+ = $($field)*} - ) - ); - (parent: $parent:expr, $lvl:expr, ?$($k:ident).+ = $($field:tt)*) => ( - $crate::tracing::event!( - parent: $parent, - $lvl, - { ?$($k).+ = $($field)*} - ) - ); - (parent: $parent:expr, $lvl:expr, %$($k:ident).+ = $($field:tt)*) => ( - $crate::tracing::event!( - parent: $parent, - $lvl, - { %$($k).+ = $($field)*} - ) - ); - (parent: $parent:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ( - $crate::tracing::event!( - parent: $parent, - $lvl, - { $($k).+, $($field)*} - ) - ); - (parent: $parent:expr, $lvl:expr, %$($k:ident).+, $($field:tt)*) => ( - $crate::tracing::event!( - parent: $parent, - $lvl, - { %$($k).+, $($field)*} - ) - ); - (parent: $parent:expr, $lvl:expr, ?$($k:ident).+, $($field:tt)*) => ( - $crate::tracing::event!( - parent: $parent, - $lvl, - { ?$($k).+, $($field)*} - ) - ); - (parent: $parent:expr, $lvl:expr, $($arg:tt)+ ) => ( - $crate::tracing::event!(parent: $parent, $lvl, { $($arg)+ }) - ); - ( $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( - $crate::tracing::event!( - $lvl, - { $($arg)+, $($fields)* } - ) - ); - ( $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( - $crate::tracing::event!( - $lvl, - { $($arg)+, $($fields)* } - ) - ); - ($lvl:expr, $($k:ident).+ = $($field:tt)*) => ( - $crate::tracing::event!( - $lvl, - { $($k).+ = $($field)*} - ) - ); - ($lvl:expr, $($k:ident).+, $($field:tt)*) => ( - $crate::tracing::event!( - $lvl, - { $($k).+, $($field)*} - ) - ); - ($lvl:expr, ?$($k:ident).+, $($field:tt)*) => ( - $crate::tracing::event!( - $lvl, - { ?$($k).+, $($field)*} - ) - ); - ($lvl:expr, %$($k:ident).+, $($field:tt)*) => ( - $crate::tracing::event!( - $lvl, - { %$($k).+, $($field)*} - ) - ); - ($lvl:expr, ?$($k:ident).+) => ( - $crate::tracing::event!($lvl, ?$($k).+,) - ); - ($lvl:expr, %$($k:ident).+) => ( - $crate::tracing::event!($lvl, %$($k).+,) - ); - ($lvl:expr, $($k:ident).+) => ( - $crate::tracing::event!($lvl, $($k).+,) - ); - ( $lvl:expr, $($arg:tt)+ ) => ( - $crate::tracing::event!($lvl, { $($arg)+ }) - ); +#[cfg(feature = "std")] +macro_rules! if_tracing { + ( $if:expr ) => {{ $if }} } -/// Trace an Event. -/// -/// see `tracing`-crate for details on usage -/// noop if `with-tracing`-feature is not enabled. #[macro_export] -#[cfg(not(feature = "with-tracing"))] -macro_rules! event { - (target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* } )=> ({ {} }); - (target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ {} }); - (target: $target:expr, parent: $parent:expr, $lvl:expr, $($k:ident).+ = $($fields:tt)* ) => ({ {} }); - (target: $target:expr, parent: $parent:expr, $lvl:expr, $($arg:tt)+) => ({ {} }); - (target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({ {} }); - (target: $target:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ {} }); - (target: $target:expr, $lvl:expr, $($k:ident).+ = $($fields:tt)* ) => ({ {} }); - (target: $target:expr, $lvl:expr, $($arg:tt)+ ) => ({ {} }); - (parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ {} }); - (parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ {} }); - (parent: $parent:expr, $lvl:expr, $($k:ident).+ = $($field:tt)*) => ({ {} }); - (parent: $parent:expr, $lvl:expr, ?$($k:ident).+ = $($field:tt)*) => ({ {} }); - (parent: $parent:expr, $lvl:expr, %$($k:ident).+ = $($field:tt)*) => ({ {} }); - (parent: $parent:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ({ {} }); - (parent: $parent:expr, $lvl:expr, %$($k:ident).+, $($field:tt)*) => ({ {} }); - (parent: $parent:expr, $lvl:expr, ?$($k:ident).+, $($field:tt)*) => ({ {} }); - (parent: $parent:expr, $lvl:expr, $($arg:tt)+ ) => ({ {} }); - ($lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ {} }); - ($lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ({ {} }); - ($lvl:expr, $($k:ident).+ = $($field:tt)*) => ({ {} }); - ($lvl:expr, $($k:ident).+, $($field:tt)*) => ({ {} }); - ($lvl:expr, ?$($k:ident).+, $($field:tt)*) => ({ {} }); - ($lvl:expr, %$($k:ident).+, $($field:tt)*) => ({ {} }); - ($lvl:expr, ?$($k:ident).+) => ({ {} }); - ($lvl:expr, %$($k:ident).+) => ({ {} }); - ($lvl:expr, $($k:ident).+) => ({ {} }); - ($lvl:expr, $($arg:tt)+ ) => ({ {} }); +#[cfg(not(feature = "std"))] +macro_rules! if_tracing { + ( $if:expr ) => {{}} } #[cfg(feature = "std")] From 0e14ca51c78c71a0a1c0116561e062c99939edc4 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 23 Jul 2020 15:09:44 +0100 Subject: [PATCH 15/21] remove From impl due to fallback required on parent_id --- client/tracing/src/lib.rs | 14 -------------- 1 file changed, 14 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index aae5395d53eb5..d6ba0b3b35bbf 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -80,20 +80,6 @@ pub struct TraceEvent { pub parent_id: Option, } -impl From<&Event<'_>> for TraceEvent { - fn from(event: &Event<'_>) -> TraceEvent { - let mut values = Values::new(); - event.record(&mut values); - TraceEvent { - name: event.metadata().name(), - target: event.metadata().target().to_owned(), - level: event.metadata().level().clone(), - parent_id: event.parent().cloned(), - values, - } - } -} - /// Represents a single instance of a tracing span #[derive(Debug)] pub struct SpanDatum { From 912b4d5ec2dd17fdbe11e0fbf493fc97f25f5515 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 3 Aug 2020 13:41:35 +0100 Subject: [PATCH 16/21] implement SPAN_LIMIT change event log output --- Cargo.lock | 16 ++++----- bin/node/cli/Cargo.toml | 2 +- client/executor/Cargo.toml | 2 +- client/service/Cargo.toml | 2 +- client/tracing/Cargo.toml | 6 ++-- client/tracing/src/lib.rs | 36 +++++++++++++------- primitives/runtime-interface/test/Cargo.toml | 2 +- primitives/tracing/Cargo.toml | 2 +- 8 files changed, 40 insertions(+), 28 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 57e4afdecc110..a71404c840f7a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -9262,9 +9262,9 @@ checksum = "e987b6bf443f4b5b3b6f38704195592cca41c5bb7aedd3c3693c7081f8289860" [[package]] name = "tracing" -version = "0.1.16" +version = "0.1.18" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "c2e2a2de6b0d5cbb13fc21193a2296888eaab62b6044479aafb3c54c01c29fcd" +checksum = "f0aae59226cf195d8e74d4b34beae1859257efb4e5fed3f147d2dc2c7d372178" dependencies = [ "cfg-if", "tracing-attributes", @@ -9284,9 +9284,9 @@ dependencies = [ [[package]] name = "tracing-core" -version = "0.1.11" +version = "0.1.12" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "94ae75f0d28ae10786f3b1895c55fe72e79928fd5ccdebb5438c75e93fec178f" +checksum = "b2734b5a028fa697686f16c6d18c2c6a3c7e41513f9a213abb6754c4acb3c8d7" dependencies = [ "lazy_static", ] @@ -9314,11 +9314,11 @@ dependencies = [ [[package]] name = "tracing-subscriber" -version = "0.2.7" +version = "0.2.10" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "c72c8cf3ec4ed69fef614d011a5ae4274537a8a8c59133558029bd731eb71659" +checksum = "f7b33f8b2ef2ab0c3778c12646d9c42a24f7772bee4cdafc72199644a9f58fdc" dependencies = [ - "ansi_term 0.11.0", + "ansi_term 0.12.1", "chrono", "lazy_static", "matchers", @@ -9423,7 +9423,7 @@ version = "1.5.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "3bfd5b7557925ce778ff9b9ef90e3ade34c524b5ff10e239c69a42d546d2af56" dependencies = [ - "rand 0.3.23", + "rand 0.7.3", ] [[package]] diff --git a/bin/node/cli/Cargo.toml b/bin/node/cli/Cargo.toml index 4fbb48513b3ce..161da7e43fc97 100644 --- a/bin/node/cli/Cargo.toml +++ b/bin/node/cli/Cargo.toml @@ -42,7 +42,7 @@ jsonrpc-core = "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/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/service/Cargo.toml b/client/service/Cargo.toml index 32f6532e7e0d2..3292846e9de2f 100644 --- a/client/service/Cargo.toml +++ b/client/service/Cargo.toml @@ -73,7 +73,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(all(any(unix, windows), not(target_os = "android"), not(target_os = "ios")))'.dependencies] diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index 88f801c61e0c8..28e2f7855be39 100644 --- a/client/tracing/Cargo.toml +++ b/client/tracing/Cargo.toml @@ -19,11 +19,11 @@ 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-subscriber = "0.2.7" +tracing-core = "0.1.12" +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.16" +tracing = "0.1.18" diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index d6ba0b3b35bbf..38943cea75403 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -46,6 +46,16 @@ 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"; +const SPAN_LIMIT: usize = 1000; + +/// 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)] @@ -207,15 +217,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>, - current_span: CurrentSpan, -} - impl ProfilingSubscriber { /// Takes a `TracingReceiver` and a comma separated list of targets, /// either with a level: "pallet=trace,frame=debug" @@ -308,7 +309,18 @@ impl Subscriber for ProfilingSubscriber { overall_time: ZERO_DURATION, values, }; - self.span_data.lock().insert(id.clone(), span_datum); + { + let mut span_data = self.span_data.lock(); + if span_data.len() > SPAN_LIMIT { + log::warn!("Accumulated too many spans, discarding oldest"); + let mut keys = span_data.keys().map(|id| id.into_u64()).collect::>(); + keys.sort(); + for key in keys[0.. SPAN_LIMIT / 10].iter() { + span_data.remove(&Id::from_u64(*key)); + } + } + span_data.insert(id.clone(), span_datum); + } id } @@ -419,8 +431,8 @@ impl TraceHandler for LogTraceHandler { fn handle_event(&self, event: TraceEvent) { log::log!( log_level(event.level), - "{}: {}, parent_id: {:?}, values: {}", - event.name, + "{}, parent_id: {:?}, {}", + // event.name, event.target, event.parent_id.map(|s| s.into_u64()), event.values 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 } From 7fa7f26644e72579437072a813116973bb24534e Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 3 Aug 2020 18:04:05 +0100 Subject: [PATCH 17/21] change version of tracing-core --- client/tracing/Cargo.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index 28e2f7855be39..8e377672e1231 100644 --- a/client/tracing/Cargo.toml +++ b/client/tracing/Cargo.toml @@ -19,7 +19,7 @@ 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.12" +tracing-core = "0.1.11" tracing-subscriber = "0.2.10" sp-tracing = { version = "2.0.0-rc2", path = "../../primitives/tracing" } From 9e42b31e6dc53797fecc0ccdf4de99cc39caa9c4 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 10 Aug 2020 13:45:47 +0100 Subject: [PATCH 18/21] update dependancies --- Cargo.lock | 1 - client/tracing/Cargo.toml | 2 +- client/tracing/src/lib.rs | 2 +- 3 files changed, 2 insertions(+), 3 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 0c3db11436b53..97b9ddca3e3d9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -7100,7 +7100,6 @@ dependencies = [ "slog", "sp-tracing", "tracing", - "tracing-core", "tracing-subscriber", ] diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index 8e377672e1231..c8367e31b1028 100644 --- a/client/tracing/Cargo.toml +++ b/client/tracing/Cargo.toml @@ -19,7 +19,7 @@ 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.11" +tracing = "0.1.18" tracing-subscriber = "0.2.10" sp-tracing = { version = "2.0.0-rc2", path = "../../primitives/tracing" } diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 38943cea75403..ca7ce8dff28a2 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, From 8f16d7bada61b57a019bc429d9fede2c402cff79 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Tue, 11 Aug 2020 11:51:14 +0100 Subject: [PATCH 19/21] revert limit --- client/tracing/src/lib.rs | 14 +------------- 1 file changed, 1 insertion(+), 13 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index ca7ce8dff28a2..02a285427bcf6 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -46,7 +46,6 @@ 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"; -const SPAN_LIMIT: usize = 1000; /// Responsible for assigning ids to new spans, which are not re-used. pub struct ProfilingSubscriber { @@ -309,18 +308,7 @@ impl Subscriber for ProfilingSubscriber { overall_time: ZERO_DURATION, values, }; - { - let mut span_data = self.span_data.lock(); - if span_data.len() > SPAN_LIMIT { - log::warn!("Accumulated too many spans, discarding oldest"); - let mut keys = span_data.keys().map(|id| id.into_u64()).collect::>(); - keys.sort(); - for key in keys[0.. SPAN_LIMIT / 10].iter() { - span_data.remove(&Id::from_u64(*key)); - } - } - span_data.insert(id.clone(), span_datum); - } + self.span_data.lock().insert(id.clone(), span_datum); id } From 471724737919d005fa0037e31da9285f83a5bdac Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Tue, 11 Aug 2020 11:58:23 +0100 Subject: [PATCH 20/21] remove duplicate dependency --- client/tracing/Cargo.toml | 3 --- 1 file changed, 3 deletions(-) diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index c8367e31b1028..0a692cbe57f84 100644 --- a/client/tracing/Cargo.toml +++ b/client/tracing/Cargo.toml @@ -24,6 +24,3 @@ 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.18" From 9dc17e38c49934fa65fa229059869f5dab8ef918 Mon Sep 17 00:00:00 2001 From: mattrutherford <44339188+mattrutherford@users.noreply.github.com> Date: Wed, 12 Aug 2020 11:42:01 +0100 Subject: [PATCH 21/21] Apply suggestions from code review MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Bastian Köcher --- client/tracing/src/lib.rs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 02a285427bcf6..f642b00720f1a 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -420,10 +420,9 @@ impl TraceHandler for LogTraceHandler { log::log!( log_level(event.level), "{}, parent_id: {:?}, {}", - // event.name, event.target, event.parent_id.map(|s| s.into_u64()), - event.values + event.values, ); } }