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 8824a60deea54d9b437407a21c8ceaf6a1902ee5. * 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>
2026-06-13 07:01:05 +00:00 · 2020-09-18 08:10:59 +02:00
parent 649bee1a1e
commit a9c73113a8
34 changed files with 1207 additions and 436 deletions
@@ -32,6 +32,9 @@ use sp_std::vec::Vec;
 #[cfg(feature = "std")]
 use sp_std::ops::Deref;

+#[cfg(feature = "std")]
+use tracing;
+
 #[cfg(feature = "std")]
 use sp_core::{
 	crypto::Pair,
@@ -52,6 +55,7 @@ use sp_core::{
 use sp_trie::{TrieConfiguration, trie_types::Layout};

 use sp_runtime_interface::{runtime_interface, Pointer};
+use sp_runtime_interface::pass_by::PassBy;

 use codec::{Encode, Decode};

@@ -1004,55 +1008,156 @@ pub trait Logging {
 	}
 }

-#[cfg(feature = "std")]
-sp_externalities::decl_extension! {
-	/// Extension to allow running traces in wasm via Proxy
-	pub struct TracingProxyExt(sp_tracing::proxy::TracingProxy);
+#[derive(Encode, Decode)]
+/// Crossing is a helper wrapping any Encode-Decodeable type
+/// for transferring over the wasm barrier.
+pub struct Crossing<T: Encode + Decode>(T);
+
+impl<T: Encode + Decode> PassBy for Crossing<T> {
+	type PassBy = sp_runtime_interface::pass_by::Codec<Self>;
 }

-/// Interface that provides functions for profiling the runtime.
-#[runtime_interface]
+impl<T: Encode + Decode> Crossing<T> {
+
+	/// Convert into the inner type
+	pub fn into_inner(self) -> T {
+		self.0
+	}
+}
+
+// useful for testing
+impl<T> core::default::Default for Crossing<T>
+	where T: core::default::Default + Encode + Decode
+{
+	fn default() -> Self {
+		Self(Default::default())
+	}
+
+}
+
+/// Interface to provide tracing facilities for wasm. Modelled after tokios `tracing`-crate
+/// interfaces. See `sp-tracing` for more information.
+#[runtime_interface(wasm_only, no_tracing)]
 pub trait WasmTracing {
-	/// To create and enter a `tracing` span, using `sp_tracing::proxy`
-	/// Returns 0 value to indicate that no further traces should be attempted
-	fn enter_span(&mut self, target: &str, name: &str) -> u64 {
-		if sp_tracing::wasm_tracing_enabled() {
-			match self.extension::<TracingProxyExt>() {
-				Some(proxy) => return proxy.enter_span(target, name),
-				None => {
-					if self.register_extension(TracingProxyExt(sp_tracing::proxy::TracingProxy::new())).is_ok() {
-						if let Some(proxy) = self.extension::<TracingProxyExt>() {
-							return proxy.enter_span(target, name);
-						}
-					} else {
-						log::warn!(
-							target: "tracing",
-							"Unable to register extension: TracingProxyExt"
-						);
-					}
-				}
+	/// Whether the span described in `WasmMetadata` should be traced wasm-side
+	/// On the host converts into a static Metadata and checks against the global `tracing` dispatcher.
+	///
+	/// When returning false the calling code should skip any tracing-related execution. In general
+	/// within the same block execution this is not expected to change and it doesn't have to be
+	/// checked more than once per metadata. This exists for optimisation purposes but is still not
+	/// cheap as it will jump the wasm-native-barrier every time it is called. So an implementation might
+	/// chose to cache the result for the execution of the entire block.
+	fn enabled(&mut self, metadata: Crossing<sp_tracing::WasmMetadata>) -> bool {
+		let metadata: &tracing_core::metadata::Metadata<'static> = (&metadata.into_inner()).into();
+		tracing::dispatcher::get_default(|d| {
+			d.enabled(metadata)
+		})
+	}
+
+	/// Open a new span with the given attributes. Return the u64 Id of the span.
+	///
+	/// On the native side this goes through the default `tracing` dispatcher to register the span
+	/// and then calls `clone_span` with the ID to signal that we are keeping it around on the wasm-
+	/// side even after the local span is dropped. The resulting ID is then handed over to the wasm-
+	/// side.
+	fn enter_span(&mut self, span: Crossing<sp_tracing::WasmEntryAttributes>) -> u64 {
+		let span: tracing::Span = span.into_inner().into();
+		match span.id() {
+			Some(id) => tracing::dispatcher::get_default(|d| {
+				// inform dispatch that we'll keep the ID around
+				// then enter it immediately
+				let final_id = d.clone_span(&id);
+				d.enter(&final_id);
+				final_id.into_u64()
+			}),
+			_ => {
+				0
 			}
 		}
-		log::debug!(
-			target: "tracing",
-			"Notify to runtime that tracing is disabled."
-		);
-		0
 	}

-	/// Exit a `tracing` span, using `sp_tracing::proxy`
-	fn exit_span(&mut self, id: u64) {
-		if let Some(proxy) = self.extension::<TracingProxyExt>() {
-			proxy.exit_span(id)
-		} else {
-			log::warn!(
-				target: "tracing",
-				"Unable to load extension: TracingProxyExt"
-			);
+	/// Emit the given event to the global tracer on the native side
+	fn event(&mut self, event: Crossing<sp_tracing::WasmEntryAttributes>) {
+		event.into_inner().emit();
+	}
+
+	/// Signal that a given span-id has been exited. On native, this directly
+	/// proxies the span to the global dispatcher.
+	fn exit(&mut self, span: u64) {
+		tracing::dispatcher::get_default(|d| {
+			let id = tracing_core::span::Id::from_u64(span);
+			d.exit(&id);
+		});
+	}
+}
+
+#[cfg(all(not(feature="std"), feature="with-tracing"))]
+mod tracing_setup {
+	use core::sync::atomic::{AtomicBool, Ordering};
+	use tracing_core::{
+		dispatcher::{Dispatch, set_global_default},
+		span::{Id, Record, Attributes},
+		Metadata, Event,
+	};
+	use super::{wasm_tracing, Crossing};
+
+	const TRACING_SET : AtomicBool = AtomicBool::new(false);
+
+
+	/// The PassingTracingSubscriber implements `tracing_core::Subscriber`
+	/// and pushes the information across the runtime interface to the host
+	struct PassingTracingSubsciber;
+
+	impl tracing_core::Subscriber for PassingTracingSubsciber {
+		fn enabled(&self, metadata: &Metadata<'_>) -> bool {
+			wasm_tracing::enabled(Crossing(metadata.into()))
+		}
+		fn new_span(&self, attrs: &Attributes<'_>) -> Id {
+			Id::from_u64(wasm_tracing::enter_span(Crossing(attrs.into())))
+		}
+		fn enter(&self, span: &Id) {
+			// Do nothing, we already entered the span previously
+		}
+		/// Not implemented! We do not support recording values later
+		/// Will panic when used.
+		fn record(&self, span: &Id, values: &Record<'_>) {
+			unimplemented!{} // this usage is not supported
+		}
+		/// Not implemented! We do not support recording values later
+		/// Will panic when used.
+		fn record_follows_from(&self, span: &Id, follows: &Id) {
+			unimplemented!{ } // this usage is not supported
+		}
+		fn event(&self, event: &Event<'_>) {
+			wasm_tracing::event(Crossing(event.into()))
+		}
+		fn exit(&self, span: &Id) {
+			wasm_tracing::exit(span.into_u64())
+		}
+	}
+
+
+	/// Initialize tracing of sp_tracing on wasm with `with-tracing` enabled.
+	/// Can be called multiple times from within the same process and will only
+	/// set the global bridging subscriber once.
+	pub fn init_tracing() {
+		if TRACING_SET.load(Ordering::Relaxed) == false {
+			set_global_default(Dispatch::new(PassingTracingSubsciber {}))
+				.expect("We only ever call this once");
+			TRACING_SET.store(true, Ordering::Relaxed);
 		}
 	}
 }

+#[cfg(not(all(not(feature="std"), feature="with-tracing")))]
+mod tracing_setup {
+	/// Initialize tracing of sp_tracing not necessary – noop. To enable build
+	/// without std and with the `with-tracing`-feature.
+	pub fn init_tracing() { }
+}
+
+pub use tracing_setup::init_tracing;
+
 /// Wasm-only interface that provides functions for interacting with the sandbox.
 #[runtime_interface(wasm_only)]
 pub trait Sandbox {