Facilitate tracing from WASM

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]

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<HashMap<u64, SpanDatum>>,
+	span_data: Mutex<FxHashMap<u64, SpanDatum>>,
 }
 
 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()),
 		}
 	}
 }
@@ -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(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) {}
 

frame/support/src/dispatch.rs

@@ -1023,6 +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");
 				{ $( $impl )* }
 			}
 		}
@@ -1039,6 +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");
 				{ $( $impl )* }
 			}
 		}
@@ -1065,6 +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");
 				{ $( $impl )* }
 			}
 		}
@@ -1092,6 +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");
 				{ $( $impl )* }
 			}
 		}
@@ -1108,6 +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");
 				{ $( $impl )* }
 			}
 		}
@@ -1177,6 +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"));
 			{ $( $impl )* }
 			Ok(())
 		}
@@ -1196,6 +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"));
 			$( $impl )*
 		}
 	};

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;
@@ -64,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;
 

frame/support/src/wasm_tracing.rs

@@ -0,0 +1,49 @@
+// 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 <http://www.gnu.org/licenses/>.
+
+//! # To allow tracing in WASM execution environment
+//!
+//! 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(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
+///
+/// ```
+/// # use frame_support::wasm_tracing;
+/// 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)
+		);
+	}
+}

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 }

primitives/io/src/lib.rs

@@ -858,6 +858,22 @@ 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`.
+	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);
+	}
+}
+
 /// Wasm-only interface that provides functions for interacting with the sandbox.
 #[runtime_interface(wasm_only)]
 pub trait Sandbox {
@@ -1004,6 +1020,7 @@ pub type SubstrateHostFunctions = (
 	storage::HostFunctions,
 	default_child_storage::HostFunctions,
 	misc::HostFunctions,
+	wasm_tracing::HostFunctions,
 	offchain::HostFunctions,
 	crypto::HostFunctions,
 	hashing::HostFunctions,

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" ]

primitives/tracing/src/lib.rs

@@ -18,13 +18,21 @@
 //!
 //! 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")]
 #[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.