Facilitate tracing from WASM

client/tracing/Cargo.toml

@@ -15,12 +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"
 
 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"

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};
@@ -38,11 +38,13 @@ use tracing_core::{
 	Level,
 	metadata::Metadata,
 	span::{Attributes, Id, Record},
-	subscriber::Subscriber
+	subscriber::Subscriber,
 };
 
 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,23 +73,27 @@ struct SpanDatum {
 }
 
 #[derive(Clone, Debug)]
-struct Visitor(Vec<(String, String)>);
+struct Visitor(FxHashMap<String, String>);
 
 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 +111,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::<Vec<String>>().join(", ");
+		let values = self.0.iter().map(|(k, v)| format!("{}={}", k, v)).collect::<Vec<String>>().join(", ");
 		write!(f, "{}", values)
 	}
 }
@@ -136,7 +142,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,9 +155,20 @@ impl ProfilingSubscriber {
 			next_id: AtomicU64::new(1),
 			targets,
 			receiver,
-			span_data: Mutex::new(HashMap::new()),
+			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
@@ -173,25 +190,24 @@ 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());
-			}
-		}
-		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(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(),
@@ -202,7 +218,12 @@ 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);
+		}
+	}
 
 	fn record_follows_from(&self, _span: &Id, _follows: &Id) {}
 
@@ -213,23 +234,32 @@ 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 {
+				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
 	}

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;
@@ -65,6 +67,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,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 <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
+///
+/// ```
+/// frame_support::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)
+		);
+	}
+}