diff --git a/substrate/Cargo.lock b/substrate/Cargo.lock index a3f24d6748c58b22c02a68a6834f4425e8289f00..051e6448b36bffe3d88fbcda2ae8ac9b18a09c24 100644 --- a/substrate/Cargo.lock +++ b/substrate/Cargo.lock @@ -6767,6 +6767,7 @@ dependencies = [ "sp-utils", "substrate-test-runtime-client", "substrate-test-runtime-transaction-pool", + "tracing", "wasm-timer", ] diff --git a/substrate/client/transaction-pool/Cargo.toml b/substrate/client/transaction-pool/Cargo.toml index a6a5ec67e7793580773d7d5e036c125976b0a94e..2a757652f92ab07da79c98fdefbf89a002c4e357 100644 --- a/substrate/client/transaction-pool/Cargo.toml +++ b/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" +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" -wasm-timer = "0.2" -sp-core = { version = "2.0.0-dev", path = "../../primitives/core" } +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-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" -parity-util-mem = { version = "0.6.1", default-features = false, features = ["primitive-types"] } +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" diff --git a/substrate/client/transaction-pool/src/api.rs b/substrate/client/transaction-pool/src/api.rs index bf104c8d78191c231b7102e97d31ccdf1237fefa..2e590ccad8a36f2124b50f30af720f59d67fc19f 100644 --- a/substrate/client/transaction-pool/src/api.rs +++ b/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 { diff --git a/substrate/frame/executive/src/lib.rs b/substrate/frame/executive/src/lib.rs index 32f4c8f1b1dd6a4c5fcde18cc01bc27969da7783..747fc858668628dccb17c7d82495fa16c70e5638 100644 --- a/substrate/frame/executive/src/lib.rs +++ b/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. diff --git a/substrate/frame/support/src/lib.rs b/substrate/frame/support/src/lib.rs index 9a32d9a779e0b129243290bf4c4a23c3a68dade1..eed5c95b17eb32e9488969a166ee58c6f57c198c 100644 --- a/substrate/frame/support/src/lib.rs +++ b/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)]