Add performance tracing to validate_transaction (#5671)

* Validate transaction timeouts

* Add timing

* Add tracing to transaction validation.

* Fix docs.

Co-authored-by: NikVolf <nikvolf@gmail.com>

substrate/Cargo.lock

@@ -6767,6 +6767,7 @@ dependencies = [
  "sp-utils",
  "substrate-test-runtime-client",
  "substrate-test-runtime-transaction-pool",
+ "tracing",
  "wasm-timer",
 ]
 

substrate/client/transaction-pool/Cargo.toml

@@ -16,19 +16,20 @@ codec = { package = "parity-scale-codec", version = "1.3.0" }
 derive_more = "0.99.2"
 futures = { version = "0.3.1", features = ["compat"] }
 futures-diagnose = "1.0"
-log = "0.4.8"
-parking_lot = "0.10.0"
-wasm-timer = "0.2"
-sp-core = { version = "2.0.0-dev", path = "../../primitives/core" }
-sp-api = { version = "2.0.0-dev", path = "../../primitives/api" }
-sp-runtime = { version = "2.0.0-dev", path = "../../primitives/runtime" }
-sp-utils = { version = "2.0.0-dev", path = "../../primitives/utils" }
-sc-transaction-graph = { version = "2.0.0-dev", path = "./graph" }
-sp-transaction-pool = { version = "2.0.0-dev", path = "../../primitives/transaction-pool" }
-sc-client-api = { version = "2.0.0-dev", path = "../api" }
-sp-blockchain = { version = "2.0.0-dev", path = "../../primitives/blockchain" }
 intervalier = "0.4.0"
+log = "0.4.8"
 parity-util-mem = { version = "0.6.1", default-features = false, features = ["primitive-types"] }
+parking_lot = "0.10.0"
+sc-client-api = { version = "2.0.0-dev", path = "../api" }
+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-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]
 assert_matches = "1.3.0"

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

@@ -89,12 +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");
+			let guard = span.enter();
 			let runtime_api = client.runtime_api();
 			let has_v2 = runtime_api
 				.has_api_with::<dyn TaggedTransactionQueue<Self::Block, Error=()>, _>(
 					&at, |v| v >= 2,
 				)
 				.unwrap_or_default();
+			std::mem::drop(guard);
+			let span = tracing::span!(tracing::Level::DEBUG, "validate_transaction");
+			let _guard = span.enter();
 			let res = if has_v2 {
 				runtime_api.validate_transaction(&at, source, uxt)
 			} else {

substrate/frame/executive/src/lib.rs

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

substrate/frame/support/src/lib.rs

@@ -222,6 +222,38 @@ 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)]