Tracing for wasm with bridging to native (#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 <[email protected]> * 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 <[email protected]> Co-authored-by: Matt Rutherford <[email protected]> Co-authored-by: Niklas Adolfsson <[email protected]> Co-authored-by: David <[email protected]>
paritytech · Sep 18, 2020 · 5a2c400 · 5a2c400
1 parent fbf617e
commit 5a2c400
Show file tree

Hide file tree

Showing 34 changed files with 1,211 additions and 440 deletions.
diff --git a/.gitlab-ci.yml b/.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:

diff --git a/Cargo.lock b/Cargo.lock
diff --git a/bin/node/cli/Cargo.toml b/bin/node/cli/Cargo.toml
@@ -41,7 +41,7 @@ hex-literal = "0.3.1"
 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

diff --git a/bin/node/runtime/Cargo.toml b/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",

diff --git a/client/executor/Cargo.toml b/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]

diff --git a/client/executor/runtime-test/Cargo.toml b/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",
 ]
diff --git a/client/executor/runtime-test/build.rs b/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();
 }
diff --git a/client/executor/runtime-test/src/lib.rs b/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 {

diff --git a/client/executor/src/integration_tests/mod.rs b/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);
 }
diff --git a/client/service/Cargo.toml b/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]

diff --git a/client/tracing/Cargo.toml b/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" }
diff --git a/client/tracing/src/lib.rs b/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

diff --git a/client/transaction-pool/src/api.rs b/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>