diff --git a/bin/node/runtime/src/lib.rs b/bin/node/runtime/src/lib.rs index 07b0a82e481a9..85c3aef41c88d 100644 --- a/bin/node/runtime/src/lib.rs +++ b/bin/node/runtime/src/lib.rs @@ -98,7 +98,7 @@ pub const VERSION: RuntimeVersion = RuntimeVersion { // implementation changes and behavior does not, then leave spec_version as // is and increment impl_version. spec_version: 255, - impl_version: 0, + impl_version: 1, apis: RUNTIME_API_VERSIONS, transaction_version: 1, }; diff --git a/client/cli/src/commands/mod.rs b/client/cli/src/commands/mod.rs index 04cce66bef80d..ff5395c0fcb8f 100644 --- a/client/cli/src/commands/mod.rs +++ b/client/cli/src/commands/mod.rs @@ -390,6 +390,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 fa3f09116c314..4b9e2b052e1a0 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -378,6 +378,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 @@ -469,6 +478,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 c7f48d2721468..51a16fc3efb1b 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -239,7 +239,7 @@ pub fn init_logger(pattern: &str) { builder.filter(Some("hyper"), log::LevelFilter::Warn); builder.filter(Some("cranelift_wasm"), log::LevelFilter::Warn); // Always log the special target `sc_tracing`, overrides global level - builder.filter(Some("sc_tracing"), log::LevelFilter::Info); + builder.filter(Some("sc_tracing"), log::LevelFilter::Trace); // Enable info for others. builder.filter(None, log::LevelFilter::Info); 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/src/integration_tests/mod.rs b/client/executor/src/integration_tests/mod.rs index 21924270b8c1e..10ba29e36cc9d 100644 --- a/client/executor/src/integration_tests/mod.rs +++ b/client/executor/src/integration_tests/mod.rs @@ -661,23 +661,23 @@ fn parallel_execution(wasm_method: WasmExecutionMethod) { fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) { use std::sync::{Arc, Mutex}; - use sc_tracing::SpanDatum; + struct TestTraceHandler(Arc>>); + 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"); + Box::new(handler), "integration_test_span_target", false + ); let _guard = tracing::subscriber::set_default(test_subscriber); diff --git a/client/service/src/builder.rs b/client/service/src/builder.rs index 16b41e135a518..dd3de98a1b3e4 100644 --- a/client/service/src/builder.rs +++ b/client/service/src/builder.rs @@ -1043,7 +1043,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 f3080005a6cf3..dc3c3311dd650 100644 --- a/client/service/src/config.rs +++ b/client/service/src/config.rs @@ -101,6 +101,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 ac95dd11e8b27..9d7f92bc8d14e 100644 --- a/client/service/test/src/lib.rs +++ b/client/service/test/src/lib.rs @@ -265,6 +265,7 @@ fn node_config ProfilingSubscriber { + pub fn new(receiver: TracingReceiver, targets: &str, wasm_tracing: bool) -> ProfilingSubscriber { match receiver { - TracingReceiver::Log => Self::new_with_handler(Box::new(LogTraceHandler), 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, ), } } @@ -182,9 +183,10 @@ 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) + 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), diff --git a/frame/support/src/dispatch.rs b/frame/support/src/dispatch.rs index dc305357e7218..6585617f0b737 100644 --- a/frame/support/src/dispatch.rs +++ b/frame/support/src/dispatch.rs @@ -1238,7 +1238,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 )* } } } @@ -1254,7 +1254,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 )* } } } @@ -1280,7 +1280,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 )* } } } @@ -1333,7 +1333,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 )* } } } @@ -1349,7 +1349,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 )* } } } @@ -1418,7 +1418,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(()) } @@ -1437,7 +1437,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 06a8ce856dd64..535c4f2b7d634 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/utils/browser/src/lib.rs b/utils/browser/src/lib.rs index 9313d41bf5726..1e39f1d989ecf 100644 --- a/utils/browser/src/lib.rs +++ b/utils/browser/src/lib.rs @@ -94,6 +94,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,