Improve tracing (#5698)

* Improve tracing implementation

* Enable tracing in runtime interfaces

* Switch to `TRACE` level

substrate/Cargo.lock

@@ -1453,6 +1453,7 @@ dependencies = [
  "sp-io",
  "sp-runtime",
  "sp-std",
+ "sp-tracing",
  "sp-version",
 ]
 
@@ -1488,7 +1489,7 @@ dependencies = [
  "sp-runtime",
  "sp-state-machine",
  "sp-std",
- "tracing",
+ "sp-tracing",
 ]
 
 [[package]]
@@ -6765,12 +6766,12 @@ dependencies = [
  "sp-core",
  "sp-keyring",
  "sp-runtime",
+ "sp-tracing",
  "sp-transaction-pool",
  "sp-utils",
  "substrate-prometheus-endpoint",
  "substrate-test-runtime-client",
  "substrate-test-runtime-transaction-pool",
- "tracing",
  "wasm-timer",
 ]
 
@@ -7574,6 +7575,7 @@ dependencies = [
  "sp-runtime-interface-test-wasm",
  "sp-state-machine",
  "sp-std",
+ "sp-tracing",
  "sp-wasm-interface",
  "static_assertions",
  "trybuild",
@@ -7601,6 +7603,7 @@ dependencies = [
  "sp-runtime-interface-test-wasm",
  "sp-runtime-interface-test-wasm-deprecated",
  "sp-state-machine",
+ "tracing",
 ]
 
 [[package]]
@@ -7725,6 +7728,13 @@ dependencies = [
  "wasm-timer",
 ]
 
+[[package]]
+name = "sp-tracing"
+version = "2.0.0-dev"
+dependencies = [
+ "tracing",
+]
+
 [[package]]
 name = "sp-transaction-pool"
 version = "2.0.0-dev"

substrate/Cargo.toml

@@ -159,6 +159,7 @@ members = [
 	"primitives/timestamp",
 	"primitives/test-primitives",
 	"primitives/transaction-pool",
+	"primitives/tracing",
 	"primitives/trie",
 	"primitives/utils",
 	"primitives/wasm-interface",

substrate/client/tracing/src/lib.rs

@@ -20,20 +20,8 @@
 //!
 //! # Usage
 //!
-//! Monitor performance throughout the codebase via the creation of `Span`s.
+//! See `sp-tracing` for examples on how to use tracing.
-//! A span is set in the following way:
-//! ```
-//! let span = tracing::span!(tracing::Level::INFO, "my_span_name");
-//! let _guard = span.enter();
-//! ```
-//! To begin timing, a span must be entered. When the span is dropped, the execution time
-//! is recorded and details sent to the `Receiver` which defines how to process it.
 //!
-//! It's possible to record values with each span in the following way:
-//! ```
-//! let span = tracing::span!(tracing::Level::INFO, "my_span_name", my_number = 10, a_key = "a value");
-//! let _guard = span.enter();
-//! ```
 //! Currently we provide `Log` (default), `Telemetry` variants for `Receiver`
 
 use std::collections::HashMap;

substrate/client/transaction-pool/Cargo.toml

@@ -26,10 +26,10 @@ sc-transaction-graph = { version = "2.0.0-dev", path = "./graph" }
 sp-api = { version = "2.0.0-dev", path = "../../primitives/api" }
 sp-core = { version = "2.0.0-dev", path = "../../primitives/core" }
 sp-runtime = { version = "2.0.0-dev", path = "../../primitives/runtime" }
+sp-tracing = { version = "2.0.0-dev", path = "../../primitives/tracing" }
 sp-transaction-pool = { version = "2.0.0-dev", path = "../../primitives/transaction-pool" }
 sp-blockchain = { version = "2.0.0-dev", path = "../../primitives/blockchain" }
 sp-utils = { version = "2.0.0-dev", path = "../../primitives/utils" }
-tracing = "0.1.10"
 wasm-timer = "0.2"
 
 [dev-dependencies]

substrate/client/transaction-pool/src/api.rs

@@ -89,17 +89,17 @@ impl<Client, Block> sc_transaction_graph::ChainApi for FullChainApi<Client, Bloc
 		let at = at.clone();
 
 		self.pool.spawn_ok(futures_diagnose::diagnose("validate-transaction", async move {
-			let span = tracing::span!(tracing::Level::DEBUG, "validate_transaction::check_version");
+			sp_tracing::enter_span!("validate_transaction");
-			let guard = span.enter();
 			let runtime_api = client.runtime_api();
-			let has_v2 = runtime_api
+			let has_v2 = sp_tracing::tracing_span! { "check_version";
+				runtime_api
 				.has_api_with::<dyn TaggedTransactionQueue<Self::Block, Error=()>, _>(
 					&at, |v| v >= 2,
 				)
-				.unwrap_or_default();
+				.unwrap_or_default()
-			std::mem::drop(guard);
+			};
-			let span = tracing::span!(tracing::Level::DEBUG, "validate_transaction");
+
-			let _guard = span.enter();
+			sp_tracing::enter_span!("runtime::validate_transaction");
 			let res = if has_v2 {
 				runtime_api.validate_transaction(&at, source, uxt)
 			} else {

substrate/frame/executive/Cargo.toml

@@ -17,6 +17,7 @@ frame-support = { version = "2.0.0-dev", default-features = false, path = "../su
 frame-system = { version = "2.0.0-dev", default-features = false, path = "../system" }
 serde = { version = "1.0.101", optional = true }
 sp-runtime = { version = "2.0.0-dev", default-features = false, path = "../../primitives/runtime" }
+sp-tracing = { version = "2.0.0-dev", default-features = false, path = "../../primitives/tracing" }
 sp-std = { version = "2.0.0-dev", default-features = false, path = "../../primitives/std" }
 sp-io = { version = "2.0.0-dev", default-features = false, path = "../../primitives/io" }
 
@@ -37,5 +38,6 @@ std = [
 	"frame-system/std",
 	"serde",
 	"sp-runtime/std",
+	"sp-tracing/std",
 	"sp-std/std",
 ]

substrate/frame/executive/src/lib.rs

@@ -348,25 +348,20 @@ where
 		source: TransactionSource,
 		uxt: Block::Extrinsic,
 	) -> TransactionValidity {
-		use frame_support::tracing_span;
+		use sp_tracing::tracing_span;
 
-		tracing_span!{ "validate_transaction::using_encoded";
+		sp_tracing::enter_span!("validate_transaction");
-			let encoded_len = uxt.using_encoded(|d| d.len());
-		};
 
-		tracing_span!{ "validate_transaction::check";
+		let encoded_len = tracing_span!{ "using_encoded"; uxt.using_encoded(|d| d.len()) };
-			let xt = uxt.check(&Default::default())?;
-		};
 
-		tracing_span!{ "validate_transaction::dispatch_info";
+		let xt = tracing_span!{ "check"; uxt.check(&Default::default())? };
-			let dispatch_info = xt.get_dispatch_info();
-		};
 
-		tracing_span!{ "validate_transaction::validate";
+		let dispatch_info = tracing_span!{ "dispatch_info"; xt.get_dispatch_info() };
-			let result = xt.validate::<UnsignedValidator>(source, &dispatch_info, encoded_len);
-		};
 
-		result
+		tracing_span! {
+			"validate";
+			xt.validate::<UnsignedValidator>(source, &dispatch_info, encoded_len)
+		}
 	}
 
 	/// Start an offchain worker and generate extrinsics.

substrate/frame/support/Cargo.toml

@@ -19,6 +19,7 @@ frame-metadata = { version = "11.0.0-dev", default-features = false, path = "../
 sp-std = { version = "2.0.0-dev", default-features = false, path = "../../primitives/std" }
 sp-io = { version = "2.0.0-dev", default-features = false, path = "../../primitives/io" }
 sp-runtime = { version = "2.0.0-dev", default-features = false, path = "../../primitives/runtime" }
+sp-tracing = { version = "2.0.0-dev", default-features = false, path = "../../primitives/tracing" }
 sp-core = { version = "2.0.0-dev", default-features = false, path = "../../primitives/core" }
 sp-arithmetic = { version = "2.0.0-dev", default-features = false, path = "../../primitives/arithmetic" }
 sp-inherents = { version = "2.0.0-dev", default-features = false, path = "../../primitives/inherents" }
@@ -28,7 +29,6 @@ once_cell = { version = "1", default-features = false, optional = true }
 sp-state-machine = { version = "0.8.0-dev", optional = true, path = "../../primitives/state-machine" }
 bitmask = { version = "0.5.0", default-features = false }
 impl-trait-for-tuples = "0.1.3"
-tracing = { version = "0.1.10", optional = true }
 
 [dev-dependencies]
 pretty_assertions = "0.6.1"
@@ -37,7 +37,6 @@ frame-system = { version = "2.0.0-dev", path = "../system" }
 [features]
 default = ["std"]
 std = [
-	"tracing",
 	"once_cell",
 	"bitmask/std",
 	"serde",
@@ -45,6 +44,7 @@ std = [
 	"codec/std",
 	"sp-std/std",
 	"sp-runtime/std",
+	"sp-tracing/std",
 	"sp-arithmetic/std",
 	"frame-metadata/std",
 	"sp-inherents/std",

substrate/frame/support/src/dispatch.rs

@@ -1030,12 +1030,7 @@ macro_rules! decl_module {
 			for $module<$trait_instance$(, $instance)?> where $( $other_where_bounds )*
 		{
 			fn on_initialize(_block_number_not_used: $trait_instance::BlockNumber) -> $return {
-				use $crate::sp_std::if_std;
+				$crate::sp_tracing::enter_span!("on_initialize");
-				if_std! {
-					use $crate::tracing;
-					let span = tracing::span!(tracing::Level::DEBUG, "on_initialize");
-					let _enter = span.enter();
-				}
 				{ $( $impl )* }
 			}
 		}
@@ -1051,12 +1046,7 @@ macro_rules! decl_module {
 			for $module<$trait_instance$(, $instance)?> where $( $other_where_bounds )*
 		{
 			fn on_initialize($param: $param_ty) -> $return {
-				use $crate::sp_std::if_std;
+				$crate::sp_tracing::enter_span!("on_initialize");
-				if_std! {
-					use $crate::tracing;
-					let span = tracing::span!(tracing::Level::DEBUG, "on_initialize");
-					let _enter = span.enter();
-				}
 				{ $( $impl )* }
 			}
 		}
@@ -1082,12 +1072,7 @@ macro_rules! decl_module {
 			for $module<$trait_instance$(, $instance)?> where $( $other_where_bounds )*
 		{
 			fn on_runtime_upgrade() -> $return {
-				use $crate::sp_std::if_std;
+				$crate::sp_tracing::enter_span!("on_runtime_upgrade");
-				if_std! {
-					use $crate::tracing;
-					let span = tracing::span!(tracing::Level::DEBUG, "on_runtime_upgrade");
-					let _enter = span.enter();
-				}
 				{ $( $impl )* }
 			}
 		}
@@ -1114,12 +1099,7 @@ macro_rules! decl_module {
 			for $module<$trait_instance$(, $instance)?> where $( $other_where_bounds )*
 		{
 			fn on_finalize(_block_number_not_used: $trait_instance::BlockNumber) {
-				use $crate::sp_std::if_std;
+				$crate::sp_tracing::enter_span!("on_finalize");
-				if_std! {
-					use $crate::tracing;
-					let span = tracing::span!(tracing::Level::DEBUG, "on_finalize");
-					let _enter = span.enter();
-				}
 				{ $( $impl )* }
 			}
 		}
@@ -1135,12 +1115,7 @@ macro_rules! decl_module {
 			for $module<$trait_instance$(, $instance)?> where $( $other_where_bounds )*
 		{
 			fn on_finalize($param: $param_ty) {
-				use $crate::sp_std::if_std;
+				$crate::sp_tracing::enter_span!("on_finalize");
-				if_std! {
-					use $crate::tracing;
-					let span = tracing::span!(tracing::Level::DEBUG, "on_finalize");
-					let _enter = span.enter();
-				}
 				{ $( $impl )* }
 			}
 		}
@@ -1209,15 +1184,9 @@ macro_rules! decl_module {
 		$vis fn $name(
 			$origin: $origin_ty $(, $param: $param_ty )*
 		) -> $crate::dispatch::DispatchResult {
-			$crate::sp_std::if_std! {
+			$crate::sp_tracing::enter_span!(stringify!($name));
-				use $crate::tracing;
+			{ $( $impl )* }
-				let span = tracing::span!(tracing::Level::DEBUG, stringify!($name));
+			Ok(())
-				let _enter = span.enter();
-			}
-			{
-				{ $( $impl )* }
-				Ok(())
-			}
 		}
 	};
 
@@ -1234,13 +1203,8 @@ macro_rules! decl_module {
 	) => {
 		$(#[doc = $doc_attr])*
 		$vis fn $name($origin: $origin_ty $(, $param: $param_ty )* ) -> $result {
-			use $crate::sp_std::if_std;
+			$crate::sp_tracing::enter_span!(stringify!($name));
-			if_std! {
+			$( $impl )*
-				use $crate::tracing;
-				let span = tracing::span!(tracing::Level::DEBUG, stringify!($name));
-				let _enter = span.enter();
-			}
-			{ $( $impl )* }
 		}
 	};
 

substrate/frame/support/src/lib.rs

@@ -23,8 +23,9 @@ extern crate self as frame_support;
 
 #[macro_use]
 extern crate bitmask;
-#[cfg(feature = "std")]
+
-pub extern crate tracing;
+#[doc(hidden)]
+pub use sp_tracing;
 
 #[cfg(feature = "std")]
 pub use serde;
@@ -222,38 +223,6 @@ macro_rules! assert_ok {
 	}
 }
 
-/// Runs given code within a tracing span, measuring it's execution time.
-///
-/// Has effect only when running in native environment. In WASM, it simply inserts the
-/// code in-place, without any metrics added.
-#[macro_export]
-macro_rules! tracing_span {
-	($name:expr; $( $code:tt )*) => {
-		let span = $crate::if_tracing!(
-			$crate::tracing::span!($crate::tracing::Level::TRACE, $name)
-		,
-			()
-		);
-		let guard = $crate::if_tracing!(span.enter(), ());
-		$( $code )*
-
-		$crate::sp_std::mem::drop(guard);
-		$crate::sp_std::mem::drop(span);
-	}
-}
-
-#[macro_export]
-#[cfg(feature = "tracing")]
-macro_rules! if_tracing {
-	( $if:expr, $else:expr ) => {{ $if }}
-}
-
-#[macro_export]
-#[cfg(not(feature = "tracing"))]
-macro_rules! if_tracing {
-	( $if:expr, $else:expr ) => {{ $else }}
-}
-
 /// The void type - it cannot exist.
 // Oh rust, you crack me up...
 #[derive(Clone, Eq, PartialEq, RuntimeDebug)]

substrate/primitives/runtime-interface/Cargo.toml

@@ -15,6 +15,7 @@ targets = ["x86_64-unknown-linux-gnu"]
 [dependencies]
 sp-wasm-interface = { version = "2.0.0-dev", path = "../wasm-interface", default-features = false }
 sp-std = { version = "2.0.0-dev", default-features = false, path = "../std" }
+sp-tracing = { version = "2.0.0-dev", default-features = false, path = "../tracing" }
 sp-runtime-interface-proc-macro = { version = "2.0.0-dev", path = "proc-macro" }
 sp-externalities = { version = "0.8.0-dev", optional = true, path = "../externalities" }
 codec = { package = "parity-scale-codec", version = "1.3.0", default-features = false }
@@ -34,6 +35,7 @@ default = [ "std" ]
 std = [
 	"sp-wasm-interface/std",
 	"sp-std/std",
+	"sp-tracing/std",
 	"codec/std",
 	"sp-externalities",
 	"primitive-types/std",

substrate/primitives/runtime-interface/proc-macro/src/runtime_interface/bare_function_interface.rs

@@ -146,6 +146,7 @@ fn function_std_impl(
 	is_wasm_only: bool,
 ) -> Result<TokenStream> {
 	let function_name = create_function_ident_with_version(&method.sig.ident, version);
+	let function_name_str = function_name.to_string();
 
 	let crate_ = generate_crate_access();
 	let args = get_function_arguments(&method.sig).map(FnArg::Typed).chain(
@@ -172,6 +173,7 @@ fn function_std_impl(
 			#[cfg(feature = "std")]
 			#( #attrs )*
 			fn #function_name( #( #args, )* ) #return_value {
+				#crate_::sp_tracing::enter_span!(#function_name_str);
 				#call_to_trait
 			}
 		}

substrate/primitives/runtime-interface/proc-macro/src/runtime_interface/host_function_interface.rs

@@ -226,6 +226,7 @@ fn generate_host_function_implementation(
 						__function_context__: &mut dyn #crate_::sp_wasm_interface::FunctionContext,
 						args: &mut dyn Iterator<Item = #crate_::sp_wasm_interface::Value>,
 					) -> std::result::Result<Option<#crate_::sp_wasm_interface::Value>, String> {
+						#crate_::sp_tracing::enter_span!(#name);
 						#( #wasm_to_ffi_values )*
 						#( #ffi_to_host_values )*
 						#host_function_call

substrate/primitives/runtime-interface/src/lib.rs

@@ -109,6 +109,9 @@ extern crate self as sp_runtime_interface;
 #[cfg(feature = "std")]
 pub use sp_wasm_interface;
 
+#[doc(hidden)]
+pub use sp_tracing;
+
 #[doc(hidden)]
 pub use sp_std;
 

substrate/primitives/runtime-interface/test/Cargo.toml

@@ -19,3 +19,4 @@ sp-runtime-interface-test-wasm-deprecated = { version = "2.0.0-dev", path = "../
 sp-state-machine = { version = "0.8.0-dev", path = "../../../primitives/state-machine" }
 sp-runtime = { version = "2.0.0-dev", path = "../../runtime" }
 sp-io = { version = "2.0.0-dev", path = "../../io" }
+tracing = "0.1.13"

substrate/primitives/runtime-interface/test/src/lib.rs

@@ -27,6 +27,8 @@ use sp_runtime_interface_test_wasm_deprecated::WASM_BINARY as WASM_BINARY_DEPREC
 use sp_wasm_interface::HostFunctions as HostFunctionsT;
 use sc_executor::CallInWasm;
 
+use std::{collections::HashSet, sync::{Arc, Mutex}};
+
 type TestExternalities = sp_state_machine::TestExternalities<sp_runtime::traits::BlakeTwo256, u64>;
 
 fn call_wasm_method<HF: HostFunctionsT>(binary: &[u8], method: &str) -> TestExternalities {
@@ -150,3 +152,47 @@ fn test_versionining_with_new_host_works() {
 		"test_versionning_works",
 	);
 }
+
+#[test]
+fn test_tracing() {
+	use tracing::span::Id as SpanId;
+
+	#[derive(Clone)]
+	struct TracingSubscriber(Arc<Mutex<Inner>>);
+
+	#[derive(Default)]
+	struct Inner {
+		spans: HashSet<&'static str>,
+	}
+
+	impl tracing::subscriber::Subscriber for TracingSubscriber {
+		fn enabled(&self, _: &tracing::Metadata) -> bool { true }
+
+		fn new_span(&self, span: &tracing::span::Attributes) -> tracing::Id {
+			let mut inner = self.0.lock().unwrap();
+			let id = SpanId::from_u64((inner.spans.len() + 1) as _);
+			inner.spans.insert(span.metadata().name());
+			id
+		}
+
+		fn record(&self, _: &SpanId, _: &tracing::span::Record) {}
+
+		fn record_follows_from(&self, _: &SpanId, _: &SpanId) {}
+
+		fn event(&self, _: &tracing::Event) {}
+
+		fn enter(&self, _: &SpanId) {}
+
+		fn exit(&self, _: &SpanId) {}
+	}
+
+	let subscriber = TracingSubscriber(Default::default());
+	let _guard = tracing::subscriber::set_default(subscriber.clone());
+
+	// Call some method to generate a trace
+	call_wasm_method::<HostFunctions>(&WASM_BINARY[..], "test_return_data");
+
+	let inner = subscriber.0.lock().unwrap();
+	assert!(inner.spans.contains("return_input_version_1"));
+	assert!(inner.spans.contains("ext_test_api_return_input_version_1"));
+}

substrate/primitives/tracing/Cargo.toml

@@ -0,0 +1,19 @@
+[package]
+name = "sp-tracing"
+version = "2.0.0-dev"
+license = "GPL-3.0"
+authors = ["Parity Technologies <admin@parity.io>"]
+edition = "2018"
+homepage = "https://substrate.dev"
+repository = "https://github.com/paritytech/substrate/"
+description = "Instrumentation primitives and macros for Substrate."
+
+[package.metadata.docs.rs]
+targets = ["x86_64-unknown-linux-gnu"]
+
+[dependencies]
+tracing = { version = "0.1.13", optional = true }
+
+[features]
+default = [ "std" ]
+std = [ "tracing" ]

substrate/primitives/tracing/src/lib.rs

@@ -0,0 +1,84 @@
+// Copyright 2020 Parity Technologies (UK) Ltd.
+// This file is part of Substrate.
+
+// Substrate is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+
+// Substrate is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+// GNU General Public License for more details.
+
+// You should have received a copy of the GNU General Public License
+// along with Substrate.  If not, see <http://www.gnu.org/licenses/>.
+
+//! Substrate tracing primitives and macros.
+//!
+//! To trace functions or invidual code in Substrate, this crate provides [`tracing_span`]
+//! and [`enter_span`]. See the individual docs for how to use these macros.
+
+#![cfg_attr(not(feature = "std"), no_std)]
+
+#[cfg(feature = "std")]
+#[doc(hidden)]
+pub use tracing;
+
+/// Runs given code within a tracing span, measuring it's execution time.
+///
+/// If tracing is not enabled, the code is still executed.
+///
+/// # Example
+///
+/// ```
+/// sp_tracing::tracing_span! {
+///     "test-span";
+///     1 + 1;
+///     // some other complex code
+/// }
+/// ```
+#[macro_export]
+macro_rules! tracing_span {
+	(
+		$name:expr;
+		$( $code:tt )*
+	) => {
+		{
+			$crate::enter_span!($name);
+			$( $code )*
+		}
+	}
+}
+
+/// Enter a span.
+///
+/// The span will be valid, until the scope is left.
+///
+/// # Example
+///
+/// ```
+/// sp_tracing::enter_span!("test-span");
+/// ```
+#[macro_export]
+macro_rules! enter_span {
+	( $name:expr ) => {
+		let __tracing_span__ = $crate::if_tracing!(
+			$crate::tracing::span!($crate::tracing::Level::TRACE, $name)
+		);
+		let __tracing_guard__ = $crate::if_tracing!(__tracing_span__.enter());
+	}
+}
+
+/// Generates the given code if the tracing dependency is enabled.
+#[macro_export]
+#[cfg(feature = "std")]
+macro_rules! if_tracing {
+	( $if:expr ) => {{ $if }}
+}
+
+#[macro_export]
+#[cfg(not(feature = "std"))]
+macro_rules! if_tracing {
+	( $if:expr ) => {{}}
+}