Runtime interface to add support for tracing from wasm (#6381)

* Add span recording to tracing implementation

* Add tracing proxy

* switch to rustc_hash::FxHashMap

* Replace lazy_static and hashmap with thread_local and vec.

* fix marking valid span as invalid while removing invalid spans

* refactor, add wasm_tracing module in `support`

* update registered spans

* tidy up

* typos

* refactor

* update flag name to signal lost trace - `is_valid_trace`

* update flag name to signal lost trace - `is_valid_trace`

* update docs

* update docs

* Use tracing Field recording to store the actual `name` and `target`
from wasm traces.

* fix debug log in subscriber + small refactor

* add tests

* handle misuse in case trying to exit span not held

* Implement filter for wasm traces, simplify field recording for primitive types

* remove superfluous warning

* update docs

* Update primitives/tracing/src/proxy.rs

Co-authored-by: Kian Paimani <5588131+kianenigma@users.noreply.github.com>

* Apply suggestions from code review

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* update docs, apply suggestions

* move Proxy from thread_local to `Extension`, rename macro

* fix test

* unify native & wasm span macro calls

* implement wasm tracing control facility in primitives and frame

* add cli flag `--wasm-tracing`

* fix

* switch to `Option<u4>` (possible performance degradation), switch
to static mut bool

* performance improvement using u64 vs Option<u64>

* performance improvement moving concat to client

* update docs

* Update client/cli/src/params/import_params.rs

Co-authored-by: Cecile Tonglet <cecile@parity.io>

* performance improvement

* Revert "performance improvement"

This reverts commit cff0aa2.

* small refactor

* formatting

* bump impl_version

* Update client/cli/src/config.rs

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* update docs

* small fixes, remove pub static

* nit

* add integration tests and refactor Subscriber

* tests

* revert formatting

* try fix test that works locally but not in CI

* try fix test that works locally but not in CI

* debug test that works locally but not in CI

* fix test that works locally but not in CI

* remove pub visibility from bool in runtime

* make TracingSpanGuard #[cfg(not(feature = "std"))], update docs, comments

* make TracingProxy drop implementation conditional on !empty state

* add docs for TraceHandler

* remove blank line

* update expect message

* update tests

* rename cli option to tracing_enable_wasm

* rename cli option to tracing_enable_wasm

* fix

* ensure wasm-tracing features are wasm only

* bump impl_version

* bump impl_version

* add `"pallet-scheduler/std"` to `[features]` `std` in node/runtime

* refactor service to remove sp_tracing dependency

* refactor: line width, trait bounds

* improve LogTraceHandler output

* fix test

* improve tracing log output

* Apply suggestions from code review

* Apply suggestions from code review

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* swap wasm indication from trace name to a separate value

* Update client/tracing/src/lib.rs

* add docs

* remove runtime features

remove wasm_tracing option from CLI

remove wasm_tracing flag from ProfilingSubscriber

Co-authored-by: Matt Rutherford <mattrutherford@users.noreply.github.com>
Co-authored-by: Kian Paimani <5588131+kianenigma@users.noreply.github.com>
Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>
Co-authored-by: Cecile Tonglet <cecile@parity.io>

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