diff --git a/Cargo.lock b/Cargo.lock index 83c98c65c6cb0..4d78d81fb4428 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5563,6 +5563,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.6", + "syn 1.0.17", +] + [[package]] name = "ring" version = "0.16.12" @@ -6173,6 +6194,7 @@ dependencies = [ "sc-executor-wasmi", "sc-executor-wasmtime", "sc-runtime-test", + "sc-tracing", "sp-api", "sp-core", "sp-externalities", @@ -6182,11 +6204,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", ] @@ -6745,10 +6769,12 @@ dependencies = [ "erased-serde", "log", "parking_lot 0.10.2", + "rustc-hash", "sc-telemetry", "serde", "serde_json", "slog", + "sp-tracing", "tracing", "tracing-core", ] @@ -7506,6 +7532,7 @@ dependencies = [ "sp-runtime-interface", "sp-state-machine", "sp-std", + "sp-tracing", "sp-trie", "sp-wasm-interface", ] @@ -7781,6 +7808,8 @@ dependencies = [ name = "sp-tracing" version = "2.0.0-rc3" dependencies = [ + "log", + "rental", "tracing", ] @@ -8814,9 +8843,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", @@ -8825,10 +8854,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.6", "syn 1.0.17", ] 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", diff --git a/client/cli/src/commands/mod.rs b/client/cli/src/commands/mod.rs index 6931a8715c4fd..d714f4a8578f9 100644 --- a/client/cli/src/commands/mod.rs +++ b/client/cli/src/commands/mod.rs @@ -384,6 +384,12 @@ macro_rules! substrate_cli_subcommands { } } + fn tracing_enable_wasm(&self) -> $crate::Result { + match self { + $($enum::$variant(cmd) => cmd.tracing_enable_wasm()),* + } + } + 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 d121546c193a0..535a3981fb6ed 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -374,6 +374,15 @@ pub trait CliConfiguration: Sized { .unwrap_or(Default::default())) } + /// Returns `Ok(true)` if wasm tracing should be enabled + /// + /// By default this is `false`. + fn tracing_enable_wasm(&self) -> Result { + Ok(self.import_params() + .map(|x| x.tracing_enable_wasm()) + .unwrap_or_default()) + } + /// Get the node key from the current object /// /// By default this is retrieved from `NodeKeyParams` if it is available. Otherwise its @@ -464,6 +473,7 @@ pub trait CliConfiguration: Sized { dev_key_seed: self.dev_key_seed(is_dev)?, tracing_targets: self.tracing_targets()?, tracing_receiver: self.tracing_receiver()?, + tracing_enable_wasm: self.tracing_enable_wasm()?, chain_spec, max_runtime_instances, announce_block: self.announce_block()?, 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/cli/src/params/import_params.rs b/client/cli/src/params/import_params.rs index c2fb34f90e6fc..306cc6e0c6737 100644 --- a/client/cli/src/params/import_params.rs +++ b/client/cli/src/params/import_params.rs @@ -80,6 +80,10 @@ pub struct ImportParams { default_value = "Log" )] pub tracing_receiver: TracingReceiver, + + /// Enable wasm tracing + #[structopt(long)] + pub tracing_enable_wasm: bool, } impl ImportParams { @@ -93,6 +97,11 @@ impl ImportParams { self.tracing_targets.clone() } + /// Flag to enable wasm tracing. + pub fn tracing_enable_wasm(&self) -> bool { + self.tracing_enable_wasm + } + /// Specify the state cache size. pub fn state_cache_size(&self) -> usize { self.state_cache_size diff --git a/client/executor/Cargo.toml b/client/executor/Cargo.toml index 9eee3de1e26a2..96d2d9eb94ca2 100644 --- a/client/executor/Cargo.toml +++ b/client/executor/Cargo.toml @@ -44,6 +44,9 @@ substrate-test-runtime = { version = "2.0.0-rc3", path = "../../test-utils/runti sp-state-machine = { version = "0.8.0-rc3", path = "../../primitives/state-machine" } test-case = "0.3.3" sp-runtime = { version = "2.0.0-rc3", path = "../../primitives/runtime" } +sp-tracing = { version = "2.0.0-rc3", path = "../../primitives/tracing" } +sc-tracing = { version = "2.0.0-rc3", 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 dc6bab759ef00..4962c558eaa2d 100644 --- a/client/executor/runtime-test/src/lib.rs +++ b/client/executor/runtime-test/src/lib.rs @@ -10,7 +10,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}}; @@ -246,6 +246,14 @@ 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(span_id: u64) { + wasm_tracing::exit_span(span_id) + } + 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..56baa2cc3f0d5 100644 --- a/client/executor/src/integration_tests/mod.rs +++ b/client/executor/src/integration_tests/mod.rs @@ -658,3 +658,102 @@ fn parallel_execution(wasm_method: WasmExecutionMethod) { t.join().unwrap(); } } + +#[test_case(WasmExecutionMethod::Interpreted)] +fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { + + use std::sync::{Arc, Mutex}; + + use sc_tracing::SpanDatum; + + impl sc_tracing::TraceHandler for TestTraceHandler { + 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()); + + // Create subscriber with wasm_tracing disabled + let test_subscriber = sc_tracing::ProfilingSubscriber::new_with_handler( + Box::new(handler), "integration_test_span_target", false); + + let _guard = tracing::subscriber::set_default(test_subscriber); + + let mut ext = TestExternalities::default(); + let mut ext = ext.ext(); + + // 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!( + 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); + + 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", + &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 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/service/src/builder.rs b/client/service/src/builder.rs index 813fe50cce513..1430748b2163f 100644 --- a/client/service/src/builder.rs +++ b/client/service/src/builder.rs @@ -1374,7 +1374,7 @@ 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 ); match tracing::subscriber::set_global_default(subscriber) { Ok(_) => (), diff --git a/client/service/src/config.rs b/client/service/src/config.rs index 2d4dc9dc2e90a..73dc86e432e9c 100644 --- a/client/service/src/config.rs +++ b/client/service/src/config.rs @@ -98,6 +98,8 @@ pub struct Configuration { pub tracing_targets: Option, /// Tracing receiver pub tracing_receiver: sc_tracing::TracingReceiver, + /// Enable wasm tracing + 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 613b0d71ce933..401019e8a61cc 100644 --- a/client/service/test/src/lib.rs +++ b/client/service/test/src/lib.rs @@ -208,6 +208,7 @@ fn node_config); +pub struct Visitor(FxHashMap); + +impl Visitor { + /// Consume the Visitor, returning the inner FxHashMap + pub fn into_inner(self) -> FxHashMap { + self.0 + } +} 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) { - self.0.push((field.name().to_string(), format!("{:?}",value))); + self.0.insert(field.name().to_string(), format!("{:?}", value)); } } @@ -105,7 +128,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) } } @@ -135,23 +158,52 @@ impl Value for Visitor { pub struct ProfilingSubscriber { next_id: AtomicU64, targets: Vec<(String, Level)>, - receiver: TracingReceiver, - span_data: Mutex>, + trace_handler: Box, + span_data: Mutex>, } 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 { + /// 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, 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. + /// 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), targets, - receiver, - span_data: Mutex::new(HashMap::new()), + trace_handler, + 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 { + return true; + } + } + false + } } // Default to TRACE if no level given or unable to parse Level @@ -173,36 +225,45 @@ 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; - } else { - log::debug!("Disabled target: {}, level: {}", 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 } - false } 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); + // 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(), - 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(), - overall_time: Duration::from_nanos(0), + overall_time: ZERO_DURATION, values, }; self.span_data.lock().insert(id, span_datum); 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(s) = span_data.get_mut(&span.into_u64()) { + values.record(&mut s.values); + } + } fn record_follows_from(&self, _span: &Id, _follows: &Id) {} @@ -213,65 +274,89 @@ 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; } } 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); + 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 { + 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; + } + if let Some(t) = span_datum.values.0.remove(WASM_TARGET_KEY) { + span_datum.target = t; + } + } + 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 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, } } -fn print_log(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: {}, {}", - span_datum.level, - span_datum.target, - span_datum.name, - span_datum.line, - span_datum.overall_time.as_nanos(), - span_datum.values - ); +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: {}", + span_datum.target, + span_datum.name, + span_datum.overall_time.as_nanos(), + ); + } else { + log::log!( + log_level(span_datum.level), + "{}: {}, time: {}, {}", + span_datum.target, + span_datum.name, + span_datum.overall_time.as_nanos(), + span_datum.values, + ); + } } } -fn send_telemetry(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 - ); +/// 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 + ); + } } - diff --git a/frame/support/src/dispatch.rs b/frame/support/src/dispatch.rs index 70a552ce3a5d5..f461153d42a25 100644 --- a/frame/support/src/dispatch.rs +++ b/frame/support/src/dispatch.rs @@ -1023,7 +1023,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!("on_initialize"); { $( $impl )* } } } @@ -1039,7 +1039,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!("on_initialize"); { $( $impl )* } } } @@ -1065,7 +1065,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!("on_runtime_upgrade"); { $( $impl )* } } } @@ -1092,7 +1092,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!("on_finalize"); { $( $impl )* } } } @@ -1108,7 +1108,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!("on_finalize"); { $( $impl )* } } } @@ -1177,7 +1177,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!(stringify!($name)); { $( $impl )* } Ok(()) } @@ -1196,7 +1196,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!(stringify!($name)); $( $impl )* } }; diff --git a/frame/support/src/lib.rs b/frame/support/src/lib.rs index 196bddbdf5bce..95d6eb1e756ac 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..e40dba6ce75a7 --- /dev/null +++ b/frame/support/src/wasm_tracing.rs @@ -0,0 +1,92 @@ +// 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` + +// static mut has potential for data race conditions. +// 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() { + crate::sp_io::wasm_tracing::exit_span(id); + } + } +} + +/// 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 +/// +/// ``` +/// frame_support::enter_span!("fn_name"); +/// ``` +#[macro_export] +macro_rules! enter_span { + ( $name:expr ) => { + #[cfg(not(feature = "std"))] + 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 { + $crate::wasm_tracing::disable_wasm_tracing(); + $crate::wasm_tracing::TracingSpanGuard::new(None) + } else { + $crate::wasm_tracing::TracingSpanGuard::new(Some(id)) + } + } else { + $crate::wasm_tracing::TracingSpanGuard::new(None) + }; + #[cfg(feature = "std")] + $crate::sp_tracing::enter_span!($name); + } +} + diff --git a/primitives/io/Cargo.toml b/primitives/io/Cargo.toml index 353532b1b4caa..df66740d657ee 100644 --- a/primitives/io/Cargo.toml +++ b/primitives/io/Cargo.toml @@ -24,6 +24,7 @@ sp-wasm-interface = { version = "2.0.0-rc3", path = "../../primitives/wasm-inter sp-runtime-interface = { version = "2.0.0-rc3", default-features = false, path = "../runtime-interface" } sp-trie = { version = "2.0.0-rc3", optional = true, path = "../../primitives/trie" } sp-externalities = { version = "0.8.0-rc3", optional = true, path = "../externalities" } +sp-tracing = { version = "2.0.0-rc3", default-features = false, path = "../tracing" } log = { version = "0.4.8", optional = true } futures = { version = "0.3.1", features = ["thread-pool"], optional = true } parking_lot = { version = "0.10.0", optional = true } diff --git a/primitives/io/src/lib.rs b/primitives/io/src/lib.rs index 8d81a84c4c88a..1d5e01bdffb62 100644 --- a/primitives/io/src/lib.rs +++ b/primitives/io/src/lib.rs @@ -216,7 +216,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], @@ -965,6 +965,55 @@ 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, 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 self.register_extension(TracingProxyExt(sp_tracing::proxy::TracingProxy::new())).is_ok() { + if let Some(proxy) = self.extension::() { + return proxy.enter_span(target, name); + } + } else { + log::warn!( + target: "tracing", + "Unable to register extension: TracingProxyExt" + ); + } + } + } + } + log::debug!( + target: "tracing", + "Notify to runtime that tracing is disabled." + ); + 0 + } + + /// Exit a `tracing` span, using `sp_tracing::proxy` + fn exit_span(&mut self, id: u64) { + if let Some(proxy) = self.extension::() { + proxy.exit_span(id) + } else { + log::warn!( + target: "tracing", + "Unable to load extension: TracingProxyExt" + ); + } + } +} + /// Wasm-only interface that provides functions for interacting with the sandbox. #[runtime_interface(wasm_only)] pub trait Sandbox { @@ -1111,6 +1160,7 @@ pub type SubstrateHostFunctions = ( storage::HostFunctions, default_child_storage::HostFunctions, misc::HostFunctions, + wasm_tracing::HostFunctions, offchain::HostFunctions, crypto::HostFunctions, hashing::HostFunctions, diff --git a/primitives/tracing/Cargo.toml b/primitives/tracing/Cargo.toml index f0560adb06f3a..e47d9859c902d 100644 --- a/primitives/tracing/Cargo.toml +++ b/primitives/tracing/Cargo.toml @@ -13,7 +13,9 @@ targets = ["x86_64-unknown-linux-gnu"] [dependencies] tracing = { version = "0.1.13", optional = true } +rental = { version = "0.5.5", optional = true } +log = { version = "0.4.8", optional = true } [features] default = [ "std" ] -std = [ "tracing" ] +std = [ "tracing", "rental", "log" ] diff --git a/primitives/tracing/src/lib.rs b/primitives/tracing/src/lib.rs index fa43f812d22cd..e82d8861cd3f5 100644 --- a/primitives/tracing/src/lib.rs +++ b/primitives/tracing/src/lib.rs @@ -19,13 +19,35 @@ //! //! 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")] +#[macro_use] +extern crate rental; + #[cfg(feature = "std")] #[doc(hidden)] 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")] +static WASM_TRACING_ENABLED: AtomicBool = AtomicBool::new(false); + /// Runs given code within a tracing span, measuring it's execution time. /// /// If tracing is not enabled, the code is still executed. @@ -83,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 new file mode 100644 index 0000000000000..270f57aaa69f0 --- /dev/null +++ b/primitives/tracing/src/proxy.rs @@ -0,0 +1,165 @@ +// 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 . + +//! Proxy to allow entering tracing spans from wasm. +//! +//! Use `enter_span` and `exit_span` to surround the code that you wish to trace +use rental; +use tracing::info_span; + +/// 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; + +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: Vec<(u64, rent_span::SpanAndGuard)>, +} + +impl Drop for TracingProxy { + fn drop(&mut self) { + 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); }); + } + } + } +} + +impl TracingProxy { + pub fn new() -> TracingProxy { + TracingProxy { + next_id: 0, + spans: Vec::new(), + } + } +} + +impl TracingProxy { + /// 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( + Box::new(span), + |span| span.enter(), + ); + self.spans.push((self.next_id, sg)); + 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 misconfiguration / misuse + log::warn!( + target: "tracing", + "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); }); + } + self.next_id + } + + /// 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!(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; qed"); + while 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!(target: "tracing", "Span id not found in TracingProxy {}", id); + return; + } + } + } +} + + +#[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.enter_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, 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); + // exit all spans + proxy.exit_span(1); + assert_eq!(proxy.spans.len(), 0); + } +} diff --git a/utils/browser/src/lib.rs b/utils/browser/src/lib.rs index 04af2ceb58136..2d6c1afbfed52 100644 --- a/utils/browser/src/lib.rs +++ b/utils/browser/src/lib.rs @@ -93,6 +93,7 @@ where state_cache_size: Default::default(), tracing_receiver: Default::default(), tracing_targets: Default::default(), + tracing_enable_wasm: Default::default(), transaction_pool: Default::default(), wasm_method: Default::default(), max_runtime_instances: 8,