Facilitate tracing from WASM

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"

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<String, String>);
 
 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
 	}

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 {

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.
 ///

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,33 +71,24 @@ 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,
 		}
 	}
 }
 
 /// 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<tracing::Span, String> = 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;