Runtime interface to add support for tracing from wasm

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

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

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;

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<Mutex<Vec<SpanDatum>>>);
+
+	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");
+
+	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");
+}

client/tracing/Cargo.toml

@@ -15,10 +15,12 @@ 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"
+sp-tracing = { version = "2.0.0-rc2", path = "../../primitives/tracing" }
 
 sc-telemetry = { version = "2.0.0-rc3", path = "../telemetry" }