From 62f4df90fd8233cfb50245a4b1907c57145b0e2f Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 27 Apr 2020 07:51:19 +0100 Subject: [PATCH 01/75] Add span recording to tracing implementation --- client/tracing/src/lib.rs | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index d450700ed3c49..2ab4f36d1715a 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -202,7 +202,14 @@ impl Subscriber for ProfilingSubscriber { Id::from_u64(id) } - fn record(&self, _span: &Id, _values: &Record<'_>) {} + fn record(&self, span: &Id, values: &Record<'_>) { + let mut span_data = self.span_data.lock(); + if let Some(mut s) = span_data.get_mut(&span.into_u64()) { + values.record(&mut s.values); + } else { + log::warn!("Tried to record to span `{:?}` that has already been closed!", span); + } + } fn record_follows_from(&self, _span: &Id, _follows: &Id) {} From e5aa529a1d7898d5c1370915fb4a2aedb3f29fc0 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Tue, 28 Apr 2020 23:09:27 +0100 Subject: [PATCH 02/75] Add tracing proxy --- Cargo.lock | 26 ++++++ client/tracing/src/lib.rs | 2 +- frame/support/src/dispatch.rs | 14 ++++ frame/support/src/lib.rs | 2 + primitives/io/Cargo.toml | 1 + primitives/io/src/lib.rs | 35 +++++++++ primitives/tracing/Cargo.toml | 6 +- primitives/tracing/src/lib.rs | 14 +++- primitives/tracing/src/proxy.rs | 100 ++++++++++++++++++++++++ primitives/tracing/src/span_dispatch.rs | 47 +++++++++++ 10 files changed, 244 insertions(+), 3 deletions(-) create mode 100644 primitives/tracing/src/proxy.rs create mode 100644 primitives/tracing/src/span_dispatch.rs diff --git a/Cargo.lock b/Cargo.lock index e9f315b1bd4a5..1f9bc39e681c3 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5612,6 +5612,27 @@ dependencies = [ "winapi 0.3.8", ] +[[package]] +name = "rental" +version = "0.5.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8545debe98b2b139fb04cad8618b530e9b07c152d99a5de83c860b877d67847f" +dependencies = [ + "rental-impl", + "stable_deref_trait", +] + +[[package]] +name = "rental-impl" +version = "0.5.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "475e68978dc5b743f2f40d8e0a8fdc83f1c5e78cbf4b8fa5e74e73beebc340de" +dependencies = [ + "proc-macro2", + "quote 1.0.3", + "syn 1.0.17", +] + [[package]] name = "ring" version = "0.16.12" @@ -7513,6 +7534,7 @@ dependencies = [ "sp-runtime-interface", "sp-state-machine", "sp-std", + "sp-tracing", "sp-trie", "sp-wasm-interface", ] @@ -7784,6 +7806,10 @@ dependencies = [ name = "sp-tracing" version = "2.0.0-dev" dependencies = [ + "lazy_static", + "log", + "parking_lot 0.10.2", + "rental", "tracing", ] diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 2ab4f36d1715a..b9e5b5c2ed8ee 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -204,7 +204,7 @@ impl Subscriber for ProfilingSubscriber { fn record(&self, span: &Id, values: &Record<'_>) { let mut span_data = self.span_data.lock(); - if let Some(mut s) = span_data.get_mut(&span.into_u64()) { + if let Some(s) = span_data.get_mut(&span.into_u64()) { values.record(&mut s.values); } else { log::warn!("Tried to record to span `{:?}` that has already been closed!", span); diff --git a/frame/support/src/dispatch.rs b/frame/support/src/dispatch.rs index 081574726a62c..b4084312ad276 100644 --- a/frame/support/src/dispatch.rs +++ b/frame/support/src/dispatch.rs @@ -1023,6 +1023,8 @@ macro_rules! decl_module { { fn on_initialize(_block_number_not_used: $trait_instance::BlockNumber) -> $return { $crate::sp_tracing::enter_span!("on_initialize"); + #[cfg(not(feature = "std"))] + let _span_id = $crate::sp_io::TracingSpanGuard($crate::sp_io::profiling::enter_span(module_path!(), "on_initialize_WASM")); { $( $impl )* } } } @@ -1039,6 +1041,8 @@ macro_rules! decl_module { { fn on_initialize($param: $param_ty) -> $return { $crate::sp_tracing::enter_span!("on_initialize"); + #[cfg(not(feature = "std"))] + let _span_id = $crate::sp_io::TracingSpanGuard($crate::sp_io::profiling::enter_span(module_path!(), "on_initialize_WASM")); { $( $impl )* } } } @@ -1065,6 +1069,8 @@ macro_rules! decl_module { { fn on_runtime_upgrade() -> $return { $crate::sp_tracing::enter_span!("on_runtime_upgrade"); + #[cfg(not(feature = "std"))] + let _span_id = $crate::sp_io::TracingSpanGuard($crate::sp_io::profiling::enter_span(module_path!(), "on_runtime_upgrade_WASM")); { $( $impl )* } } } @@ -1092,6 +1098,8 @@ macro_rules! decl_module { { fn on_finalize(_block_number_not_used: $trait_instance::BlockNumber) { $crate::sp_tracing::enter_span!("on_finalize"); + #[cfg(not(feature = "std"))] + let _span_id = $crate::sp_io::TracingSpanGuard($crate::sp_io::profiling::enter_span(module_path!(), "on_finalize_WASM")); { $( $impl )* } } } @@ -1108,6 +1116,8 @@ macro_rules! decl_module { { fn on_finalize($param: $param_ty) { $crate::sp_tracing::enter_span!("on_finalize"); + #[cfg(not(feature = "std"))] + let _span_id = $crate::sp_io::TracingSpanGuard($crate::sp_io::profiling::enter_span(module_path!(), "on_finalize_WASM")); { $( $impl )* } } } @@ -1177,6 +1187,8 @@ macro_rules! decl_module { $origin: $origin_ty $(, $param: $param_ty )* ) -> $crate::dispatch::DispatchResult { $crate::sp_tracing::enter_span!(stringify!($name)); + #[cfg(not(feature = "std"))] + let _span_id = $crate::sp_io::TracingSpanGuard($crate::sp_io::profiling::enter_span(module_path!(), concat!(stringify!($name), "_WASM"))); { $( $impl )* } Ok(()) } @@ -1196,6 +1208,8 @@ macro_rules! decl_module { $(#[doc = $doc_attr])* $vis fn $name($origin: $origin_ty $(, $param: $param_ty )* ) -> $result { $crate::sp_tracing::enter_span!(stringify!($name)); + #[cfg(not(feature = "std"))] + let _span_id = $crate::sp_io::TracingSpanGuard($crate::sp_io::profiling::enter_span(module_path!(), concat!(stringify!($name), "_WASM"))); $( $impl )* } }; diff --git a/frame/support/src/lib.rs b/frame/support/src/lib.rs index b0e7395e9ff2f..a2eba06b58bcb 100644 --- a/frame/support/src/lib.rs +++ b/frame/support/src/lib.rs @@ -26,6 +26,8 @@ extern crate bitmask; #[doc(hidden)] pub use sp_tracing; +#[doc(hidden)] +pub use sp_io; #[cfg(feature = "std")] pub use serde; diff --git a/primitives/io/Cargo.toml b/primitives/io/Cargo.toml index 93c8cc9d38b40..abab29e92df4c 100644 --- a/primitives/io/Cargo.toml +++ b/primitives/io/Cargo.toml @@ -18,6 +18,7 @@ codec = { package = "parity-scale-codec", version = "1.3.0", default-features = hash-db = { version = "0.15.2", default-features = false } sp-core = { version = "2.0.0-dev", default-features = false, path = "../core" } sp-std = { version = "2.0.0-dev", default-features = false, path = "../std" } +sp-tracing = { version = "2.0.0-dev", default-features = false, path = "../tracing" } libsecp256k1 = { version = "0.3.4", optional = true } sp-state-machine = { version = "0.8.0-dev", optional = true, path = "../../primitives/state-machine" } sp-wasm-interface = { version = "2.0.0-dev", path = "../../primitives/wasm-interface", default-features = false } diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index c7da89ab7203e..ffff60dc6981a 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -858,6 +858,40 @@ pub trait Logging { } } +// Do not pass this across the WASM boundry, (eg. by deriving PassByCodec), +// else the drop impl will effectively run twice for the same span id. +/// This is holds a span id and is to notify on drop that a tracing span has exited +/// It must be bound to a named variable eg. `_span_guard` +pub struct TracingSpanGuard(pub u64); + +impl Drop for TracingSpanGuard { + fn drop(&mut self) { + profiling::exit_span(self.0); + } +} + +/// Interface that provides functions for profiling the runtime. +#[runtime_interface] +pub trait Profiling { + /// For enter_span to work correctly with the Tracing profiler, + /// the span `target` and `name` must also be registered in + /// `sp_profiler::span_dispatch::create_registered_span`. + /// The returned `TracingSpanGuard` must be bound to a named variable eg. `_span_guard` + fn enter_span(target: &str, name: &str) -> u64 { + sp_tracing::proxy::create_registered_span(target, name) + } + + /// If there is a panic in the WASM VM then this may not be called. + fn exit_span(id: u64) { + sp_tracing::proxy::exit_span(id); + } + +// fn record_info_u64(id: u64, key: &str, value: &u64) { +// sp_tracing::record_event(id, &format!("{} = {}", key, value)); +// } + +} + /// Wasm-only interface that provides functions for interacting with the sandbox. #[runtime_interface(wasm_only)] pub trait Sandbox { @@ -1004,6 +1038,7 @@ pub type SubstrateHostFunctions = ( storage::HostFunctions, default_child_storage::HostFunctions, misc::HostFunctions, + profiling::HostFunctions, offchain::HostFunctions, crypto::HostFunctions, hashing::HostFunctions, diff --git a/primitives/tracing/Cargo.toml b/primitives/tracing/Cargo.toml index 8eb3bc2beaad5..81c458aa7dedc 100644 --- a/primitives/tracing/Cargo.toml +++ b/primitives/tracing/Cargo.toml @@ -13,7 +13,11 @@ targets = ["x86_64-unknown-linux-gnu"] [dependencies] tracing = { version = "0.1.13", optional = true } +parking_lot = { version = "0.10.0", optional = true } +lazy_static = { version = "1.4.0", optional = true } +rental = { version = "0.5.5", optional = true } +log = { version = "0.4.8", optional = true } [features] default = [ "std" ] -std = [ "tracing" ] +std = [ "tracing", "parking_lot", "lazy_static", "rental", "log"] diff --git a/primitives/tracing/src/lib.rs b/primitives/tracing/src/lib.rs index e5bc93cf9ee52..2684767ef01b7 100644 --- a/primitives/tracing/src/lib.rs +++ b/primitives/tracing/src/lib.rs @@ -18,13 +18,25 @@ //! //! To trace functions or invidual code in Substrate, this crate provides [`tracing_span`] //! and [`enter_span`]. See the individual docs for how to use these macros. - #![cfg_attr(not(feature = "std"), no_std)] +#[cfg(feature = "std")] +#[macro_use] +extern crate rental; + +#[cfg(feature = "std")] +#[macro_use] +extern crate lazy_static; + #[cfg(feature = "std")] #[doc(hidden)] pub use tracing; +#[cfg(feature = "std")] +pub mod proxy; +#[cfg(feature = "std")] +mod span_dispatch; + /// Runs given code within a tracing span, measuring it's execution time. /// /// If tracing is not enabled, the code is still executed. diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs new file mode 100644 index 0000000000000..49f72974839eb --- /dev/null +++ b/primitives/tracing/src/proxy.rs @@ -0,0 +1,100 @@ +use std::sync::Arc; +use parking_lot::Mutex; +use std::collections::BTreeMap; +use rental; +use lazy_static; + +use crate::span_dispatch; + +const MAX_SPAN_STACK_LEN: usize = 1000; + +lazy_static! { + static ref PROXY: Arc> = Arc::new(Mutex::new(TracingProxy::new())); +} + +pub fn create_registered_span(target: &str, name: &str) -> u64 { + PROXY.lock().create_registered_span(target, name) +} + +pub fn exit_span(id: u64) { + PROXY.lock().exit_span(id); +} + +rental! { + pub mod rent_span { + #[rental] + pub struct SpanAndGuard { + span: Box, + guard: tracing::span::Entered<'span>, + } + } +} + +/// Requires a tracing::Subscriber to process span traces, +/// this is available when running with client (and relevant cli params) +pub struct TracingProxy { + next_id: u64, + spans: BTreeMap, +} + +impl TracingProxy { + pub fn new() -> TracingProxy { + let spans: BTreeMap = BTreeMap::new(); + TracingProxy { + // Span ids start from 1 - we will use 0 as special case for unregistered spans + next_id: 1, + spans, + } + } +} + +/// For spans to be recorded they must be registered in `span_dispatch` +impl TracingProxy { + fn create_registered_span(&mut self, target: &str, name: &str) -> u64 { + let create_span: Result = span_dispatch::create_registered_span(target, name); + let id; + match create_span { + Ok(span) => { + self.next_id += 1; + id = self.next_id; + let sg = rent_span::SpanAndGuard::new( + Box::new(span), + |span| span.enter(), + ); + self.spans.insert(id, sg); + }, + Err(e) => { + id = 0; + log::info!("{}", e); + } + } + let spans_len = self.spans.len(); + if spans_len > MAX_SPAN_STACK_LEN { + let n_to_remove = spans_len - MAX_SPAN_STACK_LEN; + let keys: Vec<_> = self.spans.keys().take(n_to_remove).cloned().collect(); + log::warn!("MAX_SPAN_STACK_LEN exceeded, removing oldest {} spans, recording `sp_profiler_ok = false`", n_to_remove); + for key in keys { + let mut sg = self.spans.remove(&key).expect("Just got the key so must be in the map"); + sg.rent_all_mut(|s| { s.span.record("tracing_proxy_ok", &false); }); + } + } + id + } + + fn exit_span(&mut self, id: u64) { + if id == 0 { return; } + match self.spans.remove(&id) { + Some(_) => (), + None => { + log::warn!("Span id: {} not found", id); + return; + } + } + } + +// fn record_info(&mut self, id: u64, info: &str) { +// if let Some(mut sg) = self.spans.get_mut(&id) { +// sg.rent_all_mut(|s| { s.span.record("info", &info); }); +// } +// } +} diff --git a/primitives/tracing/src/span_dispatch.rs b/primitives/tracing/src/span_dispatch.rs new file mode 100644 index 0000000000000..9da6096f8010d --- /dev/null +++ b/primitives/tracing/src/span_dispatch.rs @@ -0,0 +1,47 @@ +use tracing::{span, field, Level}; + +macro_rules! span_dispatch { + ($target:tt, $name:tt, { $($registered_target:tt,$registered_name:tt;)* }) => { + match ($target, $name) { + $( + ($registered_target, $registered_name) => Ok(span!(target: $registered_target, Level::INFO, $registered_name, sp_profiler_ok = true)), + )* + _ => { + Err(format!("Trying to profile span target: {}, name: {} that is not registered", + $target, + $name)) + } + } + } +} + +/// Spans (target/name pairs) must be pre-registered here +pub fn create_registered_span(target: &str, name: &str) -> Result { + span_dispatch! { + target, name, { + "frame_executive","execute_block_WASM"; + "frame_executive","apply_extrinsic_with_len_WASM"; + "pallet_scheduler","on_initialize_WASM"; + "pallet_society","on_initialize_WASM"; + "pallet_randomness_collective_flip","on_initialize_WASM"; + "pallet_offences","on_initialize_WASM"; + "pallet_treasury","on_initialize_WASM"; + "pallet_elections_phragmen","on_initialize_WASM"; + "pallet_democracy","on_initialize_WASM"; + "pallet_session","on_initialize_WASM"; + "pallet_staking","on_initialize_WASM"; + "pallet_indices","on_initialize_WASM"; + "pallet_authorship","on_initialize_WASM"; + "pallet_babe","on_initialize_WASM"; + "pallet_grandpa","on_finalize_WASM"; + "pallet_finality_tracker","on_finalize_WASM"; + "pallet_staking","on_finalize_WASM"; + "pallet_transaction_payment","on_finalize_WASM"; + "pallet_authorship","on_finalize_WASM"; + "pallet_timestamp","on_finalize_WASM"; + "pallet_babe","on_finalize_WASM"; + "pallet_timestamp","set_WASM"; + "pallet_finality_tracker","final_hint_WASM"; + } + } +} From e71eb09b81eb47cf85c27b00cce172c44e07d758 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 29 Apr 2020 12:31:30 +0100 Subject: [PATCH 03/75] switch to rustc_hash::FxHashMap --- Cargo.lock | 2 ++ client/tracing/Cargo.toml | 2 ++ client/tracing/src/lib.rs | 6 +++--- primitives/tracing/Cargo.toml | 3 ++- primitives/tracing/src/proxy.rs | 24 ++++++++++++------------ 5 files changed, 21 insertions(+), 16 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 1f9bc39e681c3..7a39dfada1da6 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6783,6 +6783,7 @@ dependencies = [ "erased-serde", "log", "parking_lot 0.10.2", + "rustc-hash", "sc-telemetry", "serde", "serde_json", @@ -7810,6 +7811,7 @@ dependencies = [ "log", "parking_lot 0.10.2", "rental", + "rustc-hash", "tracing", ] diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index 23f44fd057570..6417ce8dd70ed 100644 --- a/client/tracing/Cargo.toml +++ b/client/tracing/Cargo.toml @@ -20,6 +20,8 @@ serde_json = "1.0.41" slog = { version = "2.5.2", features = ["nested-values"] } tracing-core = "0.1.7" +rustc-hash = "1.1.0" + sc-telemetry = { version = "2.0.0-dev", path = "../telemetry" } [dev-dependencies] diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index b9e5b5c2ed8ee..2416a86a2160e 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -24,7 +24,7 @@ //! //! Currently we provide `Log` (default), `Telemetry` variants for `Receiver` -use std::collections::HashMap; +use rustc_hash::FxHashMap; use std::fmt; use std::sync::atomic::{AtomicU64, Ordering}; use std::time::{Duration, Instant}; @@ -136,7 +136,7 @@ pub struct ProfilingSubscriber { next_id: AtomicU64, targets: Vec<(String, Level)>, receiver: TracingReceiver, - span_data: Mutex>, + span_data: Mutex>, } impl ProfilingSubscriber { @@ -149,7 +149,7 @@ impl ProfilingSubscriber { next_id: AtomicU64::new(1), targets, receiver, - span_data: Mutex::new(HashMap::new()), + span_data: Mutex::new(FxHashMap::default()), } } } diff --git a/primitives/tracing/Cargo.toml b/primitives/tracing/Cargo.toml index 81c458aa7dedc..09382fa156fb7 100644 --- a/primitives/tracing/Cargo.toml +++ b/primitives/tracing/Cargo.toml @@ -17,7 +17,8 @@ parking_lot = { version = "0.10.0", optional = true } lazy_static = { version = "1.4.0", optional = true } rental = { version = "0.5.5", optional = true } log = { version = "0.4.8", optional = true } +rustc-hash = { version = "1.1.0", optional = true } [features] default = [ "std" ] -std = [ "tracing", "parking_lot", "lazy_static", "rental", "log"] +std = [ "tracing", "parking_lot", "lazy_static", "rental", "log", "rustc-hash"] diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index 49f72974839eb..a1e819c517f34 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -3,10 +3,11 @@ use parking_lot::Mutex; use std::collections::BTreeMap; use rental; use lazy_static; +use rustc_hash::FxHashMap; use crate::span_dispatch; -const MAX_SPAN_STACK_LEN: usize = 1000; +const MAX_SPANS_LEN: usize = 1000; lazy_static! { static ref PROXY: Arc> = Arc::new(Mutex::new(TracingProxy::new())); @@ -34,12 +35,12 @@ rental! { /// this is available when running with client (and relevant cli params) pub struct TracingProxy { next_id: u64, - spans: BTreeMap, + spans: FxHashMap, } impl TracingProxy { pub fn new() -> TracingProxy { - let spans: BTreeMap = BTreeMap::new(); + let spans: FxHashMap = FxHashMap::default(); TracingProxy { // Span ids start from 1 - we will use 0 as special case for unregistered spans next_id: 1, @@ -62,21 +63,20 @@ impl TracingProxy { |span| span.enter(), ); self.spans.insert(id, sg); - }, + } Err(e) => { id = 0; log::info!("{}", e); } } let spans_len = self.spans.len(); - if spans_len > MAX_SPAN_STACK_LEN { - let n_to_remove = spans_len - MAX_SPAN_STACK_LEN; - let keys: Vec<_> = self.spans.keys().take(n_to_remove).cloned().collect(); - log::warn!("MAX_SPAN_STACK_LEN exceeded, removing oldest {} spans, recording `sp_profiler_ok = false`", n_to_remove); - for key in keys { - let mut sg = self.spans.remove(&key).expect("Just got the key so must be in the map"); - sg.rent_all_mut(|s| { s.span.record("tracing_proxy_ok", &false); }); - } + if spans_len > MAX_SPANS_LEN { + log::warn!("MAX_SPANS_LEN exceeded, removing oldest span, recording `sp_profiler_ok = false`"); + let mut all_keys: Vec<_> = self.spans.keys().cloned().collect(); + all_keys.sort(); + let key = all_keys.iter().next().expect("Just got the key, so must be able to get first item."); + let mut sg = self.spans.remove(&key).expect("Just got the key so must be in the map"); + sg.rent_all_mut(|s| { s.span.record("tracing_proxy_ok", &false); }); } id } From db6926843163a5a7409f16a9c1b3d3d38161139a Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 29 Apr 2020 13:49:14 +0100 Subject: [PATCH 04/75] Replace lazy_static and hashmap with thread_local and vec. --- Cargo.lock | 3 -- primitives/tracing/Cargo.toml | 5 +--- primitives/tracing/src/lib.rs | 4 --- primitives/tracing/src/proxy.rs | 53 ++++++++++++++++++++++----------- 4 files changed, 36 insertions(+), 29 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 7a39dfada1da6..c0c727334a7f2 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -7807,11 +7807,8 @@ dependencies = [ name = "sp-tracing" version = "2.0.0-dev" dependencies = [ - "lazy_static", "log", - "parking_lot 0.10.2", "rental", - "rustc-hash", "tracing", ] diff --git a/primitives/tracing/Cargo.toml b/primitives/tracing/Cargo.toml index 09382fa156fb7..f7924f3a9203c 100644 --- a/primitives/tracing/Cargo.toml +++ b/primitives/tracing/Cargo.toml @@ -13,12 +13,9 @@ targets = ["x86_64-unknown-linux-gnu"] [dependencies] tracing = { version = "0.1.13", optional = true } -parking_lot = { version = "0.10.0", optional = true } -lazy_static = { version = "1.4.0", optional = true } rental = { version = "0.5.5", optional = true } log = { version = "0.4.8", optional = true } -rustc-hash = { version = "1.1.0", optional = true } [features] default = [ "std" ] -std = [ "tracing", "parking_lot", "lazy_static", "rental", "log", "rustc-hash"] +std = [ "tracing", "rental", "log" ] diff --git a/primitives/tracing/src/lib.rs b/primitives/tracing/src/lib.rs index 2684767ef01b7..01ec236be4c3b 100644 --- a/primitives/tracing/src/lib.rs +++ b/primitives/tracing/src/lib.rs @@ -24,10 +24,6 @@ #[macro_use] extern crate rental; -#[cfg(feature = "std")] -#[macro_use] -extern crate lazy_static; - #[cfg(feature = "std")] #[doc(hidden)] pub use tracing; diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index a1e819c517f34..5b65118233076 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -1,24 +1,20 @@ -use std::sync::Arc; -use parking_lot::Mutex; -use std::collections::BTreeMap; +use std::cell::RefCell; use rental; -use lazy_static; -use rustc_hash::FxHashMap; use crate::span_dispatch; const MAX_SPANS_LEN: usize = 1000; -lazy_static! { - static ref PROXY: Arc> = Arc::new(Mutex::new(TracingProxy::new())); +thread_local! { + static PROXY: RefCell = RefCell::new(TracingProxy::new()); } pub fn create_registered_span(target: &str, name: &str) -> u64 { - PROXY.lock().create_registered_span(target, name) + PROXY.with(|proxy| proxy.borrow_mut().create_registered_span(target, name)) } pub fn exit_span(id: u64) { - PROXY.lock().exit_span(id); + PROXY.with(|proxy| proxy.borrow_mut().exit_span(id)); } rental! { @@ -35,12 +31,20 @@ rental! { /// this is available when running with client (and relevant cli params) pub struct TracingProxy { next_id: u64, - spans: FxHashMap, + spans: Vec<(u64, rent_span::SpanAndGuard)>, +} + +impl Drop for TracingProxy { + fn drop(&mut self) { + while let Some((_, mut sg)) = self.spans.pop() { + sg.rent_all_mut(|s| { s.span.record("tracing_proxy_ok", &false); }); + } + } } impl TracingProxy { pub fn new() -> TracingProxy { - let spans: FxHashMap = FxHashMap::default(); + let spans: Vec<(u64, rent_span::SpanAndGuard)> = Vec::new(); TracingProxy { // Span ids start from 1 - we will use 0 as special case for unregistered spans next_id: 1, @@ -62,7 +66,7 @@ impl TracingProxy { Box::new(span), |span| span.enter(), ); - self.spans.insert(id, sg); + self.spans.push((id, sg)); } Err(e) => { id = 0; @@ -71,11 +75,12 @@ impl TracingProxy { } let spans_len = self.spans.len(); if spans_len > MAX_SPANS_LEN { + // This could mean: + // 1. Probably doing too much tracing, or MAX_SPANS_LEN is too low. + // 2. Not correctly exiting spans due to drop impl not running (panic in runtime) + // 3. Not correctly exiting spans due to misconfiguration log::warn!("MAX_SPANS_LEN exceeded, removing oldest span, recording `sp_profiler_ok = false`"); - let mut all_keys: Vec<_> = self.spans.keys().cloned().collect(); - all_keys.sort(); - let key = all_keys.iter().next().expect("Just got the key, so must be able to get first item."); - let mut sg = self.spans.remove(&key).expect("Just got the key so must be in the map"); + let mut sg = self.spans.remove(0).1; sg.rent_all_mut(|s| { s.span.record("tracing_proxy_ok", &false); }); } id @@ -83,8 +88,20 @@ impl TracingProxy { fn exit_span(&mut self, id: u64) { if id == 0 { return; } - match self.spans.remove(&id) { - Some(_) => (), + match self.spans.pop() { + Some(v) => { + let mut last_span_id = v.0; + while id < last_span_id { + log::warn!("Span ids not equal! id parameter given: {}, last span: {}", id, last_span_id); + if let Some(mut s) = self.spans.pop() { + s.1.rent_all_mut(|s| { s.span.record("tracing_proxy_ok", &false); }); + last_span_id = s.0; + } else { + log::warn!("Span id not found {}", id); + return; + } + } + }, None => { log::warn!("Span id: {} not found", id); return; From b43015ff3bc664d79e8fadf4edeab0a7aad65ee2 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 29 Apr 2020 14:26:18 +0100 Subject: [PATCH 05/75] fix marking valid span as invalid while removing invalid spans --- primitives/tracing/src/proxy.rs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index 5b65118233076..7f71c033d284d 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -94,8 +94,10 @@ impl TracingProxy { while id < last_span_id { log::warn!("Span ids not equal! id parameter given: {}, last span: {}", id, last_span_id); if let Some(mut s) = self.spans.pop() { - s.1.rent_all_mut(|s| { s.span.record("tracing_proxy_ok", &false); }); last_span_id = s.0; + if id != last_span_id { + s.1.rent_all_mut(|s| { s.span.record("tracing_proxy_ok", &false); }); + } } else { log::warn!("Span id not found {}", id); return; From dba7d5530fc058d142a4c8c5ace1edc0b901617e Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 6 May 2020 10:41:10 +0100 Subject: [PATCH 06/75] refactor, add wasm_tracing module in `support` --- frame/support/src/dispatch.rs | 21 +++++--------- frame/support/src/lib.rs | 2 ++ frame/support/src/wasm_tracing.rs | 48 +++++++++++++++++++++++++++++++ primitives/io/src/lib.rs | 19 ++---------- primitives/tracing/src/proxy.rs | 6 ++-- 5 files changed, 63 insertions(+), 33 deletions(-) create mode 100644 frame/support/src/wasm_tracing.rs diff --git a/frame/support/src/dispatch.rs b/frame/support/src/dispatch.rs index b4084312ad276..b616f373be708 100644 --- a/frame/support/src/dispatch.rs +++ b/frame/support/src/dispatch.rs @@ -1023,8 +1023,7 @@ macro_rules! decl_module { { fn on_initialize(_block_number_not_used: $trait_instance::BlockNumber) -> $return { $crate::sp_tracing::enter_span!("on_initialize"); - #[cfg(not(feature = "std"))] - let _span_id = $crate::sp_io::TracingSpanGuard($crate::sp_io::profiling::enter_span(module_path!(), "on_initialize_WASM")); + $crate::wasm_tracing_span!(module_path!(), "on_initialize_wasm"); { $( $impl )* } } } @@ -1041,8 +1040,7 @@ macro_rules! decl_module { { fn on_initialize($param: $param_ty) -> $return { $crate::sp_tracing::enter_span!("on_initialize"); - #[cfg(not(feature = "std"))] - let _span_id = $crate::sp_io::TracingSpanGuard($crate::sp_io::profiling::enter_span(module_path!(), "on_initialize_WASM")); + $crate::wasm_tracing_span!(module_path!(), "on_initialize_wasm"); { $( $impl )* } } } @@ -1069,8 +1067,7 @@ macro_rules! decl_module { { fn on_runtime_upgrade() -> $return { $crate::sp_tracing::enter_span!("on_runtime_upgrade"); - #[cfg(not(feature = "std"))] - let _span_id = $crate::sp_io::TracingSpanGuard($crate::sp_io::profiling::enter_span(module_path!(), "on_runtime_upgrade_WASM")); + $crate::wasm_tracing_span!(module_path!(), "on_runtime_upgrade_wasm"); { $( $impl )* } } } @@ -1098,8 +1095,7 @@ macro_rules! decl_module { { fn on_finalize(_block_number_not_used: $trait_instance::BlockNumber) { $crate::sp_tracing::enter_span!("on_finalize"); - #[cfg(not(feature = "std"))] - let _span_id = $crate::sp_io::TracingSpanGuard($crate::sp_io::profiling::enter_span(module_path!(), "on_finalize_WASM")); + $crate::wasm_tracing_span!(module_path!(), "on_finalize_wasm"); { $( $impl )* } } } @@ -1116,8 +1112,7 @@ macro_rules! decl_module { { fn on_finalize($param: $param_ty) { $crate::sp_tracing::enter_span!("on_finalize"); - #[cfg(not(feature = "std"))] - let _span_id = $crate::sp_io::TracingSpanGuard($crate::sp_io::profiling::enter_span(module_path!(), "on_finalize_WASM")); + $crate::wasm_tracing_span!(module_path!(), "on_finalize_wasm"); { $( $impl )* } } } @@ -1187,8 +1182,7 @@ macro_rules! decl_module { $origin: $origin_ty $(, $param: $param_ty )* ) -> $crate::dispatch::DispatchResult { $crate::sp_tracing::enter_span!(stringify!($name)); - #[cfg(not(feature = "std"))] - let _span_id = $crate::sp_io::TracingSpanGuard($crate::sp_io::profiling::enter_span(module_path!(), concat!(stringify!($name), "_WASM"))); + $crate::wasm_tracing_span!(module_path!(), concat!(stringify!($name),"_wasm")); { $( $impl )* } Ok(()) } @@ -1208,8 +1202,7 @@ macro_rules! decl_module { $(#[doc = $doc_attr])* $vis fn $name($origin: $origin_ty $(, $param: $param_ty )* ) -> $result { $crate::sp_tracing::enter_span!(stringify!($name)); - #[cfg(not(feature = "std"))] - let _span_id = $crate::sp_io::TracingSpanGuard($crate::sp_io::profiling::enter_span(module_path!(), concat!(stringify!($name), "_WASM"))); + $crate::wasm_tracing_span!(module_path!(), concat!(stringify!($name),"_wasm")); $( $impl )* } }; diff --git a/frame/support/src/lib.rs b/frame/support/src/lib.rs index a2eba06b58bcb..f6965aa152175 100644 --- a/frame/support/src/lib.rs +++ b/frame/support/src/lib.rs @@ -66,6 +66,8 @@ pub mod inherent; pub mod unsigned; #[macro_use] pub mod error; +#[macro_use] +pub mod wasm_tracing; pub mod traits; pub mod weights; diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs new file mode 100644 index 0000000000000..77e317e52ab89 --- /dev/null +++ b/frame/support/src/wasm_tracing.rs @@ -0,0 +1,48 @@ +// Copyright 2020 Parity Technologies (UK) Ltd. +// This file is part of Substrate. + +// Substrate is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. + +// Substrate is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. + +// You should have received a copy of the GNU General Public License +// along with Substrate. If not, see . + +//! # To allow tracing in WASM execution environment +//! +//! Facilitated by `sp_io::wasm_tracing` + + +/// This is holds a span id and is to signal on drop that a tracing span has exited +/// It must be bound to a named variable eg. `_span_guard` +pub struct TracingSpanGuard(pub u64); + +impl Drop for TracingSpanGuard { + fn drop(&mut self) { + crate::sp_io::wasm_tracing::exit_span(self.0); + } +} + +/// Enters a tracing span, via [`sp_tracing::proxy`] measuring execution time +/// until exit from the current scope. +/// +/// # Example +/// +/// ``` +/// wasm_tracing_span!("target", "fn_name"); +/// ``` +#[macro_export] +macro_rules! wasm_tracing_span { + ( $target:expr, $name:expr ) => { + #[cfg(not(feature = "std"))] + let __span_id__ = $crate::wasm_tracing::TracingSpanGuard( + $crate::sp_io::wasm_tracing::enter_span($target, $name) + ); + } +} \ No newline at end of file diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index ffff60dc6981a..6841bfc612275 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -858,25 +858,12 @@ pub trait Logging { } } -// Do not pass this across the WASM boundry, (eg. by deriving PassByCodec), -// else the drop impl will effectively run twice for the same span id. -/// This is holds a span id and is to notify on drop that a tracing span has exited -/// It must be bound to a named variable eg. `_span_guard` -pub struct TracingSpanGuard(pub u64); - -impl Drop for TracingSpanGuard { - fn drop(&mut self) { - profiling::exit_span(self.0); - } -} - /// Interface that provides functions for profiling the runtime. #[runtime_interface] -pub trait Profiling { +pub trait WasmTracing { /// For enter_span to work correctly with the Tracing profiler, /// the span `target` and `name` must also be registered in - /// `sp_profiler::span_dispatch::create_registered_span`. - /// The returned `TracingSpanGuard` must be bound to a named variable eg. `_span_guard` + /// `sp_tracing::span_dispatch::create_registered_span`. fn enter_span(target: &str, name: &str) -> u64 { sp_tracing::proxy::create_registered_span(target, name) } @@ -1038,7 +1025,7 @@ pub type SubstrateHostFunctions = ( storage::HostFunctions, default_child_storage::HostFunctions, misc::HostFunctions, - profiling::HostFunctions, + wasm_tracing::HostFunctions, offchain::HostFunctions, crypto::HostFunctions, hashing::HostFunctions, diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index 7f71c033d284d..47db9d7b38d13 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -75,10 +75,10 @@ impl TracingProxy { } let spans_len = self.spans.len(); if spans_len > MAX_SPANS_LEN { - // This could mean: - // 1. Probably doing too much tracing, or MAX_SPANS_LEN is too low. + // This is to prevent unbounded growth of Vec and could mean one of the following: + // 1. Too many nested spans, or MAX_SPANS_LEN is too low. // 2. Not correctly exiting spans due to drop impl not running (panic in runtime) - // 3. Not correctly exiting spans due to misconfiguration + // 3. Not correctly exiting spans due to misconfiguration / misuse log::warn!("MAX_SPANS_LEN exceeded, removing oldest span, recording `sp_profiler_ok = false`"); let mut sg = self.spans.remove(0).1; sg.rent_all_mut(|s| { s.span.record("tracing_proxy_ok", &false); }); From 5e86ef682935c27c6be7ff6cad0f9e8e7d4a217f Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 6 May 2020 10:42:37 +0100 Subject: [PATCH 07/75] update registered spans --- primitives/tracing/src/span_dispatch.rs | 46 ++++++++++++------------- 1 file changed, 23 insertions(+), 23 deletions(-) diff --git a/primitives/tracing/src/span_dispatch.rs b/primitives/tracing/src/span_dispatch.rs index 9da6096f8010d..fa87abea90af9 100644 --- a/primitives/tracing/src/span_dispatch.rs +++ b/primitives/tracing/src/span_dispatch.rs @@ -19,29 +19,29 @@ macro_rules! span_dispatch { pub fn create_registered_span(target: &str, name: &str) -> Result { span_dispatch! { target, name, { - "frame_executive","execute_block_WASM"; - "frame_executive","apply_extrinsic_with_len_WASM"; - "pallet_scheduler","on_initialize_WASM"; - "pallet_society","on_initialize_WASM"; - "pallet_randomness_collective_flip","on_initialize_WASM"; - "pallet_offences","on_initialize_WASM"; - "pallet_treasury","on_initialize_WASM"; - "pallet_elections_phragmen","on_initialize_WASM"; - "pallet_democracy","on_initialize_WASM"; - "pallet_session","on_initialize_WASM"; - "pallet_staking","on_initialize_WASM"; - "pallet_indices","on_initialize_WASM"; - "pallet_authorship","on_initialize_WASM"; - "pallet_babe","on_initialize_WASM"; - "pallet_grandpa","on_finalize_WASM"; - "pallet_finality_tracker","on_finalize_WASM"; - "pallet_staking","on_finalize_WASM"; - "pallet_transaction_payment","on_finalize_WASM"; - "pallet_authorship","on_finalize_WASM"; - "pallet_timestamp","on_finalize_WASM"; - "pallet_babe","on_finalize_WASM"; - "pallet_timestamp","set_WASM"; - "pallet_finality_tracker","final_hint_WASM"; + "frame_executive","execute_block_wasm"; + "frame_executive","apply_extrinsic_with_len_wasm"; + "pallet_scheduler","on_initialize_wasm"; + "pallet_society","on_initialize_wasm"; + "pallet_randomness_collective_flip","on_initialize_wasm"; + "pallet_offences","on_initialize_wasm"; + "pallet_treasury","on_initialize_wasm"; + "pallet_elections_phragmen","on_initialize_wasm"; + "pallet_democracy","on_initialize_wasm"; + "pallet_session","on_initialize_wasm"; + "pallet_staking","on_initialize_wasm"; + "pallet_indices","on_initialize_wasm"; + "pallet_authorship","on_initialize_wasm"; + "pallet_babe","on_initialize_wasm"; + "pallet_grandpa","on_finalize_wasm"; + "pallet_finality_tracker","on_finalize_wasm"; + "pallet_staking","on_finalize_wasm"; + "pallet_transaction_payment","on_finalize_wasm"; + "pallet_authorship","on_finalize_wasm"; + "pallet_timestamp","on_finalize_wasm"; + "pallet_babe","on_finalize_wasm"; + "pallet_timestamp","set_wasm"; + "pallet_finality_tracker","final_hint_wasm"; } } } From 35706caded382cca2e0c3f86b645089a5e7db511 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 6 May 2020 11:25:47 +0100 Subject: [PATCH 08/75] tidy up --- primitives/io/src/lib.rs | 5 ----- primitives/tracing/src/proxy.rs | 6 ------ primitives/tracing/src/span_dispatch.rs | 6 ++++-- 3 files changed, 4 insertions(+), 13 deletions(-) diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index 6841bfc612275..df49c2542bea1 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -872,11 +872,6 @@ pub trait WasmTracing { fn exit_span(id: u64) { sp_tracing::proxy::exit_span(id); } - -// fn record_info_u64(id: u64, key: &str, value: &u64) { -// sp_tracing::record_event(id, &format!("{} = {}", key, value)); -// } - } /// Wasm-only interface that provides functions for interacting with the sandbox. diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index 47db9d7b38d13..4a4ab36fb19c3 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -110,10 +110,4 @@ impl TracingProxy { } } } - -// fn record_info(&mut self, id: u64, info: &str) { -// if let Some(mut sg) = self.spans.get_mut(&id) { -// sg.rent_all_mut(|s| { s.span.record("info", &info); }); -// } -// } } diff --git a/primitives/tracing/src/span_dispatch.rs b/primitives/tracing/src/span_dispatch.rs index fa87abea90af9..472ce108d54d5 100644 --- a/primitives/tracing/src/span_dispatch.rs +++ b/primitives/tracing/src/span_dispatch.rs @@ -1,4 +1,4 @@ -use tracing::{span, field, Level}; +use tracing::{span, Level}; macro_rules! span_dispatch { ($target:tt, $name:tt, { $($registered_target:tt,$registered_name:tt;)* }) => { @@ -15,7 +15,9 @@ macro_rules! span_dispatch { } } -/// Spans (target/name pairs) must be pre-registered here +/// Spans (target/name pairs) must be pre-registered here. +/// To be compatible with earlier on-chain versions of the runtime, +/// it is necessary to keep target/name pairs, even if not used in the current runtime. pub fn create_registered_span(target: &str, name: &str) -> Result { span_dispatch! { target, name, { From 1388002201f1efce201b0a1056c3db162efb79c9 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 6 May 2020 11:32:49 +0100 Subject: [PATCH 09/75] typos --- frame/support/src/wasm_tracing.rs | 4 ++-- primitives/tracing/src/span_dispatch.rs | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index 77e317e52ab89..b0ca88ce590e3 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -19,8 +19,8 @@ //! Facilitated by `sp_io::wasm_tracing` -/// This is holds a span id and is to signal on drop that a tracing span has exited -/// It must be bound to a named variable eg. `_span_guard` +/// This holds a tracing span id and is to signal on drop that a tracing span has exited. +/// It must be bound to a named variable eg. `_span_guard`. pub struct TracingSpanGuard(pub u64); impl Drop for TracingSpanGuard { diff --git a/primitives/tracing/src/span_dispatch.rs b/primitives/tracing/src/span_dispatch.rs index 472ce108d54d5..e6de90e714103 100644 --- a/primitives/tracing/src/span_dispatch.rs +++ b/primitives/tracing/src/span_dispatch.rs @@ -16,7 +16,7 @@ macro_rules! span_dispatch { } /// Spans (target/name pairs) must be pre-registered here. -/// To be compatible with earlier on-chain versions of the runtime, +/// To allow tracing with earlier on-chain versions of the runtime, /// it is necessary to keep target/name pairs, even if not used in the current runtime. pub fn create_registered_span(target: &str, name: &str) -> Result { span_dispatch! { From 41964e7f2a3dab7686e1203e38d5b7d82c9ff7c4 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 6 May 2020 11:45:51 +0100 Subject: [PATCH 10/75] refactor --- frame/support/src/wasm_tracing.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index b0ca88ce590e3..8201fcda2c34e 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -45,4 +45,4 @@ macro_rules! wasm_tracing_span { $crate::sp_io::wasm_tracing::enter_span($target, $name) ); } -} \ No newline at end of file +} From ad81d3bea14ce81a4edac2f4a189e6c118d82658 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 6 May 2020 14:27:50 +0100 Subject: [PATCH 11/75] update flag name to signal lost trace - `is_valid_trace` --- frame/support/src/wasm_tracing.rs | 1 + primitives/tracing/src/proxy.rs | 6 +++--- primitives/tracing/src/span_dispatch.rs | 2 +- 3 files changed, 5 insertions(+), 4 deletions(-) diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index 8201fcda2c34e..acd8a1a2a9305 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -35,6 +35,7 @@ impl Drop for TracingSpanGuard { /// # Example /// /// ``` +/// # use frame_support::wasm_tracing; /// wasm_tracing_span!("target", "fn_name"); /// ``` #[macro_export] diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index 4a4ab36fb19c3..7767a5b45a9dc 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -79,9 +79,9 @@ impl TracingProxy { // 1. Too many nested spans, or MAX_SPANS_LEN is too low. // 2. Not correctly exiting spans due to drop impl not running (panic in runtime) // 3. Not correctly exiting spans due to misconfiguration / misuse - log::warn!("MAX_SPANS_LEN exceeded, removing oldest span, recording `sp_profiler_ok = false`"); + log::warn!("MAX_SPANS_LEN exceeded, removing oldest span, recording `is_valid_trace = false`"); let mut sg = self.spans.remove(0).1; - sg.rent_all_mut(|s| { s.span.record("tracing_proxy_ok", &false); }); + sg.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); } id } @@ -96,7 +96,7 @@ impl TracingProxy { if let Some(mut s) = self.spans.pop() { last_span_id = s.0; if id != last_span_id { - s.1.rent_all_mut(|s| { s.span.record("tracing_proxy_ok", &false); }); + s.1.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); } } else { log::warn!("Span id not found {}", id); diff --git a/primitives/tracing/src/span_dispatch.rs b/primitives/tracing/src/span_dispatch.rs index e6de90e714103..b7caa7a256e9c 100644 --- a/primitives/tracing/src/span_dispatch.rs +++ b/primitives/tracing/src/span_dispatch.rs @@ -4,7 +4,7 @@ macro_rules! span_dispatch { ($target:tt, $name:tt, { $($registered_target:tt,$registered_name:tt;)* }) => { match ($target, $name) { $( - ($registered_target, $registered_name) => Ok(span!(target: $registered_target, Level::INFO, $registered_name, sp_profiler_ok = true)), + ($registered_target, $registered_name) => Ok(span!(target: $registered_target, Level::INFO, $registered_name, is_valid_trace = true)), )* _ => { Err(format!("Trying to profile span target: {}, name: {} that is not registered", From 2cb66bfad2f70db9fe825584c7a721cdf467d4b0 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 6 May 2020 14:31:00 +0100 Subject: [PATCH 12/75] update flag name to signal lost trace - `is_valid_trace` --- primitives/tracing/src/proxy.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index 7767a5b45a9dc..10e049b74925b 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -37,7 +37,7 @@ pub struct TracingProxy { impl Drop for TracingProxy { fn drop(&mut self) { while let Some((_, mut sg)) = self.spans.pop() { - sg.rent_all_mut(|s| { s.span.record("tracing_proxy_ok", &false); }); + sg.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); } } } From 03b7b6ed123b2f23957f782a489b7f6e2cd767fb Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 6 May 2020 16:01:20 +0100 Subject: [PATCH 13/75] update docs --- primitives/tracing/src/proxy.rs | 23 +++++++++++++++++++++-- primitives/tracing/src/span_dispatch.rs | 16 ++++++++++++++++ 2 files changed, 37 insertions(+), 2 deletions(-) diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index 10e049b74925b..9aa3e678c899c 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -1,3 +1,19 @@ +// Copyright 2020 Parity Technologies (UK) Ltd. +// This file is part of Substrate. + +// Substrate is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. + +// Substrate is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. + +// You should have received a copy of the GNU General Public License +// along with Substrate. If not, see . + use std::cell::RefCell; use rental; @@ -9,10 +25,13 @@ thread_local! { static PROXY: RefCell = RefCell::new(TracingProxy::new()); } +/// Create and enter a `tracing` Span, returning the span id, +/// which should be passed to `exit_span(id)` to signal that the span should exit. pub fn create_registered_span(target: &str, name: &str) -> u64 { PROXY.with(|proxy| proxy.borrow_mut().create_registered_span(target, name)) } +/// Exit a span by dropping it along with it's associated guard. pub fn exit_span(id: u64) { PROXY.with(|proxy| proxy.borrow_mut().exit_span(id)); } @@ -28,7 +47,7 @@ rental! { } /// Requires a tracing::Subscriber to process span traces, -/// this is available when running with client (and relevant cli params) +/// this is available when running with client (and relevant cli params). pub struct TracingProxy { next_id: u64, spans: Vec<(u64, rent_span::SpanAndGuard)>, @@ -53,7 +72,7 @@ impl TracingProxy { } } -/// For spans to be recorded they must be registered in `span_dispatch` +/// For spans to be recorded they must be registered in `span_dispatch`. impl TracingProxy { fn create_registered_span(&mut self, target: &str, name: &str) -> u64 { let create_span: Result = span_dispatch::create_registered_span(target, name); diff --git a/primitives/tracing/src/span_dispatch.rs b/primitives/tracing/src/span_dispatch.rs index b7caa7a256e9c..042704b9cbaf5 100644 --- a/primitives/tracing/src/span_dispatch.rs +++ b/primitives/tracing/src/span_dispatch.rs @@ -1,3 +1,19 @@ +// Copyright 2020 Parity Technologies (UK) Ltd. +// This file is part of Substrate. + +// Substrate is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. + +// Substrate is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. + +// You should have received a copy of the GNU General Public License +// along with Substrate. If not, see . + use tracing::{span, Level}; macro_rules! span_dispatch { From 16b018ce3fb8dd56a9ffb39b6fb42518cc64796a Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 6 May 2020 18:57:34 +0100 Subject: [PATCH 14/75] update docs --- frame/support/src/wasm_tracing.rs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index acd8a1a2a9305..0ddb654eef99d 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -35,8 +35,7 @@ impl Drop for TracingSpanGuard { /// # Example /// /// ``` -/// # use frame_support::wasm_tracing; -/// wasm_tracing_span!("target", "fn_name"); +/// frame_support::wasm_tracing_span!("target", "fn_name"); /// ``` #[macro_export] macro_rules! wasm_tracing_span { From d2af83ddc98eac2edb991e5a4a619259f6311af3 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 7 May 2020 15:50:23 +0100 Subject: [PATCH 15/75] Use tracing Field recording to store the actual `name` and `target` from wasm traces. --- Cargo.lock | 1 + client/tracing/Cargo.toml | 4 +- client/tracing/src/lib.rs | 29 +++++++---- primitives/tracing/src/lib.rs | 11 ++++- primitives/tracing/src/proxy.rs | 46 ++++++++--------- primitives/tracing/src/span_dispatch.rs | 65 ------------------------- 6 files changed, 53 insertions(+), 103 deletions(-) delete mode 100644 primitives/tracing/src/span_dispatch.rs diff --git a/Cargo.lock b/Cargo.lock index c0c727334a7f2..3f39bff898a2c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6788,6 +6788,7 @@ dependencies = [ "serde", "serde_json", "slog", + "sp-tracing", "tracing", "tracing-core", ] diff --git a/client/tracing/Cargo.toml b/client/tracing/Cargo.toml index 6417ce8dd70ed..9b8d3acbf3d8d 100644 --- a/client/tracing/Cargo.toml +++ b/client/tracing/Cargo.toml @@ -15,14 +15,14 @@ targets = ["x86_64-unknown-linux-gnu"] erased-serde = "0.3.9" log = { version = "0.4.8" } parking_lot = "0.10.0" +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" -rustc-hash = "1.1.0" - sc-telemetry = { version = "2.0.0-dev", path = "../telemetry" } +sp-tracing = { version = "2.0.0-dev", path = "../../primitives/tracing" } [dev-dependencies] tracing = "0.1.10" diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 2416a86a2160e..954cf3833e72b 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -43,6 +43,8 @@ use tracing_core::{ use sc_telemetry::{telemetry, SUBSTRATE_INFO}; +use sp_tracing::proxy::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER}; + /// Used to configure how to receive the metrics #[derive(Debug, Clone)] pub enum TracingReceiver { @@ -61,8 +63,8 @@ impl Default for TracingReceiver { #[derive(Debug)] struct SpanDatum { id: u64, - name: &'static str, - target: &'static str, + name: String, + target: String, level: Level, line: u32, start_time: Instant, @@ -71,7 +73,7 @@ struct SpanDatum { } #[derive(Clone, Debug)] -struct Visitor(Vec<(String, String)>); +struct Visitor(FxHashMap); impl Visit for Visitor { fn record_i64(&mut self, field: &Field, value: i64) { @@ -87,7 +89,7 @@ impl Visit for Visitor { } fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { - self.0.push((field.name().to_string(), format!("{:?}",value))); + self.0.insert(field.name().to_string(), format!("{:?}",value)); } } @@ -186,12 +188,12 @@ impl Subscriber for ProfilingSubscriber { fn new_span(&self, attrs: &Attributes<'_>) -> Id { let id = self.next_id.fetch_add(1, Ordering::Relaxed); - let mut values = Visitor(Vec::new()); + let mut values = Visitor(FxHashMap::default()); attrs.record(&mut values); let span_datum = SpanDatum { id, - name: attrs.metadata().name(), - target: attrs.metadata().target(), + name: attrs.metadata().name().to_owned(), + target: attrs.metadata().target().to_owned(), level: attrs.metadata().level().clone(), line: attrs.metadata().line().unwrap_or(0), start_time: Instant::now(), @@ -235,8 +237,17 @@ impl Subscriber for ProfilingSubscriber { fn try_close(&self, span: Id) -> bool { let mut span_data = self.span_data.lock(); - if let Some(data) = span_data.remove(&span.into_u64()) { - self.send_span(data); + if let Some(mut span_datum) = span_data.remove(&span.into_u64()) { + drop(span_data); + if span_datum.name == WASM_TRACE_IDENTIFIER { + if let Some(n) = span_datum.values.0.remove(WASM_NAME_KEY) { + span_datum.name = n; + } + if let Some(t) = span_datum.values.0.remove(WASM_TARGET_KEY) { + span_datum.target = t; + } + } + self.send_span(span_datum); }; true } diff --git a/primitives/tracing/src/lib.rs b/primitives/tracing/src/lib.rs index 01ec236be4c3b..5600fed6e294c 100644 --- a/primitives/tracing/src/lib.rs +++ b/primitives/tracing/src/lib.rs @@ -18,6 +18,15 @@ //! //! To trace functions or invidual code in Substrate, this crate provides [`tracing_span`] //! and [`enter_span`]. See the individual docs for how to use these macros. +//! +//! Note that to allow traces from wasm execution environment there are +//! 2 reserved identifiers for tracing `Field` recording, stored in the consts: +//! `WASM_TARGET_KEY` and `WASM_NAME_KEY` - if you choose to record fields, you +//! must ensure that your identifiers do not clash with either of these. +//! +//! Additionally, we have a const: `WASM_TRACE_IDENTIFIER`, which holds a span name used +//! to signal that the 'actual' span name and target should be retrieved instead from +//! the associated Fields mentioned above. #![cfg_attr(not(feature = "std"), no_std)] #[cfg(feature = "std")] @@ -30,8 +39,6 @@ pub use tracing; #[cfg(feature = "std")] pub mod proxy; -#[cfg(feature = "std")] -mod span_dispatch; /// Runs given code within a tracing span, measuring it's execution time. /// diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index 9aa3e678c899c..c4af6fe4ae669 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -16,8 +16,14 @@ use std::cell::RefCell; use rental; +use tracing::info_span; -use crate::span_dispatch; +/// Used to identify a proxied WASM trace +pub const WASM_TRACE_IDENTIFIER: &'static str = "WASM_TRACE"; +/// Used to extract the real `target` from the associated values of the span +pub const WASM_TARGET_KEY: &'static str = "proxied_wasm_target"; +/// Used to extract the real `name` from the associated values of the span +pub const WASM_NAME_KEY: &'static str = "proxied_wasm_name"; const MAX_SPANS_LEN: usize = 1000; @@ -28,7 +34,7 @@ thread_local! { /// Create and enter a `tracing` Span, returning the span id, /// which should be passed to `exit_span(id)` to signal that the span should exit. pub fn create_registered_span(target: &str, name: &str) -> u64 { - PROXY.with(|proxy| proxy.borrow_mut().create_registered_span(target, name)) + PROXY.with(|proxy| proxy.borrow_mut().create_span(target, name)) } /// Exit a span by dropping it along with it's associated guard. @@ -65,8 +71,7 @@ impl TracingProxy { pub fn new() -> TracingProxy { let spans: Vec<(u64, rent_span::SpanAndGuard)> = Vec::new(); TracingProxy { - // Span ids start from 1 - we will use 0 as special case for unregistered spans - next_id: 1, + next_id: 0, spans, } } @@ -74,24 +79,16 @@ impl TracingProxy { /// For spans to be recorded they must be registered in `span_dispatch`. impl TracingProxy { - fn create_registered_span(&mut self, target: &str, name: &str) -> u64 { - let create_span: Result = span_dispatch::create_registered_span(target, name); - let id; - match create_span { - Ok(span) => { - self.next_id += 1; - id = self.next_id; - let sg = rent_span::SpanAndGuard::new( - Box::new(span), - |span| span.enter(), - ); - self.spans.push((id, sg)); - } - Err(e) => { - id = 0; - log::info!("{}", e); - } - } + // The identifiers `wasm_target` and `wasm_name` must match their associated const, + // WASM_TARGET_KEY and WASM_NAME_KEY. + fn create_span(&mut self, proxied_wasm_target: &str, proxied_wasm_name: &str) -> u64 { + let span = info_span!(WASM_TRACE_IDENTIFIER, is_valid_trace = true, proxied_wasm_target, proxied_wasm_name); + self.next_id += 1; + let sg = rent_span::SpanAndGuard::new( + Box::new(span), + |span| span.enter(), + ); + self.spans.push((self.next_id, sg)); let spans_len = self.spans.len(); if spans_len > MAX_SPANS_LEN { // This is to prevent unbounded growth of Vec and could mean one of the following: @@ -102,11 +99,10 @@ impl TracingProxy { let mut sg = self.spans.remove(0).1; sg.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); } - id + self.next_id } fn exit_span(&mut self, id: u64) { - if id == 0 { return; } match self.spans.pop() { Some(v) => { let mut last_span_id = v.0; @@ -122,7 +118,7 @@ impl TracingProxy { return; } } - }, + } None => { log::warn!("Span id: {} not found", id); return; diff --git a/primitives/tracing/src/span_dispatch.rs b/primitives/tracing/src/span_dispatch.rs deleted file mode 100644 index 042704b9cbaf5..0000000000000 --- a/primitives/tracing/src/span_dispatch.rs +++ /dev/null @@ -1,65 +0,0 @@ -// Copyright 2020 Parity Technologies (UK) Ltd. -// This file is part of Substrate. - -// Substrate is free software: you can redistribute it and/or modify -// it under the terms of the GNU General Public License as published by -// the Free Software Foundation, either version 3 of the License, or -// (at your option) any later version. - -// Substrate is distributed in the hope that it will be useful, -// but WITHOUT ANY WARRANTY; without even the implied warranty of -// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the -// GNU General Public License for more details. - -// You should have received a copy of the GNU General Public License -// along with Substrate. If not, see . - -use tracing::{span, Level}; - -macro_rules! span_dispatch { - ($target:tt, $name:tt, { $($registered_target:tt,$registered_name:tt;)* }) => { - match ($target, $name) { - $( - ($registered_target, $registered_name) => Ok(span!(target: $registered_target, Level::INFO, $registered_name, is_valid_trace = true)), - )* - _ => { - Err(format!("Trying to profile span target: {}, name: {} that is not registered", - $target, - $name)) - } - } - } -} - -/// Spans (target/name pairs) must be pre-registered here. -/// To allow tracing with earlier on-chain versions of the runtime, -/// it is necessary to keep target/name pairs, even if not used in the current runtime. -pub fn create_registered_span(target: &str, name: &str) -> Result { - span_dispatch! { - target, name, { - "frame_executive","execute_block_wasm"; - "frame_executive","apply_extrinsic_with_len_wasm"; - "pallet_scheduler","on_initialize_wasm"; - "pallet_society","on_initialize_wasm"; - "pallet_randomness_collective_flip","on_initialize_wasm"; - "pallet_offences","on_initialize_wasm"; - "pallet_treasury","on_initialize_wasm"; - "pallet_elections_phragmen","on_initialize_wasm"; - "pallet_democracy","on_initialize_wasm"; - "pallet_session","on_initialize_wasm"; - "pallet_staking","on_initialize_wasm"; - "pallet_indices","on_initialize_wasm"; - "pallet_authorship","on_initialize_wasm"; - "pallet_babe","on_initialize_wasm"; - "pallet_grandpa","on_finalize_wasm"; - "pallet_finality_tracker","on_finalize_wasm"; - "pallet_staking","on_finalize_wasm"; - "pallet_transaction_payment","on_finalize_wasm"; - "pallet_authorship","on_finalize_wasm"; - "pallet_timestamp","on_finalize_wasm"; - "pallet_babe","on_finalize_wasm"; - "pallet_timestamp","set_wasm"; - "pallet_finality_tracker","final_hint_wasm"; - } - } -} From 9f8baf294b00f8419e5e2901c2abb59006425ebb Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 7 May 2020 18:01:28 +0100 Subject: [PATCH 16/75] fix debug log in subscriber + small refactor --- client/tracing/src/lib.rs | 17 +++++++++-------- 1 file changed, 9 insertions(+), 8 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 954cf3833e72b..91451f5cecd1e 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -38,7 +38,7 @@ use tracing_core::{ Level, metadata::Metadata, span::{Attributes, Id, Record}, - subscriber::Subscriber + subscriber::Subscriber, }; use sc_telemetry::{telemetry, SUBSTRATE_INFO}; @@ -89,7 +89,7 @@ impl Visit for Visitor { } fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { - self.0.insert(field.name().to_string(), format!("{:?}",value)); + self.0.insert(field.name().to_string(), format!("{:?}", value)); } } @@ -107,7 +107,7 @@ impl Serialize for Visitor { impl fmt::Display for Visitor { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - let values = self.0.iter().map(|(k,v)| format!("{}={}",k,v)).collect::>().join(", "); + let values = self.0.iter().map(|(k, v)| format!("{}={}", k, v)).collect::>().join(", "); write!(f, "{}", values) } } @@ -179,10 +179,9 @@ impl Subscriber for ProfilingSubscriber { if metadata.target().starts_with(t.0.as_str()) && metadata.level() <= &t.1 { log::debug!("Enabled target: {}, level: {}", metadata.target(), metadata.level()); return true; - } else { - log::debug!("Disabled target: {}, level: {}", metadata.target(), metadata.level()); } } + log::debug!("Disabled target: {}, level: {}", metadata.target(), metadata.level()); false } @@ -236,9 +235,11 @@ impl Subscriber for ProfilingSubscriber { } fn try_close(&self, span: Id) -> bool { - let mut span_data = self.span_data.lock(); - if let Some(mut span_datum) = span_data.remove(&span.into_u64()) { - drop(span_data); + let span_datum = { + let mut span_data = self.span_data.lock(); + span_data.remove(&span.into_u64()) + }; + if let Some(mut span_datum) = span_datum { if span_datum.name == WASM_TRACE_IDENTIFIER { if let Some(n) = span_datum.values.0.remove(WASM_NAME_KEY) { span_datum.name = n; From 1199f36d0e44fa70b5b795347534954d70e4901d Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 11 May 2020 13:10:24 +0100 Subject: [PATCH 17/75] add tests --- primitives/tracing/src/proxy.rs | 37 +++++++++++++++++++++++++++++++++ 1 file changed, 37 insertions(+) diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index c4af6fe4ae669..ca254e3f5dd65 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -126,3 +126,40 @@ impl TracingProxy { } } } + +#[cfg(test)] +mod tests { + use super::*; + + fn create_spans(proxy: &mut TracingProxy, qty: usize) -> Vec{ + let mut spans = Vec::new(); + for n in 0..qty { + spans.push(proxy.create_span("target", &format!("{}", n))); + } + spans + } + + #[test] + fn max_spans_len_respected() { + let mut proxy = TracingProxy::new(); + let _spans = create_spans(&mut proxy, MAX_SPANS_LEN + 10); + assert_eq!(proxy.spans.len(), MAX_SPANS_LEN); + // ensure oldest spans removed + assert_eq!(proxy.spans[0].0, 11); + } + + #[test] + fn handles_span_exit_scenarios() { + let mut proxy = TracingProxy::new(); + let _spans = create_spans(&mut proxy, 10); + assert_eq!(proxy.spans.len(), 10); + // exit span normally + proxy.exit_span(10); + assert_eq!(proxy.spans.len(), 9); + // skip and exit outer span without exiting inner, 9 instead of 10 + proxy.exit_span(8); + // should have also removed the inner span that was lost + assert_eq!(proxy.spans.len(), 7); + } + +} \ No newline at end of file From 0c61f792ddfe0c86dbc1f7ef9c4d60f8d8cb28b6 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 11 May 2020 16:05:09 +0100 Subject: [PATCH 18/75] handle misuse in case trying to exit span not held --- primitives/tracing/src/proxy.rs | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index ca254e3f5dd65..f61944e49a787 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -106,6 +106,11 @@ impl TracingProxy { match self.spans.pop() { Some(v) => { let mut last_span_id = v.0; + if id > last_span_id { + log::warn!("Span id not found {}", id); + self.spans.push(v); + return; + } while id < last_span_id { log::warn!("Span ids not equal! id parameter given: {}, last span: {}", id, last_span_id); if let Some(mut s) = self.spans.pop() { @@ -131,7 +136,7 @@ impl TracingProxy { mod tests { use super::*; - fn create_spans(proxy: &mut TracingProxy, qty: usize) -> Vec{ + fn create_spans(proxy: &mut TracingProxy, qty: usize) -> Vec { let mut spans = Vec::new(); for n in 0..qty { spans.push(proxy.create_span("target", &format!("{}", n))); @@ -156,10 +161,12 @@ mod tests { // exit span normally proxy.exit_span(10); assert_eq!(proxy.spans.len(), 9); - // skip and exit outer span without exiting inner, 9 instead of 10 + // skip and exit outer span without exiting inner, id: 8 instead of 9 proxy.exit_span(8); // should have also removed the inner span that was lost assert_eq!(proxy.spans.len(), 7); + // try to exit span not held + proxy.exit_span(9); + assert_eq!(proxy.spans.len(), 7); } - } \ No newline at end of file From 8061da5625f213d5462d123e89fb5319342e836d Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 11 May 2020 17:09:41 +0100 Subject: [PATCH 19/75] Implement filter for wasm traces, simplify field recording for primitive types --- client/tracing/src/lib.rs | 41 ++++++++++++++++++++++++++------------- 1 file changed, 27 insertions(+), 14 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 91451f5cecd1e..c6a923b68a477 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -77,15 +77,19 @@ struct Visitor(FxHashMap); impl Visit for Visitor { fn record_i64(&mut self, field: &Field, value: i64) { - self.record_debug(field, &value) + self.0.insert(field.name().to_string(), value.to_string()); } fn record_u64(&mut self, field: &Field, value: u64) { - self.record_debug(field, &value) + self.0.insert(field.name().to_string(), value.to_string()); } fn record_bool(&mut self, field: &Field, value: bool) { - self.record_debug(field, &value) + self.0.insert(field.name().to_string(), value.to_string()); + } + + fn record_str(&mut self, field: &Field, value: &str) { + self.0.insert(field.name().to_string(), value.to_owned()); } fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { @@ -154,6 +158,17 @@ impl ProfilingSubscriber { span_data: Mutex::new(FxHashMap::default()), } } + + fn check_target(&self, target: &str, level: &Level) -> bool { + for t in &self.targets { + if target.starts_with(t.0.as_str()) && level <= &t.1 { + log::debug!("Enabled target: {}, level: {}", target, level); + return true; + } + } + log::debug!("Disabled target: {}, level: {}", target, level); + false + } } // Default to TRACE if no level given or unable to parse Level @@ -175,20 +190,20 @@ fn parse_target(s: &str) -> (String, Level) { impl Subscriber for ProfilingSubscriber { fn enabled(&self, metadata: &Metadata<'_>) -> bool { - for t in &self.targets { - if metadata.target().starts_with(t.0.as_str()) && metadata.level() <= &t.1 { - log::debug!("Enabled target: {}, level: {}", metadata.target(), metadata.level()); - return true; - } - } - log::debug!("Disabled target: {}, level: {}", metadata.target(), metadata.level()); - false + if metadata.target() == WASM_TARGET_KEY { return true } + self.check_target(metadata.target(), metadata.level()) } fn new_span(&self, attrs: &Attributes<'_>) -> Id { let id = self.next_id.fetch_add(1, Ordering::Relaxed); let mut values = Visitor(FxHashMap::default()); attrs.record(&mut values); + // If this is a wasm trace, check if target/level is enabled + if let Some(wasm_target) = values.0.get(WASM_TARGET_KEY) { + if !self.check_target(wasm_target, attrs.metadata().level()) { + return Id::from_u64(id); + } + } let span_datum = SpanDatum { id, name: attrs.metadata().name().to_owned(), @@ -221,14 +236,12 @@ impl Subscriber for ProfilingSubscriber { let start_time = Instant::now(); if let Some(mut s) = span_data.get_mut(&span.into_u64()) { s.start_time = start_time; - } else { - log::warn!("Tried to enter span {:?} that has already been closed!", span); } } fn exit(&self, span: &Id) { - let mut span_data = self.span_data.lock(); 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()) { s.overall_time = end_time - s.start_time + s.overall_time; } From 2097aca00c6c6398525fa07c745dddf02478012a Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 11 May 2020 17:28:54 +0100 Subject: [PATCH 20/75] remove superfluous warning --- client/tracing/src/lib.rs | 2 -- 1 file changed, 2 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index c6a923b68a477..d164c60e98a70 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -222,8 +222,6 @@ impl Subscriber for ProfilingSubscriber { let mut span_data = self.span_data.lock(); if let Some(s) = span_data.get_mut(&span.into_u64()) { values.record(&mut s.values); - } else { - log::warn!("Tried to record to span `{:?}` that has already been closed!", span); } } From 1ef18e6c88e5affd141a9894b74530023b0fd378 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 11 May 2020 18:42:08 +0100 Subject: [PATCH 21/75] update docs --- primitives/tracing/src/proxy.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index f61944e49a787..062889a64b02e 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -79,7 +79,7 @@ impl TracingProxy { /// For spans to be recorded they must be registered in `span_dispatch`. impl TracingProxy { - // The identifiers `wasm_target` and `wasm_name` must match their associated const, + // The identifiers `proxied_wasm_target` and `proxied_wasm_name` must match their associated const, // WASM_TARGET_KEY and WASM_NAME_KEY. fn create_span(&mut self, proxied_wasm_target: &str, proxied_wasm_name: &str) -> u64 { let span = info_span!(WASM_TRACE_IDENTIFIER, is_valid_trace = true, proxied_wasm_target, proxied_wasm_name); From 460d24d6ab25f33fddaf1b4ad1cc4f097bb55b45 Mon Sep 17 00:00:00 2001 From: mattrutherford <44339188+mattrutherford@users.noreply.github.com> Date: Wed, 13 May 2020 11:55:18 +0100 Subject: [PATCH 22/75] Update primitives/tracing/src/proxy.rs Co-authored-by: Kian Paimani <5588131+kianenigma@users.noreply.github.com> --- primitives/tracing/src/proxy.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index 062889a64b02e..7af8a2f34beb0 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -169,4 +169,4 @@ mod tests { proxy.exit_span(9); assert_eq!(proxy.spans.len(), 7); } -} \ No newline at end of file +} From 85bdbe0ddabc2dd4c6b5bcd387340d23a14b05b4 Mon Sep 17 00:00:00 2001 From: mattrutherford <44339188+mattrutherford@users.noreply.github.com> Date: Wed, 13 May 2020 14:53:09 +0100 Subject: [PATCH 23/75] 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 | 4 +--- primitives/tracing/src/proxy.rs | 5 ++++- 2 files changed, 5 insertions(+), 4 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index d164c60e98a70..ea6297f9953bc 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -190,8 +190,7 @@ fn parse_target(s: &str) -> (String, Level) { impl Subscriber for ProfilingSubscriber { fn enabled(&self, metadata: &Metadata<'_>) -> bool { - if metadata.target() == WASM_TARGET_KEY { return true } - self.check_target(metadata.target(), metadata.level()) + metadata.target() == WASM_TARGET_KEY || self.check_target(metadata.target(), metadata.level()) } fn new_span(&self, attrs: &Attributes<'_>) -> Id { @@ -304,4 +303,3 @@ fn send_telemetry(span_datum: SpanDatum) { "values" => span_datum.values ); } - diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index 7af8a2f34beb0..e3f899483ebb6 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -95,7 +95,10 @@ impl TracingProxy { // 1. Too many nested spans, or MAX_SPANS_LEN is too low. // 2. Not correctly exiting spans due to drop impl not running (panic in runtime) // 3. Not correctly exiting spans due to misconfiguration / misuse - log::warn!("MAX_SPANS_LEN exceeded, removing oldest span, recording `is_valid_trace = false`"); + log::warn!( + target: "tracing", + "MAX_SPANS_LEN exceeded, removing oldest span, recording `is_valid_trace = false`", + ); let mut sg = self.spans.remove(0).1; sg.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); } From b9d1fdf37c9710ac3e962a837a0abbfb6c293070 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 14 May 2020 13:31:33 +0100 Subject: [PATCH 24/75] update docs, apply suggestions --- frame/support/src/wasm_tracing.rs | 10 +++++-- primitives/io/src/lib.rs | 6 ++--- primitives/tracing/src/proxy.rs | 45 ++++++++++++++----------------- 3 files changed, 30 insertions(+), 31 deletions(-) diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index 0ddb654eef99d..80178bb65400c 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -21,7 +21,13 @@ /// This holds a tracing span id and is to signal on drop that a tracing span has exited. /// It must be bound to a named variable eg. `_span_guard`. -pub struct TracingSpanGuard(pub u64); +pub struct TracingSpanGuard(u64); + +impl TracingSpanGuard { + pub fn new(span: u64) -> Self { + Self(span) + } +} impl Drop for TracingSpanGuard { fn drop(&mut self) { @@ -41,7 +47,7 @@ impl Drop for TracingSpanGuard { macro_rules! wasm_tracing_span { ( $target:expr, $name:expr ) => { #[cfg(not(feature = "std"))] - let __span_id__ = $crate::wasm_tracing::TracingSpanGuard( + let __span_id__ = $crate::wasm_tracing::TracingSpanGuard::new( $crate::sp_io::wasm_tracing::enter_span($target, $name) ); } diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index c71d767a16712..ede34a67cca4c 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -873,11 +873,9 @@ pub trait Logging { /// Interface that provides functions for profiling the runtime. #[runtime_interface] pub trait WasmTracing { - /// For enter_span to work correctly with the Tracing profiler, - /// the span `target` and `name` must also be registered in - /// `sp_tracing::span_dispatch::create_registered_span`. + /// To create and enter a `tracing` span, via `sp_tracing::proxy` fn enter_span(target: &str, name: &str) -> u64 { - sp_tracing::proxy::create_registered_span(target, name) + sp_tracing::proxy::enter_span(target, name) } /// If there is a panic in the WASM VM then this may not be called. diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index e3f899483ebb6..f382fb26a0520 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -14,6 +14,9 @@ // You should have received a copy of the GNU General Public License // along with Substrate. If not, see . +//! Proxy to allow entering tracing spans from wasm. +//! +//! Use `enter_span` and `exit_span` to surround the code that you wish to trace use std::cell::RefCell; use rental; use tracing::info_span; @@ -33,7 +36,7 @@ thread_local! { /// Create and enter a `tracing` Span, returning the span id, /// which should be passed to `exit_span(id)` to signal that the span should exit. -pub fn create_registered_span(target: &str, name: &str) -> u64 { +pub fn enter_span(target: &str, name: &str) -> u64 { PROXY.with(|proxy| proxy.borrow_mut().create_span(target, name)) } @@ -77,7 +80,6 @@ impl TracingProxy { } } -/// For spans to be recorded they must be registered in `span_dispatch`. impl TracingProxy { // The identifiers `proxied_wasm_target` and `proxied_wasm_name` must match their associated const, // WASM_TARGET_KEY and WASM_NAME_KEY. @@ -106,35 +108,25 @@ impl TracingProxy { } fn exit_span(&mut self, id: u64) { - match self.spans.pop() { - Some(v) => { - let mut last_span_id = v.0; - if id > last_span_id { - log::warn!("Span id not found {}", id); - self.spans.push(v); - return; - } - while id < last_span_id { - log::warn!("Span ids not equal! id parameter given: {}, last span: {}", id, last_span_id); - if let Some(mut s) = self.spans.pop() { - last_span_id = s.0; - if id != last_span_id { - s.1.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); - } - } else { - log::warn!("Span id not found {}", id); - return; - } - } - } - None => { - log::warn!("Span id: {} not found", id); + if self.spans.last().map(|l| id > l.0).unwrap_or(true) { + log::warn!("Span id not found {}", id); + return; + } + let mut last_span = self.spans.pop().expect("Just checked that there is an element to pop"); + while id < last_span.0 { + log::warn!("Span ids not equal! id parameter given: {}, last span: {}", id, last_span.0); + last_span.1.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); + if let Some(s) = self.spans.pop() { + last_span = s; + } else { + log::warn!("Span id not found {}", id); return; } } } } + #[cfg(test)] mod tests { use super::*; @@ -171,5 +163,8 @@ mod tests { // try to exit span not held proxy.exit_span(9); assert_eq!(proxy.spans.len(), 7); + // exit all spans + proxy.exit_span(1); + assert_eq!(proxy.spans.len(), 0); } } From b66bb338a7eb8e161616ae3b72a83ec22b08efb7 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 14 May 2020 16:50:14 +0100 Subject: [PATCH 25/75] move Proxy from thread_local to `Extension`, rename macro --- frame/support/src/dispatch.rs | 14 +++++++------- frame/support/src/wasm_tracing.rs | 4 ++-- primitives/io/src/lib.rs | 26 ++++++++++++++++++++++---- primitives/tracing/src/proxy.rs | 28 ++++++++-------------------- 4 files changed, 39 insertions(+), 33 deletions(-) diff --git a/frame/support/src/dispatch.rs b/frame/support/src/dispatch.rs index d380c79e6f9d7..ddd592a1210da 100644 --- a/frame/support/src/dispatch.rs +++ b/frame/support/src/dispatch.rs @@ -1023,7 +1023,7 @@ macro_rules! decl_module { { fn on_initialize(_block_number_not_used: $trait_instance::BlockNumber) -> $return { $crate::sp_tracing::enter_span!("on_initialize"); - $crate::wasm_tracing_span!(module_path!(), "on_initialize_wasm"); + $crate::enter_span_wasm!(module_path!(), "on_initialize_wasm"); { $( $impl )* } } } @@ -1040,7 +1040,7 @@ macro_rules! decl_module { { fn on_initialize($param: $param_ty) -> $return { $crate::sp_tracing::enter_span!("on_initialize"); - $crate::wasm_tracing_span!(module_path!(), "on_initialize_wasm"); + $crate::enter_span_wasm!(module_path!(), "on_initialize_wasm"); { $( $impl )* } } } @@ -1067,7 +1067,7 @@ macro_rules! decl_module { { fn on_runtime_upgrade() -> $return { $crate::sp_tracing::enter_span!("on_runtime_upgrade"); - $crate::wasm_tracing_span!(module_path!(), "on_runtime_upgrade_wasm"); + $crate::enter_span_wasm!(module_path!(), "on_runtime_upgrade_wasm"); { $( $impl )* } } } @@ -1095,7 +1095,7 @@ macro_rules! decl_module { { fn on_finalize(_block_number_not_used: $trait_instance::BlockNumber) { $crate::sp_tracing::enter_span!("on_finalize"); - $crate::wasm_tracing_span!(module_path!(), "on_finalize_wasm"); + $crate::enter_span_wasm!(module_path!(), "on_finalize_wasm"); { $( $impl )* } } } @@ -1112,7 +1112,7 @@ macro_rules! decl_module { { fn on_finalize($param: $param_ty) { $crate::sp_tracing::enter_span!("on_finalize"); - $crate::wasm_tracing_span!(module_path!(), "on_finalize_wasm"); + $crate::enter_span_wasm!(module_path!(), "on_finalize_wasm"); { $( $impl )* } } } @@ -1182,7 +1182,7 @@ macro_rules! decl_module { $origin: $origin_ty $(, $param: $param_ty )* ) -> $crate::dispatch::DispatchResult { $crate::sp_tracing::enter_span!(stringify!($name)); - $crate::wasm_tracing_span!(module_path!(), concat!(stringify!($name),"_wasm")); + $crate::enter_span_wasm!(module_path!(), concat!(stringify!($name),"_wasm")); { $( $impl )* } Ok(()) } @@ -1202,7 +1202,7 @@ macro_rules! decl_module { $(#[doc = $doc_attr])* $vis fn $name($origin: $origin_ty $(, $param: $param_ty )* ) -> $result { $crate::sp_tracing::enter_span!(stringify!($name)); - $crate::wasm_tracing_span!(module_path!(), concat!(stringify!($name),"_wasm")); + $crate::enter_span_wasm!(module_path!(), concat!(stringify!($name),"_wasm")); $( $impl )* } }; diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index 80178bb65400c..3e915bfc8d519 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -41,10 +41,10 @@ impl Drop for TracingSpanGuard { /// # Example /// /// ``` -/// frame_support::wasm_tracing_span!("target", "fn_name"); +/// frame_support::enter_span_wasm!("target", "fn_name"); /// ``` #[macro_export] -macro_rules! wasm_tracing_span { +macro_rules! enter_span_wasm { ( $target:expr, $name:expr ) => { #[cfg(not(feature = "std"))] let __span_id__ = $crate::wasm_tracing::TracingSpanGuard::new( diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index ede34a67cca4c..8e381e0beaba6 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -870,18 +870,36 @@ pub trait Logging { } } +#[cfg(feature = "std")] +sp_externalities::decl_extension! { + /// Extension to allow running traces in wasm via Proxy + pub struct TracingProxyExt(sp_tracing::proxy::TracingProxy); +} + /// Interface that provides functions for profiling the runtime. #[runtime_interface] pub trait WasmTracing { /// To create and enter a `tracing` span, via `sp_tracing::proxy` - fn enter_span(target: &str, name: &str) -> u64 { - sp_tracing::proxy::enter_span(target, name) + fn enter_span(&mut self, target: &str, name: &str) -> u64 { + let proxy = match self.extension::() { + Some(proxy) => proxy, + None => { + self.register_extension(TracingProxyExt(sp_tracing::proxy::TracingProxy::new())) + .expect("Failed to register required extension: `TracingProxyExt`"); + self.extension::().expect("Failed to load required extension: `TracingProxyExt`") + } + }; + proxy.enter_span(target, name) } /// If there is a panic in the WASM VM then this may not be called. - fn exit_span(id: u64) { - sp_tracing::proxy::exit_span(id); + fn exit_span(&mut self, id: u64) { + let proxy = self.extension::() + .expect("Failed to load required extension: \ + `TracingProxyExt` which should be loaded before calling `exit_span`"); + proxy.exit_span(id); } + } /// Wasm-only interface that provides functions for interacting with the sandbox. diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index f382fb26a0520..d253a72dde82f 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -17,7 +17,6 @@ //! Proxy to allow entering tracing spans from wasm. //! //! Use `enter_span` and `exit_span` to surround the code that you wish to trace -use std::cell::RefCell; use rental; use tracing::info_span; @@ -30,21 +29,6 @@ pub const WASM_NAME_KEY: &'static str = "proxied_wasm_name"; const MAX_SPANS_LEN: usize = 1000; -thread_local! { - static PROXY: RefCell = RefCell::new(TracingProxy::new()); -} - -/// Create and enter a `tracing` Span, returning the span id, -/// which should be passed to `exit_span(id)` to signal that the span should exit. -pub fn enter_span(target: &str, name: &str) -> u64 { - PROXY.with(|proxy| proxy.borrow_mut().create_span(target, name)) -} - -/// Exit a span by dropping it along with it's associated guard. -pub fn exit_span(id: u64) { - PROXY.with(|proxy| proxy.borrow_mut().exit_span(id)); -} - rental! { pub mod rent_span { #[rental] @@ -64,6 +48,7 @@ pub struct TracingProxy { impl Drop for TracingProxy { fn drop(&mut self) { + log::debug!("Dropping TracingProxy with {} spans", self.spans.len()); while let Some((_, mut sg)) = self.spans.pop() { sg.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); } @@ -81,9 +66,11 @@ impl TracingProxy { } impl TracingProxy { - // The identifiers `proxied_wasm_target` and `proxied_wasm_name` must match their associated const, - // WASM_TARGET_KEY and WASM_NAME_KEY. - fn create_span(&mut self, proxied_wasm_target: &str, proxied_wasm_name: &str) -> u64 { + /// Create and enter a `tracing` Span, returning the span id, + /// which should be passed to `exit_span(id)` to signal that the span should exit. + pub fn enter_span(&mut self, proxied_wasm_target: &str, proxied_wasm_name: &str) -> u64 { + // The identifiers `proxied_wasm_target` and `proxied_wasm_name` must match their associated const, + // WASM_TARGET_KEY and WASM_NAME_KEY. let span = info_span!(WASM_TRACE_IDENTIFIER, is_valid_trace = true, proxied_wasm_target, proxied_wasm_name); self.next_id += 1; let sg = rent_span::SpanAndGuard::new( @@ -107,7 +94,8 @@ impl TracingProxy { self.next_id } - fn exit_span(&mut self, id: u64) { + /// Exit a span by dropping it along with it's associated guard. + pub fn exit_span(&mut self, id: u64) { if self.spans.last().map(|l| id > l.0).unwrap_or(true) { log::warn!("Span id not found {}", id); return; From afa511d1e689fdd92468677064d526e4751f5175 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Fri, 15 May 2020 10:24:05 +0100 Subject: [PATCH 26/75] fix test --- primitives/tracing/src/proxy.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index d253a72dde82f..be609907c4ce2 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -122,7 +122,7 @@ mod tests { fn create_spans(proxy: &mut TracingProxy, qty: usize) -> Vec { let mut spans = Vec::new(); for n in 0..qty { - spans.push(proxy.create_span("target", &format!("{}", n))); + spans.push(proxy.enter_span("target", &format!("{}", n))); } spans } From 93a03a8278729e7b7eb042e4dcf9bdd68e68619f Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Fri, 15 May 2020 14:48:46 +0100 Subject: [PATCH 27/75] unify native & wasm span macro calls --- frame/support/src/dispatch.rs | 21 +++++++-------------- frame/support/src/wasm_tracing.rs | 13 +++++++++---- 2 files changed, 16 insertions(+), 18 deletions(-) diff --git a/frame/support/src/dispatch.rs b/frame/support/src/dispatch.rs index ddd592a1210da..52718a657d37a 100644 --- a/frame/support/src/dispatch.rs +++ b/frame/support/src/dispatch.rs @@ -1022,8 +1022,7 @@ macro_rules! decl_module { for $module<$trait_instance$(, $instance)?> where $( $other_where_bounds )* { fn on_initialize(_block_number_not_used: $trait_instance::BlockNumber) -> $return { - $crate::sp_tracing::enter_span!("on_initialize"); - $crate::enter_span_wasm!(module_path!(), "on_initialize_wasm"); + $crate::enter_span!("on_initialize"); { $( $impl )* } } } @@ -1039,8 +1038,7 @@ macro_rules! decl_module { for $module<$trait_instance$(, $instance)?> where $( $other_where_bounds )* { fn on_initialize($param: $param_ty) -> $return { - $crate::sp_tracing::enter_span!("on_initialize"); - $crate::enter_span_wasm!(module_path!(), "on_initialize_wasm"); + $crate::enter_span!("on_initialize"); { $( $impl )* } } } @@ -1066,8 +1064,7 @@ macro_rules! decl_module { for $module<$trait_instance$(, $instance)?> where $( $other_where_bounds )* { fn on_runtime_upgrade() -> $return { - $crate::sp_tracing::enter_span!("on_runtime_upgrade"); - $crate::enter_span_wasm!(module_path!(), "on_runtime_upgrade_wasm"); + $crate::enter_span!("on_runtime_upgrade"); { $( $impl )* } } } @@ -1094,8 +1091,7 @@ macro_rules! decl_module { for $module<$trait_instance$(, $instance)?> where $( $other_where_bounds )* { fn on_finalize(_block_number_not_used: $trait_instance::BlockNumber) { - $crate::sp_tracing::enter_span!("on_finalize"); - $crate::enter_span_wasm!(module_path!(), "on_finalize_wasm"); + $crate::enter_span!("on_finalize"); { $( $impl )* } } } @@ -1111,8 +1107,7 @@ macro_rules! decl_module { for $module<$trait_instance$(, $instance)?> where $( $other_where_bounds )* { fn on_finalize($param: $param_ty) { - $crate::sp_tracing::enter_span!("on_finalize"); - $crate::enter_span_wasm!(module_path!(), "on_finalize_wasm"); + $crate::enter_span!("on_finalize"); { $( $impl )* } } } @@ -1181,8 +1176,7 @@ macro_rules! decl_module { $vis fn $name( $origin: $origin_ty $(, $param: $param_ty )* ) -> $crate::dispatch::DispatchResult { - $crate::sp_tracing::enter_span!(stringify!($name)); - $crate::enter_span_wasm!(module_path!(), concat!(stringify!($name),"_wasm")); + $crate::enter_span!(stringify!($name)); { $( $impl )* } Ok(()) } @@ -1201,8 +1195,7 @@ macro_rules! decl_module { ) => { $(#[doc = $doc_attr])* $vis fn $name($origin: $origin_ty $(, $param: $param_ty )* ) -> $result { - $crate::sp_tracing::enter_span!(stringify!($name)); - $crate::enter_span_wasm!(module_path!(), concat!(stringify!($name),"_wasm")); + $crate::enter_span!(stringify!($name)); $( $impl )* } }; diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index 3e915bfc8d519..e7a9f1e3527c3 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -41,14 +41,19 @@ impl Drop for TracingSpanGuard { /// # Example /// /// ``` -/// frame_support::enter_span_wasm!("target", "fn_name"); +/// frame_support::enter_span!("fn_name"); /// ``` #[macro_export] -macro_rules! enter_span_wasm { - ( $target:expr, $name:expr ) => { +macro_rules! enter_span { + ( $name:expr ) => { #[cfg(not(feature = "std"))] let __span_id__ = $crate::wasm_tracing::TracingSpanGuard::new( - $crate::sp_io::wasm_tracing::enter_span($target, $name) + $crate::sp_io::wasm_tracing::enter_span( + module_path!(), + &[$name, "_wasm"].concat() + ) ); + #[cfg(feature = "std")] + $crate::sp_tracing::enter_span!($name); } } From 2126d8e97dcf609793a1af4c762109ab6c2c66eb Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Fri, 15 May 2020 15:34:35 +0100 Subject: [PATCH 28/75] implement wasm tracing control facility in primitives and frame --- frame/support/src/lib.rs | 2 ++ frame/support/src/wasm_tracing.rs | 22 +++++++++++++++------- primitives/io/src/lib.rs | 5 +++-- primitives/tracing/src/lib.rs | 4 ++++ 4 files changed, 24 insertions(+), 9 deletions(-) diff --git a/frame/support/src/lib.rs b/frame/support/src/lib.rs index b95ba16e7b291..2fcab719b9c9f 100644 --- a/frame/support/src/lib.rs +++ b/frame/support/src/lib.rs @@ -83,6 +83,8 @@ pub use self::storage::{ pub use self::dispatch::{Parameter, Callable, IsSubType}; pub use sp_runtime::{self, ConsensusEngineId, print, traits::Printable}; +pub const WASM_TRACING_ENABLED: sp_std::cell::Cell = sp_std::cell::Cell::new(true); + /// A type that cannot be instantiated. #[derive(Debug)] pub enum Never {} diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index e7a9f1e3527c3..cad3e4dbe0aca 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -18,7 +18,6 @@ //! //! Facilitated by `sp_io::wasm_tracing` - /// This holds a tracing span id and is to signal on drop that a tracing span has exited. /// It must be bound to a named variable eg. `_span_guard`. pub struct TracingSpanGuard(u64); @@ -47,12 +46,21 @@ impl Drop for TracingSpanGuard { macro_rules! enter_span { ( $name:expr ) => { #[cfg(not(feature = "std"))] - let __span_id__ = $crate::wasm_tracing::TracingSpanGuard::new( - $crate::sp_io::wasm_tracing::enter_span( - module_path!(), - &[$name, "_wasm"].concat() - ) - ); + { + let __span_id__; + if frame_support::WASM_TRACING_ENABLED.get() { + if let Some(__id__) = $crate::sp_io::wasm_tracing::enter_span( + module_path!(), + &[$name, "_wasm"].concat() + ){ + __span_id__ = $crate::wasm_tracing::TracingSpanGuard::new( + __id__ + ); + } else { + frame_support::WASM_TRACING_ENABLED.set(false); + } + } + } #[cfg(feature = "std")] $crate::sp_tracing::enter_span!($name); } diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index 8e381e0beaba6..597d5e203bdfc 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -880,7 +880,8 @@ sp_externalities::decl_extension! { #[runtime_interface] pub trait WasmTracing { /// To create and enter a `tracing` span, via `sp_tracing::proxy` - fn enter_span(&mut self, target: &str, name: &str) -> u64 { + fn enter_span(&mut self, target: &str, name: &str) -> Option { + if !sp_tracing::WASM_TRACING_ENABLED.load(std::sync::atomic::Ordering::Relaxed) { return None } let proxy = match self.extension::() { Some(proxy) => proxy, None => { @@ -889,7 +890,7 @@ pub trait WasmTracing { self.extension::().expect("Failed to load required extension: `TracingProxyExt`") } }; - proxy.enter_span(target, name) + Some(proxy.enter_span(target, name)) } /// If there is a panic in the WASM VM then this may not be called. diff --git a/primitives/tracing/src/lib.rs b/primitives/tracing/src/lib.rs index 5600fed6e294c..63cf99fad5622 100644 --- a/primitives/tracing/src/lib.rs +++ b/primitives/tracing/src/lib.rs @@ -40,6 +40,10 @@ pub use tracing; #[cfg(feature = "std")] pub mod proxy; +/// Flag to signal whether we need to run wasm tracing, inc host-function calls +#[cfg(feature = "std")] +pub const WASM_TRACING_ENABLED: std::sync::atomic::AtomicBool = std::sync::atomic::AtomicBool::new(true); + /// Runs given code within a tracing span, measuring it's execution time. /// /// If tracing is not enabled, the code is still executed. From 0d48517be78e8d51d5de4823e07c91d995339677 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Fri, 15 May 2020 16:17:37 +0100 Subject: [PATCH 29/75] add cli flag `--wasm-tracing` --- Cargo.lock | 1 + client/cli/src/commands/mod.rs | 6 ++++++ client/cli/src/config.rs | 10 ++++++++++ client/cli/src/params/import_params.rs | 9 +++++++++ client/service/Cargo.toml | 1 + client/service/src/builder.rs | 4 +++- client/service/src/config.rs | 2 ++ client/service/test/src/lib.rs | 1 + primitives/tracing/src/lib.rs | 2 +- utils/browser/src/lib.rs | 1 + 10 files changed, 35 insertions(+), 2 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 8260313ed5da6..198d7ddbeade6 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6760,6 +6760,7 @@ dependencies = [ "sp-runtime", "sp-session", "sp-state-machine", + "sp-tracing", "sp-transaction-pool", "sp-trie", "sp-utils", diff --git a/client/cli/src/commands/mod.rs b/client/cli/src/commands/mod.rs index 54a6f9b743221..e334f15a2f4f6 100644 --- a/client/cli/src/commands/mod.rs +++ b/client/cli/src/commands/mod.rs @@ -383,6 +383,12 @@ macro_rules! substrate_cli_subcommands { } } + fn wasm_tracing(&self) -> $crate::Result { + match self { + $($enum::$variant(cmd) => cmd.wasm_tracing()),* + } + } + fn node_key(&self, net_config_dir: &::std::path::PathBuf) -> $crate::Result<::sc_service::config::NodeKeyConfig> { match self { diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index 56830f2076328..2f94bad9d4cf6 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -368,6 +368,15 @@ pub trait CliConfiguration: Sized { .unwrap_or(Default::default())) } + /// Returns `Ok(true)` if wasm tracing should be enabled + /// + /// By default this is `false`. + fn wasm_tracing(&self) -> Result { + Ok(self.import_params() + .map(|x| x.wasm_tracing()) + .unwrap_or(Default::default())) + } + /// Get the node key from the current object /// /// By default this is retrieved from `NodeKeyParams` if it is available. Otherwise its @@ -463,6 +472,7 @@ pub trait CliConfiguration: Sized { dev_key_seed: self.dev_key_seed(is_dev)?, tracing_targets: self.tracing_targets()?, tracing_receiver: self.tracing_receiver()?, + wasm_tracing: self.wasm_tracing()?, chain_spec, max_runtime_instances, announce_block: self.announce_block()?, diff --git a/client/cli/src/params/import_params.rs b/client/cli/src/params/import_params.rs index c5acc6bd81440..a8eeb2f845258 100644 --- a/client/cli/src/params/import_params.rs +++ b/client/cli/src/params/import_params.rs @@ -78,6 +78,10 @@ pub struct ImportParams { default_value = "Log" )] pub tracing_receiver: TracingReceiver, + + /// Enable wasm tracing + #[structopt(long = "wasm-tracing")] + pub wasm_tracing: bool, } impl ImportParams { @@ -91,6 +95,11 @@ impl ImportParams { self.tracing_targets.clone() } + /// Flag to enable wasm tracing. + pub fn wasm_tracing(&self) -> bool { + self.wasm_tracing + } + /// Specify the state cache size. pub fn state_cache_size(&self) -> usize { self.state_cache_size diff --git a/client/service/Cargo.toml b/client/service/Cargo.toml index e5f6e229c7020..d7f686f4dedc0 100644 --- a/client/service/Cargo.toml +++ b/client/service/Cargo.toml @@ -65,6 +65,7 @@ sc-rpc-server = { version = "2.0.0-dev", path = "../rpc-servers" } sc-rpc = { version = "2.0.0-dev", path = "../rpc" } sc-block-builder = { version = "0.8.0-dev", path = "../block-builder" } sp-block-builder = { version = "2.0.0-dev", path = "../../primitives/block-builder" } +sp-tracing = { version = "2.0.0-dev", path = "../../primitives/tracing" } sc-telemetry = { version = "2.0.0-dev", path = "../telemetry" } sc-offchain = { version = "2.0.0-dev", path = "../offchain" } diff --git a/client/service/src/builder.rs b/client/service/src/builder.rs index eb6e040cc40fe..3b4a12101da4f 100644 --- a/client/service/src/builder.rs +++ b/client/service/src/builder.rs @@ -48,7 +48,7 @@ use sc_executor::{NativeExecutor, NativeExecutionDispatch, RuntimeInfo}; use std::{ collections::HashMap, io::{Read, Write, Seek}, - marker::PhantomData, sync::Arc, pin::Pin + marker::PhantomData, sync::{Arc, atomic::Ordering}, pin::Pin }; use wasm_timer::SystemTime; use sc_telemetry::{telemetry, SUBSTRATE_INFO}; @@ -1227,6 +1227,8 @@ ServiceBuilder< let subscriber = sc_tracing::ProfilingSubscriber::new( config.tracing_receiver, tracing_targets ); + sp_tracing::WASM_TRACING_ENABLED.store(config.wasm_tracing, Ordering::Relaxed); + log::debug!(target: "sp_tracing", "WASM_TRACING = {}", config.wasm_tracing ); match tracing::subscriber::set_global_default(subscriber) { Ok(_) => (), Err(e) => error!(target: "tracing", "Unable to set global default subscriber {}", e), diff --git a/client/service/src/config.rs b/client/service/src/config.rs index e0de85b56d598..18ca6390347c0 100644 --- a/client/service/src/config.rs +++ b/client/service/src/config.rs @@ -94,6 +94,8 @@ pub struct Configuration { pub tracing_targets: Option, /// Tracing receiver pub tracing_receiver: sc_tracing::TracingReceiver, + /// Enable wasm tracing + pub wasm_tracing: bool, /// The size of the instances cache. /// /// The default value is 8. diff --git a/client/service/test/src/lib.rs b/client/service/test/src/lib.rs index fd6774136597c..377e93281bf4b 100644 --- a/client/service/test/src/lib.rs +++ b/client/service/test/src/lib.rs @@ -206,6 +206,7 @@ fn node_config Date: Fri, 15 May 2020 16:47:12 +0100 Subject: [PATCH 30/75] fix --- primitives/tracing/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/primitives/tracing/src/lib.rs b/primitives/tracing/src/lib.rs index 136a26daff403..4aae74250ba31 100644 --- a/primitives/tracing/src/lib.rs +++ b/primitives/tracing/src/lib.rs @@ -42,7 +42,7 @@ pub mod proxy; /// Flag to signal whether we need to run wasm tracing, inc host-function calls #[cfg(feature = "std")] -pub const WASM_TRACING_ENABLED: std::sync::atomic::AtomicBool = std::sync::atomic::AtomicBool::new(false); +pub static WASM_TRACING_ENABLED: std::sync::atomic::AtomicBool = std::sync::atomic::AtomicBool::new(false); /// Runs given code within a tracing span, measuring it's execution time. /// From 2db5f89efec324c4432ccdd6cf3b9e897e19d79d Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Fri, 15 May 2020 17:43:33 +0100 Subject: [PATCH 31/75] switch to `Option` (possible performance degradation), switch to static mut bool --- frame/support/src/lib.rs | 2 +- frame/support/src/wasm_tracing.rs | 26 ++++++++++++++------------ primitives/io/src/lib.rs | 8 +++++++- 3 files changed, 22 insertions(+), 14 deletions(-) diff --git a/frame/support/src/lib.rs b/frame/support/src/lib.rs index 2fcab719b9c9f..1ad78dbe95e8f 100644 --- a/frame/support/src/lib.rs +++ b/frame/support/src/lib.rs @@ -83,7 +83,7 @@ pub use self::storage::{ pub use self::dispatch::{Parameter, Callable, IsSubType}; pub use sp_runtime::{self, ConsensusEngineId, print, traits::Printable}; -pub const WASM_TRACING_ENABLED: sp_std::cell::Cell = sp_std::cell::Cell::new(true); +pub static mut WASM_TRACING_ENABLED: bool = true; /// A type that cannot be instantiated. #[derive(Debug)] diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index cad3e4dbe0aca..f1dec085aa3a7 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -20,17 +20,19 @@ /// This holds a tracing span id and is to signal on drop that a tracing span has exited. /// It must be bound to a named variable eg. `_span_guard`. -pub struct TracingSpanGuard(u64); +pub struct TracingSpanGuard(Option); impl TracingSpanGuard { - pub fn new(span: u64) -> Self { + pub fn new(span: Option) -> Self { Self(span) } } impl Drop for TracingSpanGuard { fn drop(&mut self) { - crate::sp_io::wasm_tracing::exit_span(self.0); + if let Some(id) = self.0 { + crate::sp_io::wasm_tracing::exit_span(id); + } } } @@ -46,22 +48,22 @@ impl Drop for TracingSpanGuard { macro_rules! enter_span { ( $name:expr ) => { #[cfg(not(feature = "std"))] - { - let __span_id__; - if frame_support::WASM_TRACING_ENABLED.get() { + let __span_id__ = match unsafe { frame_support::WASM_TRACING_ENABLED } { + false => $crate::wasm_tracing::TracingSpanGuard::new(None), + true => { if let Some(__id__) = $crate::sp_io::wasm_tracing::enter_span( module_path!(), &[$name, "_wasm"].concat() - ){ - __span_id__ = $crate::wasm_tracing::TracingSpanGuard::new( - __id__ - ); + ) { + $crate::wasm_tracing::TracingSpanGuard::new(Some(__id__)) } else { - frame_support::WASM_TRACING_ENABLED.set(false); + unsafe { frame_support::WASM_TRACING_ENABLED = false; } + $crate::wasm_tracing::TracingSpanGuard::new(None) } } - } + }; #[cfg(feature = "std")] $crate::sp_tracing::enter_span!($name); } } + diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index 597d5e203bdfc..5ad5f6fd398d1 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -881,7 +881,13 @@ sp_externalities::decl_extension! { pub trait WasmTracing { /// To create and enter a `tracing` span, via `sp_tracing::proxy` fn enter_span(&mut self, target: &str, name: &str) -> Option { - if !sp_tracing::WASM_TRACING_ENABLED.load(std::sync::atomic::Ordering::Relaxed) { return None } + if !sp_tracing::WASM_TRACING_ENABLED.load(std::sync::atomic::Ordering::Relaxed) { + log::debug!( + target: "sp_tracing", + "Notify to runtime that tracing is disabled." + ); + return None + } let proxy = match self.extension::() { Some(proxy) => proxy, None => { From c9c7e9c4d67d245cded806ef188a7a859ec57155 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Fri, 15 May 2020 18:43:01 +0100 Subject: [PATCH 32/75] performance improvement using u64 vs Option --- frame/support/src/wasm_tracing.rs | 22 ++++++++++++---------- primitives/io/src/lib.rs | 19 ++++++++++++------- 2 files changed, 24 insertions(+), 17 deletions(-) diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index f1dec085aa3a7..174fbecb268a1 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -20,18 +20,21 @@ /// This holds a tracing span id and is to signal on drop that a tracing span has exited. /// It must be bound to a named variable eg. `_span_guard`. -pub struct TracingSpanGuard(Option); +/// +/// 0 is a special inner value to indicate that the trace is disabled and should not call out +/// of the runtime. +pub struct TracingSpanGuard(u64); impl TracingSpanGuard { - pub fn new(span: Option) -> Self { + pub fn new(span: u64) -> Self { Self(span) } } impl Drop for TracingSpanGuard { fn drop(&mut self) { - if let Some(id) = self.0 { - crate::sp_io::wasm_tracing::exit_span(id); + if self.0 > 0 { + crate::sp_io::wasm_tracing::exit_span(self.0); } } } @@ -49,17 +52,16 @@ macro_rules! enter_span { ( $name:expr ) => { #[cfg(not(feature = "std"))] let __span_id__ = match unsafe { frame_support::WASM_TRACING_ENABLED } { - false => $crate::wasm_tracing::TracingSpanGuard::new(None), + false => $crate::wasm_tracing::TracingSpanGuard::new(0), true => { - if let Some(__id__) = $crate::sp_io::wasm_tracing::enter_span( + let __id__ = $crate::sp_io::wasm_tracing::enter_span( module_path!(), &[$name, "_wasm"].concat() - ) { - $crate::wasm_tracing::TracingSpanGuard::new(Some(__id__)) - } else { + ); + if __id__ == 0 { unsafe { frame_support::WASM_TRACING_ENABLED = false; } - $crate::wasm_tracing::TracingSpanGuard::new(None) } + $crate::wasm_tracing::TracingSpanGuard::new(__id__) } }; #[cfg(feature = "std")] diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index 5ad5f6fd398d1..da18b4e935306 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -880,30 +880,35 @@ sp_externalities::decl_extension! { #[runtime_interface] pub trait WasmTracing { /// To create and enter a `tracing` span, via `sp_tracing::proxy` - fn enter_span(&mut self, target: &str, name: &str) -> Option { + fn enter_span(&mut self, target: &str, name: &str) -> u64 { if !sp_tracing::WASM_TRACING_ENABLED.load(std::sync::atomic::Ordering::Relaxed) { log::debug!( target: "sp_tracing", "Notify to runtime that tracing is disabled." ); - return None + return 0 } let proxy = match self.extension::() { Some(proxy) => proxy, None => { self.register_extension(TracingProxyExt(sp_tracing::proxy::TracingProxy::new())) .expect("Failed to register required extension: `TracingProxyExt`"); - self.extension::().expect("Failed to load required extension: `TracingProxyExt`") + self.extension::().expect("Failed to load required extension `TracingProxyExt` on enter_span") } }; - Some(proxy.enter_span(target, name)) + proxy.enter_span(target, name) } /// If there is a panic in the WASM VM then this may not be called. fn exit_span(&mut self, id: u64) { - let proxy = self.extension::() - .expect("Failed to load required extension: \ - `TracingProxyExt` which should be loaded before calling `exit_span`"); + let proxy = match self.extension::() { + Some(proxy) => proxy, + None => { + self.register_extension(TracingProxyExt(sp_tracing::proxy::TracingProxy::new())) + .expect("Failed to register required extension: `TracingProxyExt`"); + self.extension::().expect("Failed to load required extension `TracingProxyExt` on exit_span") + } + }; proxy.exit_span(id); } From e3bdb795b4279b8b6f0facdc261f4133f9018b11 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Fri, 15 May 2020 19:34:11 +0100 Subject: [PATCH 33/75] performance improvement moving concat to client --- client/tracing/src/lib.rs | 2 +- frame/support/src/wasm_tracing.rs | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index ea6297f9953bc..a701ca182499d 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -252,7 +252,7 @@ impl Subscriber for ProfilingSubscriber { if let Some(mut span_datum) = span_datum { if span_datum.name == WASM_TRACE_IDENTIFIER { if let Some(n) = span_datum.values.0.remove(WASM_NAME_KEY) { - span_datum.name = n; + span_datum.name = [&n, "_wasm"].concat(); } if let Some(t) = span_datum.values.0.remove(WASM_TARGET_KEY) { span_datum.target = t; diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index 174fbecb268a1..807ebdc5746ba 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -56,7 +56,7 @@ macro_rules! enter_span { true => { let __id__ = $crate::sp_io::wasm_tracing::enter_span( module_path!(), - &[$name, "_wasm"].concat() + $name ); if __id__ == 0 { unsafe { frame_support::WASM_TRACING_ENABLED = false; } From 10a07a64c60e7a8f0d8b9122b8077f5ab752a6d3 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 18 May 2020 09:36:38 +0100 Subject: [PATCH 34/75] update docs --- frame/support/src/lib.rs | 1 + primitives/tracing/src/lib.rs | 2 +- 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/frame/support/src/lib.rs b/frame/support/src/lib.rs index 1ad78dbe95e8f..84629cadffeb8 100644 --- a/frame/support/src/lib.rs +++ b/frame/support/src/lib.rs @@ -83,6 +83,7 @@ pub use self::storage::{ pub use self::dispatch::{Parameter, Callable, IsSubType}; pub use sp_runtime::{self, ConsensusEngineId, print, traits::Printable}; +/// Indicates whether to run traces in wasm pub static mut WASM_TRACING_ENABLED: bool = true; /// A type that cannot be instantiated. diff --git a/primitives/tracing/src/lib.rs b/primitives/tracing/src/lib.rs index 4aae74250ba31..506683a21caae 100644 --- a/primitives/tracing/src/lib.rs +++ b/primitives/tracing/src/lib.rs @@ -40,7 +40,7 @@ pub use tracing; #[cfg(feature = "std")] pub mod proxy; -/// Flag to signal whether we need to run wasm tracing, inc host-function calls +/// Flag to signal whether to run wasm tracing #[cfg(feature = "std")] pub static WASM_TRACING_ENABLED: std::sync::atomic::AtomicBool = std::sync::atomic::AtomicBool::new(false); From 2b73ed7d6c87434868bd74c72870ff39956530db Mon Sep 17 00:00:00 2001 From: mattrutherford <44339188+mattrutherford@users.noreply.github.com> Date: Mon, 18 May 2020 09:37:17 +0100 Subject: [PATCH 35/75] Update client/cli/src/params/import_params.rs Co-authored-by: Cecile Tonglet --- client/cli/src/params/import_params.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/cli/src/params/import_params.rs b/client/cli/src/params/import_params.rs index a8eeb2f845258..e1c55f101941f 100644 --- a/client/cli/src/params/import_params.rs +++ b/client/cli/src/params/import_params.rs @@ -80,7 +80,7 @@ pub struct ImportParams { pub tracing_receiver: TracingReceiver, /// Enable wasm tracing - #[structopt(long = "wasm-tracing")] + #[structopt(long)] pub wasm_tracing: bool, } From cff0aa2670cd1d380f1893f0a6f4d498b384e7b7 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 18 May 2020 14:27:39 +0100 Subject: [PATCH 36/75] performance improvement --- frame/support/src/lib.rs | 3 --- frame/support/src/wasm_tracing.rs | 11 ++++++----- primitives/io/src/lib.rs | 1 + primitives/tracing/src/proxy.rs | 8 ++++++-- 4 files changed, 13 insertions(+), 10 deletions(-) diff --git a/frame/support/src/lib.rs b/frame/support/src/lib.rs index 84629cadffeb8..b95ba16e7b291 100644 --- a/frame/support/src/lib.rs +++ b/frame/support/src/lib.rs @@ -83,9 +83,6 @@ pub use self::storage::{ pub use self::dispatch::{Parameter, Callable, IsSubType}; pub use sp_runtime::{self, ConsensusEngineId, print, traits::Printable}; -/// Indicates whether to run traces in wasm -pub static mut WASM_TRACING_ENABLED: bool = true; - /// A type that cannot be instantiated. #[derive(Debug)] pub enum Never {} diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index 807ebdc5746ba..f494dadf452e7 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -18,6 +18,9 @@ //! //! Facilitated by `sp_io::wasm_tracing` +/// Indicates whether to run traces in wasm +pub static mut WASM_TRACING_ENABLED: bool = true; + /// This holds a tracing span id and is to signal on drop that a tracing span has exited. /// It must be bound to a named variable eg. `_span_guard`. /// @@ -33,9 +36,7 @@ impl TracingSpanGuard { impl Drop for TracingSpanGuard { fn drop(&mut self) { - if self.0 > 0 { - crate::sp_io::wasm_tracing::exit_span(self.0); - } + crate::sp_io::wasm_tracing::exit_span(self.0); } } @@ -51,7 +52,7 @@ impl Drop for TracingSpanGuard { macro_rules! enter_span { ( $name:expr ) => { #[cfg(not(feature = "std"))] - let __span_id__ = match unsafe { frame_support::WASM_TRACING_ENABLED } { + let __span_id__ = match unsafe { $crate::wasm_tracing::WASM_TRACING_ENABLED } { false => $crate::wasm_tracing::TracingSpanGuard::new(0), true => { let __id__ = $crate::sp_io::wasm_tracing::enter_span( @@ -59,7 +60,7 @@ macro_rules! enter_span { $name ); if __id__ == 0 { - unsafe { frame_support::WASM_TRACING_ENABLED = false; } + unsafe { $crate::wasm_tracing ::WASM_TRACING_ENABLED = false; } } $crate::wasm_tracing::TracingSpanGuard::new(__id__) } diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index da18b4e935306..4d96cf93e12ab 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -886,6 +886,7 @@ pub trait WasmTracing { target: "sp_tracing", "Notify to runtime that tracing is disabled." ); + // Zero indicates tracing is disabled in wasm return 0 } let proxy = match self.extension::() { diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index be609907c4ce2..a2f4451f9d624 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -59,7 +59,8 @@ impl TracingProxy { pub fn new() -> TracingProxy { let spans: Vec<(u64, rent_span::SpanAndGuard)> = Vec::new(); TracingProxy { - next_id: 0, + // Important to start at 1, 0 will not record a trace + next_id: 1, spans, } } @@ -97,7 +98,10 @@ impl TracingProxy { /// Exit a span by dropping it along with it's associated guard. pub fn exit_span(&mut self, id: u64) { if self.spans.last().map(|l| id > l.0).unwrap_or(true) { - log::warn!("Span id not found {}", id); + // 0 is special case to indicate no wasm tracing + if id != 0 { + log::warn!("Span id not found {}", id); + } return; } let mut last_span = self.spans.pop().expect("Just checked that there is an element to pop"); From 70e63157c6770aac94580c1d2e96eb14efb34cc4 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 18 May 2020 15:17:05 +0100 Subject: [PATCH 37/75] Revert "performance improvement" This reverts commit cff0aa2670cd1d380f1893f0a6f4d498b384e7b7. --- frame/support/src/lib.rs | 3 +++ frame/support/src/wasm_tracing.rs | 11 +++++------ primitives/io/src/lib.rs | 1 - primitives/tracing/src/proxy.rs | 8 ++------ 4 files changed, 10 insertions(+), 13 deletions(-) diff --git a/frame/support/src/lib.rs b/frame/support/src/lib.rs index b95ba16e7b291..84629cadffeb8 100644 --- a/frame/support/src/lib.rs +++ b/frame/support/src/lib.rs @@ -83,6 +83,9 @@ pub use self::storage::{ pub use self::dispatch::{Parameter, Callable, IsSubType}; pub use sp_runtime::{self, ConsensusEngineId, print, traits::Printable}; +/// Indicates whether to run traces in wasm +pub static mut WASM_TRACING_ENABLED: bool = true; + /// A type that cannot be instantiated. #[derive(Debug)] pub enum Never {} diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index f494dadf452e7..807ebdc5746ba 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -18,9 +18,6 @@ //! //! Facilitated by `sp_io::wasm_tracing` -/// Indicates whether to run traces in wasm -pub static mut WASM_TRACING_ENABLED: bool = true; - /// This holds a tracing span id and is to signal on drop that a tracing span has exited. /// It must be bound to a named variable eg. `_span_guard`. /// @@ -36,7 +33,9 @@ impl TracingSpanGuard { impl Drop for TracingSpanGuard { fn drop(&mut self) { - crate::sp_io::wasm_tracing::exit_span(self.0); + if self.0 > 0 { + crate::sp_io::wasm_tracing::exit_span(self.0); + } } } @@ -52,7 +51,7 @@ impl Drop for TracingSpanGuard { macro_rules! enter_span { ( $name:expr ) => { #[cfg(not(feature = "std"))] - let __span_id__ = match unsafe { $crate::wasm_tracing::WASM_TRACING_ENABLED } { + let __span_id__ = match unsafe { frame_support::WASM_TRACING_ENABLED } { false => $crate::wasm_tracing::TracingSpanGuard::new(0), true => { let __id__ = $crate::sp_io::wasm_tracing::enter_span( @@ -60,7 +59,7 @@ macro_rules! enter_span { $name ); if __id__ == 0 { - unsafe { $crate::wasm_tracing ::WASM_TRACING_ENABLED = false; } + unsafe { frame_support::WASM_TRACING_ENABLED = false; } } $crate::wasm_tracing::TracingSpanGuard::new(__id__) } diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index 4d96cf93e12ab..da18b4e935306 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -886,7 +886,6 @@ pub trait WasmTracing { target: "sp_tracing", "Notify to runtime that tracing is disabled." ); - // Zero indicates tracing is disabled in wasm return 0 } let proxy = match self.extension::() { diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index a2f4451f9d624..be609907c4ce2 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -59,8 +59,7 @@ impl TracingProxy { pub fn new() -> TracingProxy { let spans: Vec<(u64, rent_span::SpanAndGuard)> = Vec::new(); TracingProxy { - // Important to start at 1, 0 will not record a trace - next_id: 1, + next_id: 0, spans, } } @@ -98,10 +97,7 @@ impl TracingProxy { /// Exit a span by dropping it along with it's associated guard. pub fn exit_span(&mut self, id: u64) { if self.spans.last().map(|l| id > l.0).unwrap_or(true) { - // 0 is special case to indicate no wasm tracing - if id != 0 { - log::warn!("Span id not found {}", id); - } + log::warn!("Span id not found {}", id); return; } let mut last_span = self.spans.pop().expect("Just checked that there is an element to pop"); From dc335e9f326b655f45b9078062225236c4703a67 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 18 May 2020 15:27:20 +0100 Subject: [PATCH 38/75] small refactor --- frame/support/src/lib.rs | 3 --- frame/support/src/wasm_tracing.rs | 19 +++++++++++-------- 2 files changed, 11 insertions(+), 11 deletions(-) diff --git a/frame/support/src/lib.rs b/frame/support/src/lib.rs index 84629cadffeb8..b95ba16e7b291 100644 --- a/frame/support/src/lib.rs +++ b/frame/support/src/lib.rs @@ -83,9 +83,6 @@ pub use self::storage::{ pub use self::dispatch::{Parameter, Callable, IsSubType}; pub use sp_runtime::{self, ConsensusEngineId, print, traits::Printable}; -/// Indicates whether to run traces in wasm -pub static mut WASM_TRACING_ENABLED: bool = true; - /// A type that cannot be instantiated. #[derive(Debug)] pub enum Never {} diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index 807ebdc5746ba..7812a41a129a8 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -18,6 +18,9 @@ //! //! Facilitated by `sp_io::wasm_tracing` +/// Indicates whether to run traces in wasm +pub static mut WASM_TRACING_ENABLED: bool = true; + /// This holds a tracing span id and is to signal on drop that a tracing span has exited. /// It must be bound to a named variable eg. `_span_guard`. /// @@ -51,17 +54,17 @@ impl Drop for TracingSpanGuard { macro_rules! enter_span { ( $name:expr ) => { #[cfg(not(feature = "std"))] - let __span_id__ = match unsafe { frame_support::WASM_TRACING_ENABLED } { + let __span_id__ = match unsafe { $crate::wasm_tracing::WASM_TRACING_ENABLED } { false => $crate::wasm_tracing::TracingSpanGuard::new(0), true => { - let __id__ = $crate::sp_io::wasm_tracing::enter_span( - module_path!(), - $name - ); - if __id__ == 0 { - unsafe { frame_support::WASM_TRACING_ENABLED = false; } + let id = $crate::sp_io::wasm_tracing::enter_span( + module_path!(), + $name + ); + if id == 0 { + unsafe { $crate::wasm_tracing::WASM_TRACING_ENABLED = false; } } - $crate::wasm_tracing::TracingSpanGuard::new(__id__) + $crate::wasm_tracing::TracingSpanGuard::new(id) } }; #[cfg(feature = "std")] From 955fa15bc9573ba8e1513c8ca9a29263be85725e Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 18 May 2020 15:39:10 +0100 Subject: [PATCH 39/75] formatting --- primitives/io/src/lib.rs | 1 - 1 file changed, 1 deletion(-) diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index da18b4e935306..f13aa163fc0ba 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -911,7 +911,6 @@ pub trait WasmTracing { }; proxy.exit_span(id); } - } /// Wasm-only interface that provides functions for interacting with the sandbox. From cd563c32d19e56280677368587790da0c5c3e12c Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 18 May 2020 15:42:05 +0100 Subject: [PATCH 40/75] bump impl_version --- bin/node/runtime/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/bin/node/runtime/src/lib.rs b/bin/node/runtime/src/lib.rs index a67f4855ac56b..4ebb3c0dd87c5 100644 --- a/bin/node/runtime/src/lib.rs +++ b/bin/node/runtime/src/lib.rs @@ -91,7 +91,7 @@ pub const VERSION: RuntimeVersion = RuntimeVersion { // implementation changes and behavior does not, then leave spec_version as // is and increment impl_version. spec_version: 247, - impl_version: 0, + impl_version: 1, apis: RUNTIME_API_VERSIONS, transaction_version: 1, }; From 1bc601fca425026d1689abff31de4a1994da970f Mon Sep 17 00:00:00 2001 From: mattrutherford <44339188+mattrutherford@users.noreply.github.com> Date: Tue, 19 May 2020 10:39:20 +0100 Subject: [PATCH 41/75] Update client/cli/src/config.rs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Bastian Köcher --- client/cli/src/config.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index 2f94bad9d4cf6..7c9dafb7fbb1b 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -374,7 +374,7 @@ pub trait CliConfiguration: Sized { fn wasm_tracing(&self) -> Result { Ok(self.import_params() .map(|x| x.wasm_tracing()) - .unwrap_or(Default::default())) + .unwrap_or_default()) } /// Get the node key from the current object From a63e6d5945ac49d592535a4532686496a76e536c Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 21 May 2020 17:33:18 +0100 Subject: [PATCH 42/75] update docs --- frame/support/src/wasm_tracing.rs | 3 +++ 1 file changed, 3 insertions(+) diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index 7812a41a129a8..9dbfff5c4fd74 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -45,6 +45,9 @@ impl Drop for TracingSpanGuard { /// Enters a tracing span, via [`sp_tracing::proxy`] measuring execution time /// until exit from the current scope. /// +/// It's also possible to directly call the functions `enter_span` and `exit_span` +/// in `sp_io::wasm_tracing` if more fine-grained control of span duration is required. +/// /// # Example /// /// ``` From 722835834fc8b7bdd7ec01147c75077547736f4b Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 28 May 2020 14:53:03 +0100 Subject: [PATCH 43/75] small fixes, remove pub static --- client/service/src/builder.rs | 3 +- client/tracing/src/lib.rs | 4 +- frame/support/src/wasm_tracing.rs | 21 +++++---- primitives/io/src/lib.rs | 78 ++++++++++++++++--------------- primitives/tracing/src/lib.rs | 15 +++++- primitives/tracing/src/proxy.rs | 22 +++++---- 6 files changed, 82 insertions(+), 61 deletions(-) diff --git a/client/service/src/builder.rs b/client/service/src/builder.rs index cf7795be4135b..e2ec6108bc2a8 100644 --- a/client/service/src/builder.rs +++ b/client/service/src/builder.rs @@ -1316,8 +1316,7 @@ ServiceBuilder< let subscriber = sc_tracing::ProfilingSubscriber::new( config.tracing_receiver, tracing_targets ); - sp_tracing::WASM_TRACING_ENABLED.store(config.wasm_tracing, Ordering::Relaxed); - log::debug!(target: "sp_tracing", "WASM_TRACING = {}", config.wasm_tracing ); + sp_tracing::set_wasm_tracing(config.wasm_tracing); match tracing::subscriber::set_global_default(subscriber) { Ok(_) => (), Err(e) => error!(target: "tracing", "Unable to set global default subscriber {}", e), diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index a701ca182499d..d0704987b3f50 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -162,11 +162,11 @@ impl ProfilingSubscriber { fn check_target(&self, target: &str, level: &Level) -> bool { for t in &self.targets { if target.starts_with(t.0.as_str()) && level <= &t.1 { - log::debug!("Enabled target: {}, level: {}", target, level); + log::debug!(target: "tracing", "Enabled target: {}, level: {}", target, level); return true; } } - log::debug!("Disabled target: {}, level: {}", target, level); + log::debug!(target: "tracing", "Disabled target: {}, level: {}", target, level); false } } diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index 9dbfff5c4fd74..1492ab1294709 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -26,18 +26,18 @@ pub static mut WASM_TRACING_ENABLED: bool = true; /// /// 0 is a special inner value to indicate that the trace is disabled and should not call out /// of the runtime. -pub struct TracingSpanGuard(u64); +pub struct TracingSpanGuard(Option); impl TracingSpanGuard { - pub fn new(span: u64) -> Self { + pub fn new(span: Option) -> Self { Self(span) } } impl Drop for TracingSpanGuard { fn drop(&mut self) { - if self.0 > 0 { - crate::sp_io::wasm_tracing::exit_span(self.0); + if let Some(id) = self.0.take() { + crate::sp_io::wasm_tracing::exit_span(id); } } } @@ -57,19 +57,20 @@ impl Drop for TracingSpanGuard { macro_rules! enter_span { ( $name:expr ) => { #[cfg(not(feature = "std"))] - let __span_id__ = match unsafe { $crate::wasm_tracing::WASM_TRACING_ENABLED } { - false => $crate::wasm_tracing::TracingSpanGuard::new(0), - true => { + let __span_id__ = if unsafe { $crate::wasm_tracing::WASM_TRACING_ENABLED } { let id = $crate::sp_io::wasm_tracing::enter_span( module_path!(), $name ); if id == 0 { unsafe { $crate::wasm_tracing::WASM_TRACING_ENABLED = false; } + $crate::wasm_tracing::TracingSpanGuard::new(None) + } else { + $crate::wasm_tracing::TracingSpanGuard::new(Some(id)) } - $crate::wasm_tracing::TracingSpanGuard::new(id) - } - }; + } else { + $crate::wasm_tracing::TracingSpanGuard::new(None) + }; #[cfg(feature = "std")] $crate::sp_tracing::enter_span!($name); } diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index e6ecfb0190807..4c07ba4c9efec 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -23,9 +23,9 @@ #![cfg_attr(not(feature = "std"), feature(alloc_error_handler))] #![cfg_attr(feature = "std", - doc = "Substrate runtime standard library as compiled when linked with Rust's standard library.")] +doc = "Substrate runtime standard library as compiled when linked with Rust's standard library.")] #![cfg_attr(not(feature = "std"), - doc = "Substrate's runtime standard library as compiled without Rust's standard library.")] +doc = "Substrate's runtime standard library as compiled without Rust's standard library.")] use sp_std::vec::Vec; @@ -161,7 +161,6 @@ pub trait Storage { /// from within the runtime. #[runtime_interface] pub trait DefaultChildStorage { - /// Get a default child storage value for a given key. /// /// Parameter `storage_key` is the unprefixed location of the root of the child trie in the parent trie. @@ -216,7 +215,7 @@ pub trait DefaultChildStorage { /// Clear a child storage key. /// /// For the default child storage at `storage_key`, clear value at `key`. - fn clear ( + fn clear( &mut self, storage_key: &[u8], key: &[u8], @@ -964,37 +963,42 @@ sp_externalities::decl_extension! { /// Interface that provides functions for profiling the runtime. #[runtime_interface] pub trait WasmTracing { - /// To create and enter a `tracing` span, via `sp_tracing::proxy` + /// To create and enter a `tracing` span, using `sp_tracing::proxy` fn enter_span(&mut self, target: &str, name: &str) -> u64 { - if !sp_tracing::WASM_TRACING_ENABLED.load(std::sync::atomic::Ordering::Relaxed) { - log::debug!( - target: "sp_tracing", - "Notify to runtime that tracing is disabled." - ); - return 0 - } - let proxy = match self.extension::() { - Some(proxy) => proxy, - None => { - self.register_extension(TracingProxyExt(sp_tracing::proxy::TracingProxy::new())) - .expect("Failed to register required extension: `TracingProxyExt`"); - self.extension::().expect("Failed to load required extension `TracingProxyExt` on enter_span") + if sp_tracing::wasm_tracing_enabled() { + match self.extension::() { + Some(proxy) => return proxy.enter_span(target, name), + None => { + if let Ok(_) = self.register_extension(TracingProxyExt(sp_tracing::proxy::TracingProxy::new())) { + if let Some(proxy) = self.extension::() { + return proxy.enter_span(target, name); + } + } else { + log::warn!( + target: "tracing", + "Unable to register extension: TracingProxyExt" + ); + } + } } - }; - proxy.enter_span(target, name) + } + log::debug!( + target: "tracing", + "Notify to runtime that tracing is disabled." + ); + 0 } - /// If there is a panic in the WASM VM then this may not be called. + /// Exit a `tracing` span, using `sp_tracing::proxy` fn exit_span(&mut self, id: u64) { - let proxy = match self.extension::() { - Some(proxy) => proxy, - None => { - self.register_extension(TracingProxyExt(sp_tracing::proxy::TracingProxy::new())) - .expect("Failed to register required extension: `TracingProxyExt`"); - self.extension::().expect("Failed to load required extension `TracingProxyExt` on exit_span") - } - }; - proxy.exit_span(id); + if let Some(proxy) = self.extension::() { + proxy.exit_span(id) + } else { + log::warn!( + target: "tracing", + "Unable to load extension: TracingProxyExt" + ); + } } } @@ -1194,10 +1198,10 @@ mod tests { t.execute_with(|| { let mut v = [0u8; 4]; - assert!(storage::read(b":test", &mut v[..], 0).unwrap() >= 4); + assert!(storage::read(b":test", &mut v[..], 0).unwrap() > = 4); assert_eq!(v, [11u8, 0, 0, 0]); let mut w = [0u8; 11]; - assert!(storage::read(b":test", &mut w[..], 4).unwrap() >= 11); + assert!(storage::read(b":test", &mut w[..], 4).unwrap() > = 11); assert_eq!(&w, b"Hello world"); }); } @@ -1206,11 +1210,11 @@ mod tests { fn clear_prefix_works() { let mut t = BasicExternalities::new(Storage { top: map![ - b":a".to_vec() => b"\x0b\0\0\0Hello world".to_vec(), - b":abcd".to_vec() => b"\x0b\0\0\0Hello world".to_vec(), - b":abc".to_vec() => b"\x0b\0\0\0Hello world".to_vec(), - b":abdd".to_vec() => b"\x0b\0\0\0Hello world".to_vec() - ], + b":a".to_vec() => b"\x0b\0\0\0Hello world".to_vec(), + b":abcd".to_vec() => b"\x0b\0\0\0Hello world".to_vec(), + b":abc".to_vec() => b"\x0b\0\0\0Hello world".to_vec(), + b":abdd".to_vec() => b"\x0b\0\0\0Hello world".to_vec() + ], children_default: map![], }); diff --git a/primitives/tracing/src/lib.rs b/primitives/tracing/src/lib.rs index 0e1ec9a47276d..e82d8861cd3f5 100644 --- a/primitives/tracing/src/lib.rs +++ b/primitives/tracing/src/lib.rs @@ -41,9 +41,12 @@ pub use tracing; #[cfg(feature = "std")] pub mod proxy; +#[cfg(feature = "std")] +use std::sync::atomic::{AtomicBool, Ordering}; + /// Flag to signal whether to run wasm tracing #[cfg(feature = "std")] -pub static WASM_TRACING_ENABLED: std::sync::atomic::AtomicBool = std::sync::atomic::AtomicBool::new(false); +static WASM_TRACING_ENABLED: AtomicBool = AtomicBool::new(false); /// Runs given code within a tracing span, measuring it's execution time. /// @@ -102,3 +105,13 @@ macro_rules! if_tracing { macro_rules! if_tracing { ( $if:expr ) => {{}} } + +#[cfg(feature = "std")] +pub fn wasm_tracing_enabled() -> bool { + WASM_TRACING_ENABLED.load(Ordering::Relaxed) +} + +#[cfg(feature = "std")] +pub fn set_wasm_tracing(b: bool) { + WASM_TRACING_ENABLED.store(b, Ordering::Relaxed) +} \ No newline at end of file diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index be609907c4ce2..a04e27492ab9c 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -48,7 +48,10 @@ pub struct TracingProxy { impl Drop for TracingProxy { fn drop(&mut self) { - log::debug!("Dropping TracingProxy with {} spans", self.spans.len()); + log::debug!( + target: "tracing", + "Dropping TracingProxy with {} spans", self.spans.len() + ); while let Some((_, mut sg)) = self.spans.pop() { sg.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); } @@ -78,15 +81,13 @@ impl TracingProxy { |span| span.enter(), ); self.spans.push((self.next_id, sg)); - let spans_len = self.spans.len(); - if spans_len > MAX_SPANS_LEN { + if self.spans.len() > MAX_SPANS_LEN { // This is to prevent unbounded growth of Vec and could mean one of the following: // 1. Too many nested spans, or MAX_SPANS_LEN is too low. - // 2. Not correctly exiting spans due to drop impl not running (panic in runtime) - // 3. Not correctly exiting spans due to misconfiguration / misuse + // 2. Not correctly exiting spans due to misconfiguration / misuse log::warn!( target: "tracing", - "MAX_SPANS_LEN exceeded, removing oldest span, recording `is_valid_trace = false`", + "TracingProxy MAX_SPANS_LEN exceeded, removing oldest span, recording `is_valid_trace = false`" ); let mut sg = self.spans.remove(0).1; sg.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); @@ -97,17 +98,20 @@ impl TracingProxy { /// Exit a span by dropping it along with it's associated guard. pub fn exit_span(&mut self, id: u64) { if self.spans.last().map(|l| id > l.0).unwrap_or(true) { - log::warn!("Span id not found {}", id); + log::warn!(target: "tracing", "Span id not found in TracingProxy: {}", id); return; } let mut last_span = self.spans.pop().expect("Just checked that there is an element to pop"); while id < last_span.0 { - log::warn!("Span ids not equal! id parameter given: {}, last span: {}", id, last_span.0); + log::warn!( + target: "tracing", + "TracingProxy Span ids not equal! id parameter given: {}, last span: {}", id, last_span.0 + ); last_span.1.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); if let Some(s) = self.spans.pop() { last_span = s; } else { - log::warn!("Span id not found {}", id); + log::warn!(target: "tracing", "Span id not found in TracingProxy {}", id); return; } } From d735529a04cb9e080819b2edffd185dad04f8596 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Fri, 29 May 2020 14:03:57 +0100 Subject: [PATCH 44/75] nit --- primitives/tracing/src/proxy.rs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index a04e27492ab9c..ba3b7f3fc3150 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -60,10 +60,9 @@ impl Drop for TracingProxy { impl TracingProxy { pub fn new() -> TracingProxy { - let spans: Vec<(u64, rent_span::SpanAndGuard)> = Vec::new(); TracingProxy { next_id: 0, - spans, + spans: Vec::new(), } } } From de94f077f46baf9d69e8a8440e0eeeed79ba5145 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 1 Jun 2020 15:49:46 +0100 Subject: [PATCH 45/75] add integration tests and refactor Subscriber --- Cargo.lock | 12 ++- client/executor/Cargo.toml | 3 + client/executor/runtime-test/src/lib.rs | 12 ++- client/executor/src/integration_tests/mod.rs | 73 +++++++++++++++ client/service/src/builder.rs | 2 +- client/tracing/src/lib.rs | 97 +++++++++++++------- 6 files changed, 158 insertions(+), 41 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 03a6f4ae71593..e74d8351bda69 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6297,6 +6297,7 @@ dependencies = [ "sc-executor-wasmi", "sc-executor-wasmtime", "sc-runtime-test", + "sc-tracing", "sp-api", "sp-core", "sp-externalities", @@ -6306,11 +6307,13 @@ dependencies = [ "sp-runtime-interface", "sp-serializer", "sp-state-machine", + "sp-tracing", "sp-trie", "sp-version", "sp-wasm-interface", "substrate-test-runtime", "test-case", + "tracing", "wabt", "wasmi", ] @@ -8912,9 +8915,9 @@ checksum = "e987b6bf443f4b5b3b6f38704195592cca41c5bb7aedd3c3693c7081f8289860" [[package]] name = "tracing" -version = "0.1.13" +version = "0.1.14" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "1721cc8cf7d770cc4257872507180f35a4797272f5962f24c806af9e7faf52ab" +checksum = "a7c6b59d116d218cb2d990eb06b77b64043e0268ef7323aae63d8b30ae462923" dependencies = [ "cfg-if", "tracing-attributes", @@ -8923,10 +8926,11 @@ dependencies = [ [[package]] name = "tracing-attributes" -version = "0.1.7" +version = "0.1.8" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "7fbad39da2f9af1cae3016339ad7f2c7a9e870f12e8fd04c4fd7ef35b30c0d2b" +checksum = "99bbad0de3fd923c9c3232ead88510b783e5a4d16a6154adffa3d53308de984c" dependencies = [ + "proc-macro2", "quote 1.0.3", "syn 1.0.17", ] diff --git a/client/executor/Cargo.toml b/client/executor/Cargo.toml index 7290538f487b9..68d6b831cf422 100644 --- a/client/executor/Cargo.toml +++ b/client/executor/Cargo.toml @@ -44,6 +44,9 @@ substrate-test-runtime = { version = "2.0.0-rc2", path = "../../test-utils/runti sp-state-machine = { version = "0.8.0-rc2", path = "../../primitives/state-machine" } test-case = "0.3.3" sp-runtime = { version = "2.0.0-rc2", path = "../../primitives/runtime" } +sp-tracing = { version = "2.0.0-rc2", path = "../../primitives/tracing" } +sc-tracing = { version = "2.0.0-rc2", path = "../tracing" } +tracing = "0.1.14" [features] default = [ "std" ] diff --git a/client/executor/runtime-test/src/lib.rs b/client/executor/runtime-test/src/lib.rs index 15a4177048a40..bd7e242066851 100644 --- a/client/executor/runtime-test/src/lib.rs +++ b/client/executor/runtime-test/src/lib.rs @@ -11,7 +11,7 @@ use sp_std::{vec::Vec, vec}; #[cfg(not(feature = "std"))] use sp_io::{ storage, hashing::{blake2_128, blake2_256, sha2_256, twox_128, twox_256}, - crypto::{ed25519_verify, sr25519_verify}, + crypto::{ed25519_verify, sr25519_verify}, wasm_tracing, }; #[cfg(not(feature = "std"))] use sp_runtime::{print, traits::{BlakeTwo256, Hash}}; @@ -247,6 +247,16 @@ sp_core::wasm_export_functions! { sp_allocator::FreeingBumpHeapAllocator::new(0); } + fn test_enter_span() -> u64 { + wasm_tracing::enter_span("integration_test_span_target", "integration_test_span_name") + } + + fn test_exit_span(input: Vec) { + let mut array = [0u8; 8]; + array.clone_from_slice(&input); + wasm_tracing::exit_span(u64::from_le_bytes(array)) + } + fn returns_mutable_static() -> u64 { unsafe { MUTABLE_STATIC += 1; diff --git a/client/executor/src/integration_tests/mod.rs b/client/executor/src/integration_tests/mod.rs index 80b123ed4b556..5a0f5b7f8f8b0 100644 --- a/client/executor/src/integration_tests/mod.rs +++ b/client/executor/src/integration_tests/mod.rs @@ -658,3 +658,76 @@ fn parallel_execution(wasm_method: WasmExecutionMethod) { t.join().unwrap(); } } + +#[test_case(WasmExecutionMethod::Interpreted)] +#[cfg_attr(feature = "wasmtime", test_case(WasmExecutionMethod::Compiled))] +fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { + + use tracing::subscriber::set_global_default; + use std::sync::{Arc, Mutex}; + + struct TestTraceHandler(Arc>>); + + impl sc_tracing::TraceHandler for TestTraceHandler { + fn process_span(&self, sd: sc_tracing::SpanDatum) { + println!("{:?}",sd); + self.0.lock().unwrap().push((sd.target, sd.name)); + } + } + + let traces = Arc::new(Mutex::new(Vec::new())); + let handler = TestTraceHandler(traces.clone()); + + + let test_subscriber = sc_tracing::ProfilingSubscriber::new_with_handler( + Box::new(handler), "integration_test_span_target"); + + assert!(set_global_default(test_subscriber).is_ok()); + + let mut ext = TestExternalities::default(); + let mut ext = ext.ext(); + + // Test tracing disabled + assert!(!sp_tracing::wasm_tracing_enabled()); + + assert_eq!( + call_in_wasm( + "test_enter_span", + &[], + wasm_method, + &mut ext, + ).unwrap(), + 0u64.encode(), + ); + let len = traces.lock().unwrap().len(); + assert_eq!(len, 0); + + // Test tracing enabled + sp_tracing::set_wasm_tracing(true); + + assert_eq!( + call_in_wasm( + "test_enter_span", + &[], + wasm_method, + &mut ext, + ).unwrap(), + 1u64.encode(), + ); + + call_in_wasm( + "test_exit_span", + &[1u8,0,0,0,0,0,0,0].to_vec().encode(), + wasm_method, + &mut ext, + ).unwrap(); + + let len = traces.lock().unwrap().len(); + assert_eq!(len, 1); + + let (target, name) = traces.lock().unwrap().pop().unwrap(); + + assert_eq!(target, "integration_test_span_target"); + assert_eq!(name, "integration_test_span_name_wasm"); + +} diff --git a/client/service/src/builder.rs b/client/service/src/builder.rs index e2ec6108bc2a8..03a5f326cc251 100644 --- a/client/service/src/builder.rs +++ b/client/service/src/builder.rs @@ -50,7 +50,7 @@ use sc_executor::{NativeExecutor, NativeExecutionDispatch, RuntimeInfo}; use std::{ collections::HashMap, io::{Read, Write, Seek}, - marker::PhantomData, sync::{Arc, atomic::Ordering}, pin::Pin + marker::PhantomData, sync::Arc, pin::Pin }; use wasm_timer::SystemTime; use sc_telemetry::{telemetry, SUBSTRATE_INFO}; diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index d0704987b3f50..c7b419886e6df 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -42,9 +42,11 @@ use tracing_core::{ }; 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"; + /// Used to configure how to receive the metrics #[derive(Debug, Clone)] pub enum TracingReceiver { @@ -60,20 +62,26 @@ impl Default for TracingReceiver { } } +pub trait TraceHandler { + fn process_span(&self, span: SpanDatum); +} + +/// Represents a single instance of a tracing span #[derive(Debug)] -struct SpanDatum { - id: u64, - name: String, - target: String, - level: Level, - line: u32, - start_time: Instant, - overall_time: Duration, - values: Visitor, +pub struct SpanDatum { + pub id: u64, + pub name: String, + pub target: String, + pub level: Level, + pub line: u32, + pub start_time: Instant, + pub overall_time: Duration, + pub values: Visitor, } +/// Holds associated values for a tracing span #[derive(Clone, Debug)] -struct Visitor(FxHashMap); +pub struct Visitor(FxHashMap); impl Visit for Visitor { fn record_i64(&mut self, field: &Field, value: i64) { @@ -141,7 +149,7 @@ impl Value for Visitor { pub struct ProfilingSubscriber { next_id: AtomicU64, targets: Vec<(String, Level)>, - receiver: TracingReceiver, + trace_handler: Box, span_data: Mutex>, } @@ -149,12 +157,20 @@ impl ProfilingSubscriber { /// Takes a `Receiver` and a comma separated list of targets, /// either with a level: "pallet=trace" /// or without: "pallet". - pub fn new(receiver: TracingReceiver, targets: &str) -> Self { + pub fn new(receiver: TracingReceiver, targets: &str) -> ProfilingSubscriber { + match receiver { + TracingReceiver::Log => Self::new_with_handler(Box::new(LogTraceHandler), targets), + TracingReceiver::Telemetry => Self::new_with_handler(Box::new(TelemetryTraceHandler), targets), + } + } + + /// Allows use of a custom TraceHandler to create a new instance of ProfilingSubscriber + pub fn new_with_handler(trace_handler: Box, targets: &str) -> ProfilingSubscriber { let targets: Vec<_> = targets.split(',').map(|s| parse_target(s)).collect(); ProfilingSubscriber { next_id: AtomicU64::new(1), targets, - receiver, + trace_handler, span_data: Mutex::new(FxHashMap::default()), } } @@ -162,11 +178,9 @@ impl ProfilingSubscriber { fn check_target(&self, target: &str, level: &Level) -> bool { for t in &self.targets { if target.starts_with(t.0.as_str()) && level <= &t.1 { - log::debug!(target: "tracing", "Enabled target: {}, level: {}", target, level); return true; } } - log::debug!(target: "tracing", "Disabled target: {}, level: {}", target, level); false } } @@ -190,7 +204,13 @@ fn parse_target(s: &str) -> (String, Level) { impl Subscriber for ProfilingSubscriber { fn enabled(&self, metadata: &Metadata<'_>) -> bool { - metadata.target() == WASM_TARGET_KEY || self.check_target(metadata.target(), metadata.level()) + if metadata.target() == PROXY_TARGET || self.check_target(metadata.target(), metadata.level()) { + log::debug!(target: "tracing", "Enabled target: {}, level: {}", metadata.target(), metadata.level()); + true + } else { + log::debug!(target: "tracing", "Disabled target: {}, level: {}", metadata.target(), metadata.level()); + false + } } fn new_span(&self, attrs: &Attributes<'_>) -> Id { @@ -210,7 +230,7 @@ impl Subscriber for ProfilingSubscriber { level: attrs.metadata().level().clone(), line: attrs.metadata().line().unwrap_or(0), start_time: Instant::now(), - overall_time: Duration::from_nanos(0), + overall_time: ZERO_DURATION, values, }; self.span_data.lock().insert(id, span_datum); @@ -258,32 +278,29 @@ impl Subscriber for ProfilingSubscriber { span_datum.target = t; } } - self.send_span(span_datum); + if self.check_target(&span_datum.target, &span_datum.level) { + self.trace_handler.process_span(span_datum); + } }; true } } -impl ProfilingSubscriber { - fn send_span(&self, span_datum: SpanDatum) { - match self.receiver { - TracingReceiver::Log => print_log(span_datum), - TracingReceiver::Telemetry => send_telemetry(span_datum), - } - } -} +/// TraceHandler for sending span data to the logger +pub struct LogTraceHandler; -fn print_log(span_datum: SpanDatum) { - if span_datum.values.0.is_empty() { - log::info!("TRACING: {} {}: {}, line: {}, time: {}", +impl TraceHandler for LogTraceHandler { + fn process_span(&self, span_datum: SpanDatum) { + if span_datum.values.0.is_empty() { + log::info!("TRACING: {} {}: {}, line: {}, time: {}", span_datum.level, span_datum.target, span_datum.name, span_datum.line, span_datum.overall_time.as_nanos(), ); - } else { - log::info!("TRACING: {} {}: {}, line: {}, time: {}, {}", + } else { + log::info!("TRACING: {} {}: {}, line: {}, time: {}, {}", span_datum.level, span_datum.target, span_datum.name, @@ -291,15 +308,25 @@ fn print_log(span_datum: SpanDatum) { span_datum.overall_time.as_nanos(), span_datum.values ); + } } } -fn send_telemetry(span_datum: SpanDatum) { - telemetry!(SUBSTRATE_INFO; "tracing.profiling"; +/// TraceHandler for sending span data to telemetry, +/// Please see telemetry documentation for details on how to specify endpoints and +/// set the required telemetry level to activate tracing messages +pub struct TelemetryTraceHandler; + +impl TraceHandler for TelemetryTraceHandler { + fn process_span(&self, span_datum: SpanDatum) { + telemetry!(SUBSTRATE_INFO; "tracing.profiling"; "name" => span_datum.name, "target" => span_datum.target, "line" => span_datum.line, "time" => span_datum.overall_time.as_nanos(), "values" => span_datum.values - ); + ); + } } + + From 179a51575dd167e9b356b581b6a19250bb7b6a50 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 1 Jun 2020 15:54:06 +0100 Subject: [PATCH 46/75] tests --- client/executor/src/integration_tests/mod.rs | 1 - 1 file changed, 1 deletion(-) diff --git a/client/executor/src/integration_tests/mod.rs b/client/executor/src/integration_tests/mod.rs index 5a0f5b7f8f8b0..c9a93c23d8764 100644 --- a/client/executor/src/integration_tests/mod.rs +++ b/client/executor/src/integration_tests/mod.rs @@ -670,7 +670,6 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { impl sc_tracing::TraceHandler for TestTraceHandler { fn process_span(&self, sd: sc_tracing::SpanDatum) { - println!("{:?}",sd); self.0.lock().unwrap().push((sd.target, sd.name)); } } From a2fbef32229b2c016c6485b102ed21a3ac93360b Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 1 Jun 2020 15:59:25 +0100 Subject: [PATCH 47/75] revert formatting --- primitives/io/src/lib.rs | 19 ++++++++++--------- 1 file changed, 10 insertions(+), 9 deletions(-) diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index 094a87447e559..1feb846954fb5 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -23,9 +23,9 @@ #![cfg_attr(not(feature = "std"), feature(alloc_error_handler))] #![cfg_attr(feature = "std", -doc = "Substrate runtime standard library as compiled when linked with Rust's standard library.")] + doc = "Substrate runtime standard library as compiled when linked with Rust's standard library.")] #![cfg_attr(not(feature = "std"), -doc = "Substrate's runtime standard library as compiled without Rust's standard library.")] + doc = "Substrate's runtime standard library as compiled without Rust's standard library.")] use sp_std::vec::Vec; @@ -161,6 +161,7 @@ pub trait Storage { /// from within the runtime. #[runtime_interface] pub trait DefaultChildStorage { + /// Get a default child storage value for a given key. /// /// Parameter `storage_key` is the unprefixed location of the root of the child trie in the parent trie. @@ -1208,10 +1209,10 @@ mod tests { t.execute_with(|| { let mut v = [0u8; 4]; - assert!(storage::read(b":test", &mut v[..], 0).unwrap() > = 4); + assert!(storage::read(b":test", &mut v[..], 0).unwrap() >= 4); assert_eq!(v, [11u8, 0, 0, 0]); let mut w = [0u8; 11]; - assert!(storage::read(b":test", &mut w[..], 4).unwrap() > = 11); + assert!(storage::read(b":test", &mut w[..], 4).unwrap() >= 11); assert_eq!(&w, b"Hello world"); }); } @@ -1220,11 +1221,11 @@ mod tests { fn clear_prefix_works() { let mut t = BasicExternalities::new(Storage { top: map![ - b":a".to_vec() => b"\x0b\0\0\0Hello world".to_vec(), - b":abcd".to_vec() => b"\x0b\0\0\0Hello world".to_vec(), - b":abc".to_vec() => b"\x0b\0\0\0Hello world".to_vec(), - b":abdd".to_vec() => b"\x0b\0\0\0Hello world".to_vec() - ], + b":a".to_vec() => b"\x0b\0\0\0Hello world".to_vec(), + b":abcd".to_vec() => b"\x0b\0\0\0Hello world".to_vec(), + b":abc".to_vec() => b"\x0b\0\0\0Hello world".to_vec(), + b":abdd".to_vec() => b"\x0b\0\0\0Hello world".to_vec() + ], children_default: map![], }); From 74ec338235b24d3491baf14020ee706b37d14598 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 1 Jun 2020 18:58:24 +0100 Subject: [PATCH 48/75] try fix test that works locally but not in CI --- client/executor/src/integration_tests/mod.rs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/client/executor/src/integration_tests/mod.rs b/client/executor/src/integration_tests/mod.rs index c9a93c23d8764..b140551bcbe63 100644 --- a/client/executor/src/integration_tests/mod.rs +++ b/client/executor/src/integration_tests/mod.rs @@ -663,7 +663,6 @@ fn parallel_execution(wasm_method: WasmExecutionMethod) { #[cfg_attr(feature = "wasmtime", test_case(WasmExecutionMethod::Compiled))] fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { - use tracing::subscriber::set_global_default; use std::sync::{Arc, Mutex}; struct TestTraceHandler(Arc>>); @@ -681,7 +680,7 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { let test_subscriber = sc_tracing::ProfilingSubscriber::new_with_handler( Box::new(handler), "integration_test_span_target"); - assert!(set_global_default(test_subscriber).is_ok()); + let _guard = tracing::subscriber::set_default(test_subscriber); let mut ext = TestExternalities::default(); let mut ext = ext.ext(); From 749657b73fe5fa016a3f2a869a7ae3ab6283c3af Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 1 Jun 2020 19:12:51 +0100 Subject: [PATCH 49/75] try fix test that works locally but not in CI --- client/executor/src/integration_tests/mod.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/client/executor/src/integration_tests/mod.rs b/client/executor/src/integration_tests/mod.rs index b140551bcbe63..4f8cd79dde0b1 100644 --- a/client/executor/src/integration_tests/mod.rs +++ b/client/executor/src/integration_tests/mod.rs @@ -698,7 +698,7 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { 0u64.encode(), ); let len = traces.lock().unwrap().len(); - assert_eq!(len, 0); + assert_eq!(len, 0, "Len = {}, traces = {:?}", len, traces.lock().unwrap()); // Test tracing enabled sp_tracing::set_wasm_tracing(true); From 248f767613f665e7a19818c30ef6828212bb32d2 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 1 Jun 2020 19:28:26 +0100 Subject: [PATCH 50/75] debug test that works locally but not in CI --- client/executor/src/integration_tests/mod.rs | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/client/executor/src/integration_tests/mod.rs b/client/executor/src/integration_tests/mod.rs index 4f8cd79dde0b1..412728bd09d67 100644 --- a/client/executor/src/integration_tests/mod.rs +++ b/client/executor/src/integration_tests/mod.rs @@ -688,17 +688,19 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { // Test tracing disabled assert!(!sp_tracing::wasm_tracing_enabled()); - assert_eq!( - call_in_wasm( + let id = call_in_wasm( "test_enter_span", &[], wasm_method, &mut ext, - ).unwrap(), + ).unwrap(); + assert_eq!( + id, 0u64.encode(), + "traces = {:?}", traces.lock().unwrap() ); let len = traces.lock().unwrap().len(); - assert_eq!(len, 0, "Len = {}, traces = {:?}", len, traces.lock().unwrap()); + assert_eq!(len, 0); // Test tracing enabled sp_tracing::set_wasm_tracing(true); From 19cf0f95f3a30cc0e992810fd02730d11be98152 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 1 Jun 2020 20:35:16 +0100 Subject: [PATCH 51/75] fix test that works locally but not in CI --- client/executor/src/integration_tests/mod.rs | 11 +++-------- 1 file changed, 3 insertions(+), 8 deletions(-) diff --git a/client/executor/src/integration_tests/mod.rs b/client/executor/src/integration_tests/mod.rs index 412728bd09d67..94bda05912622 100644 --- a/client/executor/src/integration_tests/mod.rs +++ b/client/executor/src/integration_tests/mod.rs @@ -660,7 +660,6 @@ fn parallel_execution(wasm_method: WasmExecutionMethod) { } #[test_case(WasmExecutionMethod::Interpreted)] -#[cfg_attr(feature = "wasmtime", test_case(WasmExecutionMethod::Compiled))] fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { use std::sync::{Arc, Mutex}; @@ -676,7 +675,6 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { let traces = Arc::new(Mutex::new(Vec::new())); let handler = TestTraceHandler(traces.clone()); - let test_subscriber = sc_tracing::ProfilingSubscriber::new_with_handler( Box::new(handler), "integration_test_span_target"); @@ -688,16 +686,14 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { // Test tracing disabled assert!(!sp_tracing::wasm_tracing_enabled()); - let id = call_in_wasm( + assert_eq!( + call_in_wasm( "test_enter_span", &[], wasm_method, &mut ext, - ).unwrap(); - assert_eq!( - id, + ).unwrap(), 0u64.encode(), - "traces = {:?}", traces.lock().unwrap() ); let len = traces.lock().unwrap().len(); assert_eq!(len, 0); @@ -729,5 +725,4 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { assert_eq!(target, "integration_test_span_target"); assert_eq!(name, "integration_test_span_name_wasm"); - } From ffe508a8aa335f34e9c8f7b35b9df8284476468d Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 3 Jun 2020 13:36:22 +0100 Subject: [PATCH 52/75] remove pub visibility from bool in runtime --- frame/support/src/wasm_tracing.rs | 15 ++++++++++++--- 1 file changed, 12 insertions(+), 3 deletions(-) diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index 1492ab1294709..9bb4746ba7bd3 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -18,8 +18,17 @@ //! //! Facilitated by `sp_io::wasm_tracing` +static mut WASM_TRACING_ENABLED: bool = true; + /// Indicates whether to run traces in wasm -pub static mut WASM_TRACING_ENABLED: bool = true; +pub fn wasm_tracing_enabled() -> bool { + unsafe { WASM_TRACING_ENABLED } +} + +/// Disable wasm traces +pub fn disable_wasm_tracing() { + unsafe { WASM_TRACING_ENABLED = false } +} /// This holds a tracing span id and is to signal on drop that a tracing span has exited. /// It must be bound to a named variable eg. `_span_guard`. @@ -57,13 +66,13 @@ impl Drop for TracingSpanGuard { macro_rules! enter_span { ( $name:expr ) => { #[cfg(not(feature = "std"))] - let __span_id__ = if unsafe { $crate::wasm_tracing::WASM_TRACING_ENABLED } { + let __span_id__ = if $crate::wasm_tracing::wasm_tracing_enabled() { let id = $crate::sp_io::wasm_tracing::enter_span( module_path!(), $name ); if id == 0 { - unsafe { $crate::wasm_tracing::WASM_TRACING_ENABLED = false; } + $crate::wasm_tracing::disable_wasm_tracing(); $crate::wasm_tracing::TracingSpanGuard::new(None) } else { $crate::wasm_tracing::TracingSpanGuard::new(Some(id)) From d5ba777a3a20bb47adfa0736dae75bebccfe730e Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 4 Jun 2020 08:25:12 +0100 Subject: [PATCH 53/75] make TracingSpanGuard #[cfg(not(feature = "std"))], update docs, comments --- frame/support/src/wasm_tracing.rs | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index 9bb4746ba7bd3..49706e6f337e7 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -18,31 +18,36 @@ //! //! Facilitated by `sp_io::wasm_tracing` +// static mut has potential for data race conditions. +// For current use-case this is not an issue +#[cfg(not(feature = "std"))] static mut WASM_TRACING_ENABLED: bool = true; /// Indicates whether to run traces in wasm +#[cfg(not(feature = "std"))] pub fn wasm_tracing_enabled() -> bool { unsafe { WASM_TRACING_ENABLED } } /// Disable wasm traces +#[cfg(not(feature = "std"))] pub fn disable_wasm_tracing() { unsafe { WASM_TRACING_ENABLED = false } } /// This holds a tracing span id and is to signal on drop that a tracing span has exited. /// It must be bound to a named variable eg. `_span_guard`. -/// -/// 0 is a special inner value to indicate that the trace is disabled and should not call out -/// of the runtime. +#[cfg(not(feature = "std"))] pub struct TracingSpanGuard(Option); +#[cfg(not(feature = "std"))] impl TracingSpanGuard { pub fn new(span: Option) -> Self { Self(span) } } +#[cfg(not(feature = "std"))] impl Drop for TracingSpanGuard { fn drop(&mut self) { if let Some(id) = self.0.take() { From 25e24c47441b8c36b53a833038096ab95190ed4e Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 4 Jun 2020 09:27:03 +0100 Subject: [PATCH 54/75] make TracingProxy drop implementation conditional on !empty state --- primitives/io/src/lib.rs | 3 ++- primitives/tracing/src/proxy.rs | 14 ++++++++------ 2 files changed, 10 insertions(+), 7 deletions(-) diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index 1feb846954fb5..1d5e01bdffb62 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -975,12 +975,13 @@ sp_externalities::decl_extension! { #[runtime_interface] pub trait WasmTracing { /// To create and enter a `tracing` span, using `sp_tracing::proxy` + /// Returns 0 value to indicate that no further traces should be attempted fn enter_span(&mut self, target: &str, name: &str) -> u64 { if sp_tracing::wasm_tracing_enabled() { match self.extension::() { Some(proxy) => return proxy.enter_span(target, name), None => { - if let Ok(_) = self.register_extension(TracingProxyExt(sp_tracing::proxy::TracingProxy::new())) { + if self.register_extension(TracingProxyExt(sp_tracing::proxy::TracingProxy::new())).is_ok() { if let Some(proxy) = self.extension::() { return proxy.enter_span(target, name); } diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index ba3b7f3fc3150..02d951be9f023 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -48,12 +48,14 @@ pub struct TracingProxy { impl Drop for TracingProxy { fn drop(&mut self) { - log::debug!( - target: "tracing", - "Dropping TracingProxy with {} spans", self.spans.len() - ); - while let Some((_, mut sg)) = self.spans.pop() { - sg.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); + if !self.spans.is_empty() { + log::debug!( + target: "tracing", + "Dropping TracingProxy with {} un-exited spans, marking as not valid", self.spans.len() + ); + while let Some((_, mut sg)) = self.spans.pop() { + sg.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); + } } } } From da72fbd09f6a407419e661b4d9a2a2be784daaab Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 4 Jun 2020 09:31:46 +0100 Subject: [PATCH 55/75] add docs for TraceHandler --- client/tracing/src/lib.rs | 2 ++ 1 file changed, 2 insertions(+) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index c7b419886e6df..c2ac2b3bf8b62 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -62,7 +62,9 @@ impl Default for TracingReceiver { } } +/// A handler for tracing `SpanDatum` pub trait TraceHandler { + /// Process a `SpanDatum` fn process_span(&self, span: SpanDatum); } From f7adde5b15cab61d64dd4059094ad5b76573a6cf Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 4 Jun 2020 09:34:12 +0100 Subject: [PATCH 56/75] remove blank line --- client/service/Cargo.toml | 1 - 1 file changed, 1 deletion(-) diff --git a/client/service/Cargo.toml b/client/service/Cargo.toml index 6c6591fd558fd..025ee34a1e7f0 100644 --- a/client/service/Cargo.toml +++ b/client/service/Cargo.toml @@ -67,7 +67,6 @@ sc-block-builder = { version = "0.8.0-rc2", path = "../block-builder" } sp-block-builder = { version = "2.0.0-rc2", path = "../../primitives/block-builder" } sp-tracing = { version = "2.0.0-rc2", path = "../../primitives/tracing" } - sc-telemetry = { version = "2.0.0-rc2", path = "../telemetry" } sc-offchain = { version = "2.0.0-rc2", path = "../offchain" } parity-multiaddr = { package = "parity-multiaddr", version = "0.7.3" } From bed5bcb0046eb352e124e2576fefc43079352f3f Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 4 Jun 2020 09:36:50 +0100 Subject: [PATCH 57/75] update expect message --- primitives/tracing/src/proxy.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index 02d951be9f023..afe146ce09679 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -102,7 +102,7 @@ impl TracingProxy { log::warn!(target: "tracing", "Span id not found in TracingProxy: {}", id); return; } - let mut last_span = self.spans.pop().expect("Just checked that there is an element to pop"); + let mut last_span = self.spans.pop().expect("Just checked that there is an element to pop; qed"); while id < last_span.0 { log::warn!( target: "tracing", From 6f3602ee67e4a196dec85b5f2a1891ac2e8cb63b Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 4 Jun 2020 11:43:56 +0100 Subject: [PATCH 58/75] update tests --- client/executor/runtime-test/src/lib.rs | 6 +- client/executor/src/integration_tests/mod.rs | 58 ++++++++++++++------ 2 files changed, 44 insertions(+), 20 deletions(-) diff --git a/client/executor/runtime-test/src/lib.rs b/client/executor/runtime-test/src/lib.rs index bd7e242066851..fdb1484973a47 100644 --- a/client/executor/runtime-test/src/lib.rs +++ b/client/executor/runtime-test/src/lib.rs @@ -251,10 +251,8 @@ sp_core::wasm_export_functions! { wasm_tracing::enter_span("integration_test_span_target", "integration_test_span_name") } - fn test_exit_span(input: Vec) { - let mut array = [0u8; 8]; - array.clone_from_slice(&input); - wasm_tracing::exit_span(u64::from_le_bytes(array)) + fn test_exit_span(span_id: u64) { + wasm_tracing::exit_span(span_id) } fn returns_mutable_static() -> u64 { diff --git a/client/executor/src/integration_tests/mod.rs b/client/executor/src/integration_tests/mod.rs index 94bda05912622..f49d8f04ce386 100644 --- a/client/executor/src/integration_tests/mod.rs +++ b/client/executor/src/integration_tests/mod.rs @@ -686,43 +686,69 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { // Test tracing disabled assert!(!sp_tracing::wasm_tracing_enabled()); + let span_id = call_in_wasm( + "test_enter_span", + &[], + wasm_method, + &mut ext, + ).unwrap(); + assert_eq!( - call_in_wasm( - "test_enter_span", - &[], - wasm_method, - &mut ext, - ).unwrap(), 0u64.encode(), + span_id ); + // Repeat to check span id always 0 when deactivated + let span_id = call_in_wasm( + "test_enter_span", + &[], + wasm_method, + &mut ext, + ).unwrap(); + + assert_eq!( + 0u64.encode(), + span_id + ); + + call_in_wasm( + "test_exit_span", + &span_id.encode(), + wasm_method, + &mut ext, + ).unwrap(); + // Check span has not been recorded let len = traces.lock().unwrap().len(); assert_eq!(len, 0); // Test tracing enabled sp_tracing::set_wasm_tracing(true); - assert_eq!( - call_in_wasm( - "test_enter_span", - &[], - wasm_method, - &mut ext, - ).unwrap(), - 1u64.encode(), + let span_id = call_in_wasm( + "test_enter_span", + &[], + wasm_method, + &mut ext, + ).unwrap(); + + let span_id = u64::decode(&mut &span_id[..]).unwrap(); + + assert!( + span_id > 0 ); call_in_wasm( "test_exit_span", - &[1u8,0,0,0,0,0,0,0].to_vec().encode(), + &span_id.encode(), wasm_method, &mut ext, ).unwrap(); + // Check there is only the single trace let len = traces.lock().unwrap().len(); assert_eq!(len, 1); let (target, name) = traces.lock().unwrap().pop().unwrap(); - + // Ensure that the wasm trace has correct target and name and has "_wasm" appended to the name assert_eq!(target, "integration_test_span_target"); assert_eq!(name, "integration_test_span_name_wasm"); } From 1f016b9047db1636e583118d686c6571adec5ad5 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 4 Jun 2020 12:09:50 +0100 Subject: [PATCH 59/75] rename cli option to tracing_enable_wasm --- client/cli/src/commands/mod.rs | 4 ++-- client/cli/src/config.rs | 6 +++--- client/cli/src/params/import_params.rs | 6 +++--- client/service/src/builder.rs | 2 +- client/service/src/config.rs | 2 +- client/service/test/src/lib.rs | 2 +- 6 files changed, 11 insertions(+), 11 deletions(-) diff --git a/client/cli/src/commands/mod.rs b/client/cli/src/commands/mod.rs index f3ef386ba99d1..773a3dce8f7f7 100644 --- a/client/cli/src/commands/mod.rs +++ b/client/cli/src/commands/mod.rs @@ -384,9 +384,9 @@ macro_rules! substrate_cli_subcommands { } } - fn wasm_tracing(&self) -> $crate::Result { + fn tracing_enable_wasm(&self) -> $crate::Result { match self { - $($enum::$variant(cmd) => cmd.wasm_tracing()),* + $($enum::$variant(cmd) => cmd.tracing_enable_wasm()),* } } diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index d79e75af1f671..a9736f77b248a 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -372,9 +372,9 @@ pub trait CliConfiguration: Sized { /// Returns `Ok(true)` if wasm tracing should be enabled /// /// By default this is `false`. - fn wasm_tracing(&self) -> Result { + fn tracing_enable_wasm(&self) -> Result { Ok(self.import_params() - .map(|x| x.wasm_tracing()) + .map(|x| x.tracing_enable_wasm()) .unwrap_or_default()) } @@ -469,7 +469,7 @@ pub trait CliConfiguration: Sized { dev_key_seed: self.dev_key_seed(is_dev)?, tracing_targets: self.tracing_targets()?, tracing_receiver: self.tracing_receiver()?, - wasm_tracing: self.wasm_tracing()?, + tracing_enable_wasm: self.tracing_enable_wasm()?, chain_spec, max_runtime_instances, announce_block: self.announce_block()?, diff --git a/client/cli/src/params/import_params.rs b/client/cli/src/params/import_params.rs index 02e9a9338c498..703a517bcdc75 100644 --- a/client/cli/src/params/import_params.rs +++ b/client/cli/src/params/import_params.rs @@ -83,7 +83,7 @@ pub struct ImportParams { /// Enable wasm tracing #[structopt(long)] - pub wasm_tracing: bool, + pub tracing_enable_wasm: bool, } impl ImportParams { @@ -98,8 +98,8 @@ impl ImportParams { } /// Flag to enable wasm tracing. - pub fn wasm_tracing(&self) -> bool { - self.wasm_tracing + pub fn tracing_enable_wasm(&self) -> bool { + self.tracing_enable_wasm } /// Specify the state cache size. diff --git a/client/service/src/builder.rs b/client/service/src/builder.rs index 374293c47ca1b..41e6b54d39c9d 100644 --- a/client/service/src/builder.rs +++ b/client/service/src/builder.rs @@ -1328,7 +1328,7 @@ ServiceBuilder< let subscriber = sc_tracing::ProfilingSubscriber::new( config.tracing_receiver, tracing_targets ); - sp_tracing::set_wasm_tracing(config.wasm_tracing); + sp_tracing::set_wasm_tracing(config.tracing_enable_wasm); match tracing::subscriber::set_global_default(subscriber) { Ok(_) => (), Err(e) => error!(target: "tracing", "Unable to set global default subscriber {}", e), diff --git a/client/service/src/config.rs b/client/service/src/config.rs index f856d2a396e13..4ac964b2080f4 100644 --- a/client/service/src/config.rs +++ b/client/service/src/config.rs @@ -97,7 +97,7 @@ pub struct Configuration { /// Tracing receiver pub tracing_receiver: sc_tracing::TracingReceiver, /// Enable wasm tracing - pub wasm_tracing: bool, + pub tracing_enable_wasm: bool, /// The size of the instances cache. /// /// The default value is 8. diff --git a/client/service/test/src/lib.rs b/client/service/test/src/lib.rs index dc2dd1be5dfa4..30d2e23ffe610 100644 --- a/client/service/test/src/lib.rs +++ b/client/service/test/src/lib.rs @@ -208,7 +208,7 @@ fn node_config Date: Thu, 4 Jun 2020 13:31:43 +0100 Subject: [PATCH 60/75] rename cli option to tracing_enable_wasm --- utils/browser/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/utils/browser/src/lib.rs b/utils/browser/src/lib.rs index 49e6c36d1b6a2..84a60b9b6646c 100644 --- a/utils/browser/src/lib.rs +++ b/utils/browser/src/lib.rs @@ -93,7 +93,7 @@ where state_cache_size: Default::default(), tracing_receiver: Default::default(), tracing_targets: Default::default(), - wasm_tracing: Default::default(), + tracing_enable_wasm: Default::default(), transaction_pool: Default::default(), wasm_method: Default::default(), max_runtime_instances: 8, From 01693e03b077ba09bae5a6dfa112ded41ebae113 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 4 Jun 2020 14:12:53 +0100 Subject: [PATCH 61/75] fix --- frame/support/src/wasm_tracing.rs | 6 ------ 1 file changed, 6 deletions(-) diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index 49706e6f337e7..ffff349098fc5 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -20,34 +20,28 @@ // static mut has potential for data race conditions. // For current use-case this is not an issue -#[cfg(not(feature = "std"))] static mut WASM_TRACING_ENABLED: bool = true; /// Indicates whether to run traces in wasm -#[cfg(not(feature = "std"))] pub fn wasm_tracing_enabled() -> bool { unsafe { WASM_TRACING_ENABLED } } /// Disable wasm traces -#[cfg(not(feature = "std"))] pub fn disable_wasm_tracing() { unsafe { WASM_TRACING_ENABLED = false } } /// This holds a tracing span id and is to signal on drop that a tracing span has exited. /// It must be bound to a named variable eg. `_span_guard`. -#[cfg(not(feature = "std"))] pub struct TracingSpanGuard(Option); -#[cfg(not(feature = "std"))] impl TracingSpanGuard { pub fn new(span: Option) -> Self { Self(span) } } -#[cfg(not(feature = "std"))] impl Drop for TracingSpanGuard { fn drop(&mut self) { if let Some(id) = self.0.take() { From a17775c09b9b2d95bbf0a3b839e78aebf42a1564 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Tue, 9 Jun 2020 15:25:53 +0100 Subject: [PATCH 62/75] ensure wasm-tracing features are wasm only --- frame/support/src/wasm_tracing.rs | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index ffff349098fc5..746a7db7a07d9 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -19,29 +19,35 @@ //! Facilitated by `sp_io::wasm_tracing` // static mut has potential for data race conditions. -// For current use-case this is not an issue +// For current use-case this is not an issue, must only be used in wasmß +#[cfg(not(feature = "std"))] static mut WASM_TRACING_ENABLED: bool = true; /// Indicates whether to run traces in wasm +#[cfg(not(feature = "std"))] pub fn wasm_tracing_enabled() -> bool { unsafe { WASM_TRACING_ENABLED } } /// Disable wasm traces +#[cfg(not(feature = "std"))] pub fn disable_wasm_tracing() { unsafe { WASM_TRACING_ENABLED = false } } /// This holds a tracing span id and is to signal on drop that a tracing span has exited. /// It must be bound to a named variable eg. `_span_guard`. +#[cfg(not(feature = "std"))] pub struct TracingSpanGuard(Option); +#[cfg(not(feature = "std"))] impl TracingSpanGuard { pub fn new(span: Option) -> Self { Self(span) } } +#[cfg(not(feature = "std"))] impl Drop for TracingSpanGuard { fn drop(&mut self) { if let Some(id) = self.0.take() { From 2aa7c72b10011c69e341cbdafce13a3e59648315 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Tue, 9 Jun 2020 15:42:26 +0100 Subject: [PATCH 63/75] bump impl_version --- bin/node/runtime/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/bin/node/runtime/src/lib.rs b/bin/node/runtime/src/lib.rs index 5a56ca4a7b5ea..cab643a8515de 100644 --- a/bin/node/runtime/src/lib.rs +++ b/bin/node/runtime/src/lib.rs @@ -96,7 +96,7 @@ pub const VERSION: RuntimeVersion = RuntimeVersion { // implementation changes and behavior does not, then leave spec_version as // is and increment impl_version. spec_version: 251, - impl_version: 2, + impl_version: 3, apis: RUNTIME_API_VERSIONS, transaction_version: 1, }; From bc9ec21535e42cb23afd5dd467f7afa8dc155b00 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Tue, 9 Jun 2020 15:44:48 +0100 Subject: [PATCH 64/75] bump impl_version --- bin/node/runtime/src/lib.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/bin/node/runtime/src/lib.rs b/bin/node/runtime/src/lib.rs index f92189e3c920a..5657961f61d7c 100644 --- a/bin/node/runtime/src/lib.rs +++ b/bin/node/runtime/src/lib.rs @@ -96,7 +96,7 @@ pub const VERSION: RuntimeVersion = RuntimeVersion { // implementation changes and behavior does not, then leave spec_version as // is and increment impl_version. spec_version: 252, - impl_version: 0, + impl_version: 1, apis: RUNTIME_API_VERSIONS, transaction_version: 1, }; From 32b8e362bc1a966ceca5502314f04aeaffdffac0 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Tue, 9 Jun 2020 18:52:05 +0100 Subject: [PATCH 65/75] add `"pallet-scheduler/std"` to `[features]` `std` in node/runtime --- bin/node/runtime/Cargo.toml | 1 + 1 file changed, 1 insertion(+) diff --git a/bin/node/runtime/Cargo.toml b/bin/node/runtime/Cargo.toml index ebe3196dd744e..7cc4018fb6c4c 100644 --- a/bin/node/runtime/Cargo.toml +++ b/bin/node/runtime/Cargo.toml @@ -111,6 +111,7 @@ std = [ "pallet-membership/std", "pallet-multisig/std", "pallet-identity/std", + "pallet-scheduler/std", "node-primitives/std", "sp-offchain/std", "pallet-offences/std", From 9835a01049743577de4e25ecc758cd2e64b9fa75 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 10 Jun 2020 10:04:53 +0100 Subject: [PATCH 66/75] refactor service to remove sp_tracing dependency --- Cargo.lock | 1 - client/service/Cargo.toml | 1 - client/service/src/builder.rs | 3 +-- client/tracing/src/lib.rs | 22 ++++++++++++++-------- 4 files changed, 15 insertions(+), 12 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 6141402477241..4ab7223cd386c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6679,7 +6679,6 @@ dependencies = [ "sp-runtime", "sp-session", "sp-state-machine", - "sp-tracing", "sp-transaction-pool", "sp-trie", "sp-utils", diff --git a/client/service/Cargo.toml b/client/service/Cargo.toml index 1dbb4c8cf862e..f3687a2b8a660 100644 --- a/client/service/Cargo.toml +++ b/client/service/Cargo.toml @@ -72,7 +72,6 @@ sc-telemetry = { version = "2.0.0-rc3", path = "../telemetry" } sc-offchain = { version = "2.0.0-rc3", path = "../offchain" } parity-multiaddr = { package = "parity-multiaddr", version = "0.7.3" } prometheus-endpoint = { package = "substrate-prometheus-endpoint", path = "../../utils/prometheus" , version = "0.8.0-rc3"} -sp-tracing = { version = "2.0.0-rc3", path = "../../primitives/tracing" } sc-tracing = { version = "2.0.0-rc3", path = "../tracing" } tracing = "0.1.10" parity-util-mem = { version = "0.6.1", default-features = false, features = ["primitive-types"] } diff --git a/client/service/src/builder.rs b/client/service/src/builder.rs index f6bf15834fd46..754974baf8fe0 100644 --- a/client/service/src/builder.rs +++ b/client/service/src/builder.rs @@ -1379,9 +1379,8 @@ ServiceBuilder< // Instrumentation if let Some(tracing_targets) = config.tracing_targets.as_ref() { let subscriber = sc_tracing::ProfilingSubscriber::new( - config.tracing_receiver, tracing_targets + config.tracing_receiver, tracing_targets, config.tracing_enable_wasm ); - sp_tracing::set_wasm_tracing(config.tracing_enable_wasm); match tracing::subscriber::set_global_default(subscriber) { Ok(_) => (), Err(e) => error!(target: "tracing", "Unable to set global default subscriber {}", e), diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index c2ac2b3bf8b62..b4e8d4c69a260 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -156,18 +156,24 @@ pub struct ProfilingSubscriber { } impl ProfilingSubscriber { - /// Takes a `Receiver` and a comma separated list of targets, - /// either with a level: "pallet=trace" - /// or without: "pallet". - pub fn new(receiver: TracingReceiver, targets: &str) -> ProfilingSubscriber { + /// Takes a `TracingReceiver` and a comma separated list of targets, + /// either with a level: "pallet=trace,frame=debug" + /// or without: "pallet,frame" in which case the level defaults to `trace`. + /// wasm_tracing indicates whether to enable wasm traces + pub fn new(receiver: TracingReceiver, targets: &str, wasm_tracing: bool) -> ProfilingSubscriber { match receiver { - TracingReceiver::Log => Self::new_with_handler(Box::new(LogTraceHandler), targets), - TracingReceiver::Telemetry => Self::new_with_handler(Box::new(TelemetryTraceHandler), targets), + TracingReceiver::Log => Self::new_with_handler(Box::new(LogTraceHandler), targets, wasm_tracing), + TracingReceiver::Telemetry => Self::new_with_handler(Box::new(TelemetryTraceHandler), targets, wasm_tracing), } } - /// Allows use of a custom TraceHandler to create a new instance of ProfilingSubscriber - pub fn new_with_handler(trace_handler: Box, targets: &str) -> ProfilingSubscriber { + /// Allows use of a custom TraceHandler to create a new instance of ProfilingSubscriber. + /// Takes a comma separated list of targets, + /// either with a level, eg: "pallet=trace" + /// or without: "pallet" in which case the level defaults to `trace`. + /// wasm_tracing indicates whether to enable wasm traces + pub fn new_with_handler(trace_handler: Box, targets: &str, wasm_tracing: bool) -> ProfilingSubscriber { + sp_tracing::set_wasm_tracing(wasm_tracing); let targets: Vec<_> = targets.split(',').map(|s| parse_target(s)).collect(); ProfilingSubscriber { next_id: AtomicU64::new(1), From 8b168819f313251f170a686b011c89f997bdd4f5 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 10 Jun 2020 10:19:08 +0100 Subject: [PATCH 67/75] refactor: line width, trait bounds --- client/tracing/src/lib.rs | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index b4e8d4c69a260..dcd611c0767b3 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -63,7 +63,7 @@ impl Default for TracingReceiver { } /// A handler for tracing `SpanDatum` -pub trait TraceHandler { +pub trait TraceHandler: Send + Sync { /// Process a `SpanDatum` fn process_span(&self, span: SpanDatum); } @@ -151,7 +151,7 @@ impl Value for Visitor { pub struct ProfilingSubscriber { next_id: AtomicU64, targets: Vec<(String, Level)>, - trace_handler: Box, + trace_handler: Box, span_data: Mutex>, } @@ -163,7 +163,10 @@ impl ProfilingSubscriber { pub fn new(receiver: TracingReceiver, targets: &str, wasm_tracing: bool) -> ProfilingSubscriber { match receiver { TracingReceiver::Log => Self::new_with_handler(Box::new(LogTraceHandler), targets, wasm_tracing), - TracingReceiver::Telemetry => Self::new_with_handler(Box::new(TelemetryTraceHandler), targets, wasm_tracing), + TracingReceiver::Telemetry => Self::new_with_handler( + Box::new(TelemetryTraceHandler), + targets, + wasm_tracing), } } @@ -172,7 +175,9 @@ impl ProfilingSubscriber { /// either with a level, eg: "pallet=trace" /// or without: "pallet" in which case the level defaults to `trace`. /// wasm_tracing indicates whether to enable wasm traces - pub fn new_with_handler(trace_handler: Box, targets: &str, wasm_tracing: bool) -> ProfilingSubscriber { + pub fn new_with_handler(trace_handler: Box, targets: &str, wasm_tracing: bool) + -> ProfilingSubscriber + { sp_tracing::set_wasm_tracing(wasm_tracing); let targets: Vec<_> = targets.split(',').map(|s| parse_target(s)).collect(); ProfilingSubscriber { From 068fd943657abb46095ae4738841e48ca3d49323 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 10 Jun 2020 10:33:26 +0100 Subject: [PATCH 68/75] improve LogTraceHandler output --- client/tracing/src/lib.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index dcd611c0767b3..794135fffa7d3 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -305,7 +305,7 @@ pub struct LogTraceHandler; impl TraceHandler for LogTraceHandler { fn process_span(&self, span_datum: SpanDatum) { if span_datum.values.0.is_empty() { - log::info!("TRACING: {} {}: {}, line: {}, time: {}", + log::info!("{} {}: {}, line: {}, time: {}", span_datum.level, span_datum.target, span_datum.name, @@ -313,7 +313,7 @@ impl TraceHandler for LogTraceHandler { span_datum.overall_time.as_nanos(), ); } else { - log::info!("TRACING: {} {}: {}, line: {}, time: {}, {}", + log::info!("{} {}: {}, line: {}, time: {}, {}", span_datum.level, span_datum.target, span_datum.name, From 14a90aefb103dc8bd143f1b7f3a6d822f99b5732 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Wed, 10 Jun 2020 11:33:47 +0100 Subject: [PATCH 69/75] fix test --- client/executor/src/integration_tests/mod.rs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/client/executor/src/integration_tests/mod.rs b/client/executor/src/integration_tests/mod.rs index f49d8f04ce386..e9e71925ffef2 100644 --- a/client/executor/src/integration_tests/mod.rs +++ b/client/executor/src/integration_tests/mod.rs @@ -675,8 +675,9 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { let traces = Arc::new(Mutex::new(Vec::new())); let handler = TestTraceHandler(traces.clone()); + // Create subscriber with wasm_tracing disabled let test_subscriber = sc_tracing::ProfilingSubscriber::new_with_handler( - Box::new(handler), "integration_test_span_target"); + Box::new(handler), "integration_test_span_target", false); let _guard = tracing::subscriber::set_default(test_subscriber); From b822794e92c92ff7b6704b7bfc79b2ef091a06c1 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Thu, 11 Jun 2020 09:52:36 +0100 Subject: [PATCH 70/75] improve tracing log output --- client/cli/src/lib.rs | 2 +- client/tracing/src/lib.rs | 34 +++++++++++++++++-------------- frame/support/src/wasm_tracing.rs | 2 +- 3 files changed, 21 insertions(+), 17 deletions(-) diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index 1acd5ee60474a..8a5e9d62a414f 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -223,7 +223,7 @@ pub fn init_logger(pattern: &str) { builder.filter(Some("hyper"), log::LevelFilter::Warn); builder.filter(Some("cranelift_wasm"), log::LevelFilter::Warn); // Always log the special target `sc_tracing`, overrides global level - builder.filter(Some("sc_tracing"), log::LevelFilter::Info); + builder.filter(Some("sc_tracing"), log::LevelFilter::Trace); // Enable info for others. builder.filter(None, log::LevelFilter::Info); diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 794135fffa7d3..76fd61a1d0414 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -302,25 +302,29 @@ impl Subscriber for ProfilingSubscriber { /// TraceHandler for sending span data to the logger pub struct LogTraceHandler; +fn log_level(level: Level) -> log::Level { + match level { + Level::TRACE => log::Level::Trace, + Level::DEBUG => log::Level::Debug, + Level::INFO => log::Level::Info, + Level::WARN => log::Level::Warn, + Level::ERROR => log::Level::Error, + } +} + impl TraceHandler for LogTraceHandler { fn process_span(&self, span_datum: SpanDatum) { if span_datum.values.0.is_empty() { - log::info!("{} {}: {}, line: {}, time: {}", - span_datum.level, - span_datum.target, - span_datum.name, - span_datum.line, - span_datum.overall_time.as_nanos(), - ); + log::log!(log_level(span_datum.level), "{}: {}, time: {}", + span_datum.target, + span_datum.name, + span_datum.overall_time.as_nanos()); } else { - log::info!("{} {}: {}, line: {}, time: {}, {}", - span_datum.level, - span_datum.target, - span_datum.name, - span_datum.line, - span_datum.overall_time.as_nanos(), - span_datum.values - ); + log::log!(log_level(span_datum.level), "{}: {}, time: {}, {}", + span_datum.target, + span_datum.name, + span_datum.overall_time.as_nanos(), + span_datum.values); } } } diff --git a/frame/support/src/wasm_tracing.rs b/frame/support/src/wasm_tracing.rs index 746a7db7a07d9..e40dba6ce75a7 100644 --- a/frame/support/src/wasm_tracing.rs +++ b/frame/support/src/wasm_tracing.rs @@ -19,7 +19,7 @@ //! Facilitated by `sp_io::wasm_tracing` // static mut has potential for data race conditions. -// For current use-case this is not an issue, must only be used in wasmß +// For current use-case this is not an issue, must only be used in wasm #[cfg(not(feature = "std"))] static mut WASM_TRACING_ENABLED: bool = true; From 157a639a14c25584efa219b924d4497cae6b0298 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Thu, 11 Jun 2020 11:02:48 +0200 Subject: [PATCH 71/75] Apply suggestions from code review --- primitives/tracing/src/proxy.rs | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/primitives/tracing/src/proxy.rs b/primitives/tracing/src/proxy.rs index afe146ce09679..270f57aaa69f0 100644 --- a/primitives/tracing/src/proxy.rs +++ b/primitives/tracing/src/proxy.rs @@ -88,7 +88,7 @@ impl TracingProxy { // 2. Not correctly exiting spans due to misconfiguration / misuse log::warn!( target: "tracing", - "TracingProxy MAX_SPANS_LEN exceeded, removing oldest span, recording `is_valid_trace = false`" + "TracingProxy MAX_SPANS_LEN exceeded, removing oldest span." ); let mut sg = self.spans.remove(0).1; sg.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); @@ -106,7 +106,9 @@ impl TracingProxy { while id < last_span.0 { log::warn!( target: "tracing", - "TracingProxy Span ids not equal! id parameter given: {}, last span: {}", id, last_span.0 + "TracingProxy Span ids not equal! id parameter given: {}, last span: {}", + id, + last_span.0, ); last_span.1.rent_all_mut(|s| { s.span.record("is_valid_trace", &false); }); if let Some(s) = self.spans.pop() { From 88c3d713f3ac70505125d79cfb842c8b8854ff7b Mon Sep 17 00:00:00 2001 From: mattrutherford <44339188+mattrutherford@users.noreply.github.com> Date: Mon, 15 Jun 2020 14:28:19 +0100 Subject: [PATCH 72/75] 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 | 18 ++++++++++++------ 1 file changed, 12 insertions(+), 6 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 76fd61a1d0414..9e63fe3d57cd2 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -166,7 +166,8 @@ impl ProfilingSubscriber { TracingReceiver::Telemetry => Self::new_with_handler( Box::new(TelemetryTraceHandler), targets, - wasm_tracing), + wasm_tracing, + ), } } @@ -315,16 +316,22 @@ fn log_level(level: Level) -> log::Level { 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::log!( + log_level(span_datum.level), + "{}: {}, time: {}", span_datum.target, span_datum.name, - span_datum.overall_time.as_nanos()); + span_datum.overall_time.as_nanos(), + ); } else { - log::log!(log_level(span_datum.level), "{}: {}, time: {}, {}", + log::log!( + log_level(span_datum.level), + "{}: {}, time: {}, {}", span_datum.target, span_datum.name, span_datum.overall_time.as_nanos(), - span_datum.values); + span_datum.values, + ); } } } @@ -346,4 +353,3 @@ impl TraceHandler for TelemetryTraceHandler { } } - From c36fc2a3c4f6fe2f2fd4adca277392b9956ef7e5 Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Mon, 15 Jun 2020 17:56:13 +0100 Subject: [PATCH 73/75] swap wasm indication from trace name to a separate value --- client/executor/src/integration_tests/mod.rs | 18 +++++++++++------- client/tracing/src/lib.rs | 9 ++++++++- frame/support/src/lib.rs | 2 -- 3 files changed, 19 insertions(+), 10 deletions(-) diff --git a/client/executor/src/integration_tests/mod.rs b/client/executor/src/integration_tests/mod.rs index e9e71925ffef2..56baa2cc3f0d5 100644 --- a/client/executor/src/integration_tests/mod.rs +++ b/client/executor/src/integration_tests/mod.rs @@ -664,14 +664,16 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { use std::sync::{Arc, Mutex}; - struct TestTraceHandler(Arc>>); + use sc_tracing::SpanDatum; impl sc_tracing::TraceHandler for TestTraceHandler { - fn process_span(&self, sd: sc_tracing::SpanDatum) { - self.0.lock().unwrap().push((sd.target, sd.name)); + fn process_span(&self, sd: SpanDatum) { + self.0.lock().unwrap().push(sd); } } + struct TestTraceHandler(Arc>>); + let traces = Arc::new(Mutex::new(Vec::new())); let handler = TestTraceHandler(traces.clone()); @@ -748,8 +750,10 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { let len = traces.lock().unwrap().len(); assert_eq!(len, 1); - let (target, name) = traces.lock().unwrap().pop().unwrap(); - // Ensure that the wasm trace has correct target and name and has "_wasm" appended to the name - assert_eq!(target, "integration_test_span_target"); - assert_eq!(name, "integration_test_span_name_wasm"); + let span_datum = traces.lock().unwrap().pop().unwrap(); + let values = span_datum.values.into_inner(); + assert_eq!(span_datum.target, "integration_test_span_target"); + assert_eq!(span_datum.name, "integration_test_span_name"); + assert_eq!(values.get("wasm").unwrap(), "true"); + assert_eq!(values.get("is_valid_trace").unwrap(), "true"); } diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 9e63fe3d57cd2..eff694b9e47b1 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -85,6 +85,12 @@ pub struct SpanDatum { #[derive(Clone, Debug)] pub struct Visitor(FxHashMap); +impl Visitor { + pub fn into_inner(self) -> FxHashMap { + self.0 + } +} + impl Visit for Visitor { fn record_i64(&mut self, field: &Field, value: i64) { self.0.insert(field.name().to_string(), value.to_string()); @@ -285,8 +291,9 @@ impl Subscriber for ProfilingSubscriber { }; if let Some(mut span_datum) = span_datum { if span_datum.name == WASM_TRACE_IDENTIFIER { + span_datum.values.0.insert("wasm".to_owned(), "true".to_owned()); if let Some(n) = span_datum.values.0.remove(WASM_NAME_KEY) { - span_datum.name = [&n, "_wasm"].concat(); + span_datum.name = n; } if let Some(t) = span_datum.values.0.remove(WASM_TARGET_KEY) { span_datum.target = t; diff --git a/frame/support/src/lib.rs b/frame/support/src/lib.rs index a34f3bdf9f35a..7d7d6cdc976bf 100644 --- a/frame/support/src/lib.rs +++ b/frame/support/src/lib.rs @@ -27,8 +27,6 @@ extern crate bitmask; #[doc(hidden)] pub use sp_tracing; -#[doc(hidden)] -pub use sp_io; #[cfg(feature = "std")] pub use serde; From d9ebb3bc2583c0baab7c439c76703979a87c85cb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Mon, 15 Jun 2020 22:52:48 +0200 Subject: [PATCH 74/75] Update client/tracing/src/lib.rs --- client/tracing/src/lib.rs | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index eff694b9e47b1..9a4b5d28504ae 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -351,12 +351,11 @@ pub struct TelemetryTraceHandler; impl TraceHandler for TelemetryTraceHandler { fn process_span(&self, span_datum: SpanDatum) { telemetry!(SUBSTRATE_INFO; "tracing.profiling"; - "name" => span_datum.name, - "target" => span_datum.target, - "line" => span_datum.line, - "time" => span_datum.overall_time.as_nanos(), - "values" => span_datum.values + "name" => span_datum.name, + "target" => span_datum.target, + "line" => span_datum.line, + "time" => span_datum.overall_time.as_nanos(), + "values" => span_datum.values ); } } - From 1811e0581bf92fe79b23b5cdce7155ea06f4d3df Mon Sep 17 00:00:00 2001 From: Matt Rutherford Date: Tue, 16 Jun 2020 10:25:47 +0100 Subject: [PATCH 75/75] add docs --- client/tracing/src/lib.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/client/tracing/src/lib.rs b/client/tracing/src/lib.rs index 9a4b5d28504ae..ec52bb411f67a 100644 --- a/client/tracing/src/lib.rs +++ b/client/tracing/src/lib.rs @@ -86,6 +86,7 @@ pub struct SpanDatum { pub struct Visitor(FxHashMap); impl Visitor { + /// Consume the Visitor, returning the inner FxHashMap pub fn into_inner(self) -> FxHashMap { self.0 }