Tracing for wasm with bridging to native (paritytech#6916)

* implement events handling, implement parent_id for spans & events

* add events to sp_io::storage

* update test

* add tests

* adjust limit

* let tracing crate handle parent_ids

* re-enable current-id tracking

* add test for threads with CurrentSpan

* fix log level

* remove redundant check for non wasm traces

* remove duplicate definition in test

* Adding conditional events API

* prefer explicit parent_id over current,

enhance test

* limit changes to client::tracing event implementation

* remove From impl due to fallback required on parent_id

* make tracing codecable

* replace with global tracing

* new tracing interface

* impl TracingSubscriber in client

* implement access to global TracingSubscriber from primitives

* span for wasm

* increment towards Wasm Tracing Subscriber implementation

* increment, remove sp-tracing from runtime-interface

* increment, it compiles

* attained original functionality with new mechanism

* implement remaining TracingSubscriber functions

* remove spans from decl_module

* add handling for encoded values

* Revert "replace with global tracing"

This reverts commit 8824a60.

* Wasm Side Tracing

* tracing on wasm

* enable tracing wasm on node-runtime

* export all the macros in std

* tracing subscriber on wasm-side only

* pass spans and events over and record them

* reactivate previous code and  cleanup

* further cleaning up

* extend the span macros, activate through executive

* tracking the actual extrinsic, too

* style

* fixing tests

* spaces -> tabs

* attempting to reactivate params

* activate our tests in CI

* some passing

* tests passing

* with core lazy

* global tracer for wasm side with pass over

* fixing metadata referencing

* remove const_fn feature requirement

* reenable dispatch traces

* reset client tracing

* further cleaning up

* fixing runtime-test

* move tracing-build setup into runtime-test

* Merge DebugWriter from tracing and frame-support, move to sp-std

* remove dangling fixme

* Docs for tracing primitives

* cleaning up a bit more

* Wasm interface docs

* optimise docs.rs setup

* adding tracing flags to uncomment

* remove brace

* fixing imports

* fixing broken syntax

* add required modules

* nicer formatting

* better target management

* adding low level storage tracing events into frame

* add custom Debug impl for WasmMetadata

* cloning profiler

* adding info about cloning profiler

* using in-scope for within calls

* proper time tracing, cleaning up println

* allow to disable tracing on runtime_interface-macro

* disable tracing for wasm-tracing-interface

* simplify wasm-tracing-api

* update client to new interface

* fixing docs and tests for sp-tracing

* update integration tests

* re-activating enter_span

* dropping FIXME, it's documented

* fix formatting

* fix formatting

* fix imports

* more debug info

* inform wasm about it being disabled by returning 1

* only one tracer, but enabled multi-all support

* make trait pub again for tests

* Apply suggestions from code review

Co-authored-by: Niklas Adolfsson <niklasadolfsson1@gmail.com>

* fixing wasm doc tests for proper usage

* remove unnecessary import

* fixing formatting

* minor style fixes

* downgrading wabt

* update error message for UI

* Fix interface test

* next attempt to fix macros

* geee

* revert tracing on hashed for future PR

* remove local macros, use originals

* we are able to convert to static items

* implement more WasmValue types

* adding support to convert str, debug and encoded values

* more minor fixes

* revert unsafe 'static making

* fix indentation

* remove commented lines

* bump all them tracing versions

* cleaning up docs and info

* document new flag

* the new layered system handles span cloning better

* Apply suggestions from code review

Co-authored-by: David <dvdplm@gmail.com>

Co-authored-by: Matt Rutherford <mattrutherford@users.noreply.github.com>
Co-authored-by: Niklas Adolfsson <niklasadolfsson1@gmail.com>
Co-authored-by: David <dvdplm@gmail.com>

.gitlab-ci.yml

@@ -336,6 +336,9 @@ check-web-wasm:
     - time cargo build --target=wasm32-unknown-unknown -p sc-telemetry
     # Note: the command below is a bit weird because several Cargo issues prevent us from compiling the node in a more straight-forward way.
     - time cargo +nightly build --manifest-path=bin/node/cli/Cargo.toml --no-default-features --features browser --target=wasm32-unknown-unknown -Z features=itarget
+    # with-tracing must be explicitly activated, we run a test to ensure this works as expected in both cases
+    - time cargo +nightly test --manifest-path primitives/tracing/Cargo.toml --no-default-features
+    - time cargo +nightly test --manifest-path primitives/tracing/Cargo.toml --no-default-features --features=with-tracing
     - sccache -s
 
 test-full-crypto-feature:

bin/node/cli/Cargo.toml

@@ -43,7 +43,7 @@ jsonrpc-pubsub = "14.2.0"
 log = "0.4.8"
 rand = "0.7.2"
 structopt = { version = "0.3.8", optional = true }
-tracing = "0.1.18"
+tracing = "0.1.19"
 parking_lot = "0.10.0"
 
 # primitives

bin/node/runtime/Cargo.toml

@@ -88,6 +88,7 @@ sp-io = { version = "2.0.0-rc6", path = "../../../primitives/io" }
 
 [features]
 default = ["std"]
+with-tracing = [ "frame-executive/with-tracing" ]
 std = [
 	"sp-authority-discovery/std",
 	"pallet-authority-discovery/std",

client/executor/Cargo.toml

@@ -46,7 +46,7 @@ test-case = "0.3.3"
 sp-runtime = { version = "2.0.0-rc6", path = "../../primitives/runtime" }
 sp-tracing = { version = "2.0.0-rc6", path = "../../primitives/tracing" }
 sc-tracing = { version = "2.0.0-rc6", path = "../tracing" }
-tracing = "0.1.18"
+tracing = "0.1.19"
 tracing-subscriber = "0.2.10"
 
 [features]

client/executor/runtime-test/Cargo.toml

@@ -29,5 +29,7 @@ std = [
 	"sp-io/std",
 	"sp-sandbox/std",
 	"sp-std/std",
+	"sp-core/std",
+	"sp-runtime/std",
 	"sp-allocator/std",
 ]

client/executor/runtime-test/build.rs

@@ -17,10 +17,21 @@
 use wasm_builder_runner::WasmBuilder;
 
 fn main() {
+	// regular build
 	WasmBuilder::new()
 		.with_current_project()
 		.with_wasm_builder_from_crates_or_path("2.0.0", "../../../utils/wasm-builder")
 		.export_heap_base()
 		.import_memory()
-		.build()
+		.build();
+
+	// and building with tracing activated
+	WasmBuilder::new()
+		.with_current_project()
+		.with_wasm_builder_from_crates_or_path("2.0.0", "../../../utils/wasm-builder")
+		.export_heap_base()
+		.import_memory()
+		.set_file_name("wasm_binary_with_tracing.rs")
+		.append_to_rust_flags("--cfg feature=\\\"with-tracing\\\"")
+		.build();
 }

client/executor/runtime-test/src/lib.rs

@@ -254,11 +254,11 @@ sp_core::wasm_export_functions! {
 	}
 
 	fn test_enter_span() -> u64 {
-		wasm_tracing::enter_span("integration_test_span_target", "integration_test_span_name")
+		wasm_tracing::enter_span(Default::default())
 	}
 
 	fn test_exit_span(span_id: u64) {
-		wasm_tracing::exit_span(span_id)
+		wasm_tracing::exit(span_id)
 	}
 
 	fn returns_mutable_static() -> u64 {

client/executor/src/integration_tests/mod.rs

@@ -681,7 +681,7 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) {
 	// Create subscriber with wasm_tracing disabled
 	let test_subscriber = tracing_subscriber::fmt().finish().with(
 		sc_tracing::ProfilingLayer::new_with_handler(
-			Box::new(handler), "integration_test_span_target"
+			Box::new(handler), "default"
 		)
 	);
 
@@ -690,49 +690,9 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) {
 	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",
-		&[],
+		Default::default(),
 		wasm_method,
 		&mut ext,
 	).unwrap();
@@ -756,8 +716,7 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) {
 
 	let span_datum = traces.lock().unwrap().pop().unwrap();
 	let values = span_datum.values;
-	assert_eq!(span_datum.target, "integration_test_span_target");
-	assert_eq!(span_datum.name, "integration_test_span_name");
+	assert_eq!(span_datum.target, "default");
+	assert_eq!(span_datum.name, "");
 	assert_eq!(values.bool_values.get("wasm").unwrap(), &true);
-	assert_eq!(values.bool_values.get("is_valid_trace").unwrap(), &true);
 }

client/service/Cargo.toml

@@ -73,7 +73,8 @@ sc-telemetry = { version = "2.0.0-rc6", path = "../telemetry" }
 sc-offchain = { version = "2.0.0-rc6", path = "../offchain" }
 prometheus-endpoint = { package = "substrate-prometheus-endpoint", path = "../../utils/prometheus", version = "0.8.0-rc6"}
 sc-tracing = { version = "2.0.0-rc6", path = "../tracing" }
-tracing = "0.1.18"
+sp-tracing = { version = "2.0.0-rc6", path = "../../primitives/tracing" }
+tracing = "0.1.19"
 parity-util-mem = { version = "0.7.0", default-features = false, features = ["primitive-types"] }
 
 [target.'cfg(not(target_os = "unknown"))'.dependencies]

client/tracing/Cargo.toml

@@ -19,7 +19,8 @@ rustc-hash = "1.1.0"
 serde = "1.0.101"
 serde_json = "1.0.41"
 slog = { version = "2.5.2", features = ["nested-values"] }
-tracing = "0.1.18"
+tracing = "0.1.19"
+tracing-core = "0.1.13"
 tracing-subscriber = "0.2.10"
 sp-tracing = { version = "2.0.0-rc6", path = "../../primitives/tracing" }
 sc-telemetry = { version = "2.0.0-rc6", path = "../telemetry" }

client/tracing/src/lib.rs

@@ -40,8 +40,7 @@ use tracing::{
 use tracing_subscriber::{CurrentSpan, layer::{Layer, Context}};
 
 use sc_telemetry::{telemetry, SUBSTRATE_INFO};
-use sp_tracing::proxy::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER};
-
+use sp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER};
 const ZERO_DURATION: Duration = Duration::from_nanos(0);
 
 /// Responsible for assigning ids to new spans, which are not re-used.
@@ -275,12 +274,6 @@ impl<S: Subscriber> Layer<S> for ProfilingLayer {
 	fn new_span(&self, attrs: &Attributes<'_>, id: &Id, _ctx: Context<S>) {
 		let mut values = Values::default();
 		attrs.record(&mut values);
-		// If this is a wasm trace, check if target/level is enabled
-		if let Some(wasm_target) = values.string_values.get(WASM_TARGET_KEY) {
-			if !self.check_target(wasm_target, attrs.metadata().level()) {
-				return
-			}
-		}
 		let span_datum = SpanDatum {
 			id: id.clone(),
 			parent_id: attrs.parent().cloned().or_else(|| self.current_span.id()),
@@ -327,18 +320,13 @@ impl<S: Subscriber> Layer<S> for ProfilingLayer {
 	fn on_exit(&self, span: &Id, _ctx: Context<S>) {
 		self.current_span.exit();
 		let end_time = Instant::now();
-		let mut span_data = self.span_data.lock();
-		if let Some(mut s) = span_data.get_mut(&span) {
-			s.overall_time = end_time - s.start_time + s.overall_time;
-		}
-	}
-
-	fn on_close(&self, span: Id, _ctx: Context<S>) {
 		let span_datum = {
 			let mut span_data = self.span_data.lock();
 			span_data.remove(&span)
 		};
+
 		if let Some(mut span_datum) = span_datum {
+			span_datum.overall_time += end_time - span_datum.start_time;
 			if span_datum.name == WASM_TRACE_IDENTIFIER {
 				span_datum.values.bool_values.insert("wasm".to_owned(), true);
 				if let Some(n) = span_datum.values.string_values.remove(WASM_NAME_KEY) {
@@ -355,6 +343,10 @@ impl<S: Subscriber> Layer<S> for ProfilingLayer {
 			}
 		};
 	}
+
+	fn on_close(&self, span: Id, ctx: Context<S>) {
+		self.on_exit(&span, ctx)
+	}
 }
 
 /// TraceHandler for sending span data to the logger

client/transaction-pool/src/api.rs

@@ -168,23 +168,28 @@ where
 	Client::Api: TaggedTransactionQueue<Block>,
 	sp_api::ApiErrorFor<Client, Block>: Send + std::fmt::Display,
 {
-	sp_tracing::enter_span!("validate_transaction");
-	let runtime_api = client.runtime_api();
-	let has_v2 = sp_tracing::tracing_span! { "check_version";
-		runtime_api
-			.has_api_with::<dyn TaggedTransactionQueue<Block, Error=()>, _>(&at, |v| v >= 2)
-			.unwrap_or_default()
-	};
-
-	sp_tracing::enter_span!("runtime::validate_transaction");
-	let res = if has_v2 {
-		runtime_api.validate_transaction(&at, source, uxt)
-	} else {
-		#[allow(deprecated)] // old validate_transaction
-		runtime_api.validate_transaction_before_version_2(&at, uxt)
-	};
-
-	res.map_err(|e| Error::RuntimeApi(e.to_string()))
+	sp_tracing::within_span!(sp_tracing::Level::TRACE, "validate_transaction";
+	{
+		let runtime_api = client.runtime_api();
+		let has_v2 = sp_tracing::within_span! { sp_tracing::Level::TRACE, "check_version";
+			runtime_api
+				.has_api_with::<dyn TaggedTransactionQueue<Block, Error=()>, _>(&at, |v| v >= 2)
+				.unwrap_or_default()
+		};
+
+		let res = sp_tracing::within_span!(
+			sp_tracing::Level::TRACE, "runtime::validate_transaction";
+		{
+			if has_v2 {
+				runtime_api.validate_transaction(&at, source, uxt)
+			} else {
+				#[allow(deprecated)] // old validate_transaction
+				runtime_api.validate_transaction_before_version_2(&at, uxt)
+			}
+		});
+
+		res.map_err(|e| Error::RuntimeApi(e.to_string()))
+	})
 }
 
 impl<Client, Block> FullChainApi<Client, Block>