From 3eb37e62e0c0219eff1557cf1581c302a916d688 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tomasz=20Drwi=C4=99ga?= Date: Wed, 15 Apr 2020 16:00:47 +0200 Subject: [PATCH 1/4] Validate transaction timeouts --- client/transaction-pool/src/api.rs | 4 ++++ frame/executive/src/lib.rs | 16 +++++++++++++++- 2 files changed, 19 insertions(+), 1 deletion(-) diff --git a/client/transaction-pool/src/api.rs b/client/transaction-pool/src/api.rs index bf104c8d78191..e510433cc446b 100644 --- a/client/transaction-pool/src/api.rs +++ b/client/transaction-pool/src/api.rs @@ -89,12 +89,15 @@ impl sc_transaction_graph::ChainApi for FullChainApi, _>( &at, |v| v >= 2, ) .unwrap_or_default(); + log::info!("ValidateTransaction: check version: {}ns", time.elapsed().as_nanos()); + let time = std::time::Instant::now(); let res = if has_v2 { runtime_api.validate_transaction(&at, source, uxt) } else { @@ -102,6 +105,7 @@ impl sc_transaction_graph::ChainApi for FullChainApi TransactionValidity { + frame_support::debug::RuntimeLogger::init(); + #[cfg(feature = "std")] + let time = std::time::Instant::now(); + frame_support::debug::trace!("ValidateTransaction: start"); + frame_support::debug::native::trace!("ValidateTransaction: start/native"); let encoded_len = uxt.using_encoded(|d| d.len()); + frame_support::debug::trace!("ValidateTransaction: encoded"); + frame_support::debug::native::trace!("ValidateTransaction: encoded ({} ns)", time.elapsed().as_nanos()); let xt = uxt.check(&Default::default())?; + frame_support::debug::trace!("ValidateTransaction: checked"); + frame_support::debug::native::trace!("ValidateTransaction: checked ({} ns)", time.elapsed().as_nanos()); let dispatch_info = xt.get_dispatch_info(); - xt.validate::(source, &dispatch_info, encoded_len) + frame_support::debug::trace!("ValidateTransaction: dispatchinfo"); + frame_support::debug::native::trace!("ValidateTransaction: dispatchinfo ({} ns)", time.elapsed().as_nanos()); + let res = xt.validate::(source, &dispatch_info, encoded_len); + frame_support::debug::trace!("ValidateTransaction: done"); + frame_support::debug::native::trace!("ValidateTransaction: done ({} ns)", time.elapsed().as_nanos()); + res } /// Start an offchain worker and generate extrinsics. From 4175bd0e883b4f267c785c088db38529f7cd09b5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tomasz=20Drwi=C4=99ga?= Date: Wed, 15 Apr 2020 16:06:25 +0200 Subject: [PATCH 2/4] Add timing --- README.md | 33 +++++++++++++++++++++++++++++++++ 1 file changed, 33 insertions(+) diff --git a/README.md b/README.md index cd00013d1ae8a..51683fbe88017 100644 --- a/README.md +++ b/README.md @@ -1,3 +1,36 @@ +Example timing (simple transfer): + +``` +2020-04-15 16:04:43.681 txpool-verifier0 INFO sc_transaction_pool::api ValidateTransaction: check version: 37599ns +2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: start +2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: start/native +2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: encoded +2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: encoded (19239 ns) +2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: checked +2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: checked (108819 ns) +2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: dispatchinfo +2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: dispatchinfo (116528 ns) +2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: done +2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: done (137791 ns) +2020-04-15 16:04:43.681 txpool-verifier0 INFO sc_transaction_pool::api ValidateTransaction: took: 305684ns +``` + +``` +2020-04-15 16:04:31.13 txpool-verifier1 INFO sc_transaction_pool::api ValidateTransaction: check version: 62429ns +2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: start +2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: start/native +2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: encoded +2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: encoded (27385 ns) +2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: checked +2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: checked (173238 ns) +2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: dispatchinfo +2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: dispatchinfo (183297 ns) +2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: done +2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: done (221605 ns) +2020-04-15 16:04:31.13 txpool-verifier1 INFO sc_transaction_pool::api ValidateTransaction: took: 482321ns +``` + + # Substrate · [![GitHub license](https://img.shields.io/github/license/paritytech/substrate)](LICENSE) [![GitLab Status](https://gitlab.parity.io/parity/substrate/badges/master/pipeline.svg)](https://gitlab.parity.io/parity/substrate/pipelines) [![PRs Welcome](https://img.shields.io/badge/PRs-welcome-brightgreen.svg)](docs/CONTRIBUTING.adoc) Substrate is a next-generation framework for blockchain innovation. From 6661c4b523271702ab9c36ffca67510724c4c06d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tomasz=20Drwi=C4=99ga?= Date: Thu, 16 Apr 2020 16:32:28 +0200 Subject: [PATCH 3/4] Add tracing to transaction validation. --- Cargo.lock | 1 + README.md | 33 --------------------------- client/transaction-pool/Cargo.toml | 17 +++++++------- client/transaction-pool/src/api.rs | 9 ++++---- frame/executive/src/lib.rs | 36 +++++++++++++++--------------- frame/support/src/lib.rs | 31 +++++++++++++++++++++++++ 6 files changed, 64 insertions(+), 63 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index a970e50e7c863..f4bf87f1fa0ea 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6744,6 +6744,7 @@ dependencies = [ "sp-utils", "substrate-test-runtime-client", "substrate-test-runtime-transaction-pool", + "tracing", "wasm-timer", ] diff --git a/README.md b/README.md index 51683fbe88017..cd00013d1ae8a 100644 --- a/README.md +++ b/README.md @@ -1,36 +1,3 @@ -Example timing (simple transfer): - -``` -2020-04-15 16:04:43.681 txpool-verifier0 INFO sc_transaction_pool::api ValidateTransaction: check version: 37599ns -2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: start -2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: start/native -2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: encoded -2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: encoded (19239 ns) -2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: checked -2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: checked (108819 ns) -2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: dispatchinfo -2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: dispatchinfo (116528 ns) -2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: done -2020-04-15 16:04:43.681 txpool-verifier0 TRACE frame_executive ValidateTransaction: done (137791 ns) -2020-04-15 16:04:43.681 txpool-verifier0 INFO sc_transaction_pool::api ValidateTransaction: took: 305684ns -``` - -``` -2020-04-15 16:04:31.13 txpool-verifier1 INFO sc_transaction_pool::api ValidateTransaction: check version: 62429ns -2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: start -2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: start/native -2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: encoded -2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: encoded (27385 ns) -2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: checked -2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: checked (173238 ns) -2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: dispatchinfo -2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: dispatchinfo (183297 ns) -2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: done -2020-04-15 16:04:31.13 txpool-verifier1 TRACE frame_executive ValidateTransaction: done (221605 ns) -2020-04-15 16:04:31.13 txpool-verifier1 INFO sc_transaction_pool::api ValidateTransaction: took: 482321ns -``` - - # Substrate · [![GitHub license](https://img.shields.io/github/license/paritytech/substrate)](LICENSE) [![GitLab Status](https://gitlab.parity.io/parity/substrate/badges/master/pipeline.svg)](https://gitlab.parity.io/parity/substrate/pipelines) [![PRs Welcome](https://img.shields.io/badge/PRs-welcome-brightgreen.svg)](docs/CONTRIBUTING.adoc) Substrate is a next-generation framework for blockchain innovation. diff --git a/client/transaction-pool/Cargo.toml b/client/transaction-pool/Cargo.toml index 4eea7899f7f7e..db3410a315938 100644 --- a/client/transaction-pool/Cargo.toml +++ b/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.0", 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-blockchain = { version = "2.0.0-dev", path = "../../primitives/blockchain" } +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.0", 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/client/transaction-pool/src/api.rs b/client/transaction-pool/src/api.rs index e510433cc446b..2e590ccad8a36 100644 --- a/client/transaction-pool/src/api.rs +++ b/client/transaction-pool/src/api.rs @@ -89,15 +89,17 @@ impl sc_transaction_graph::ChainApi for FullChainApi, _>( &at, |v| v >= 2, ) .unwrap_or_default(); - log::info!("ValidateTransaction: check version: {}ns", time.elapsed().as_nanos()); - let time = std::time::Instant::now(); + 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 { @@ -105,7 +107,6 @@ impl sc_transaction_graph::ChainApi for FullChainApi TransactionValidity { - frame_support::debug::RuntimeLogger::init(); - #[cfg(feature = "std")] - let time = std::time::Instant::now(); - frame_support::debug::trace!("ValidateTransaction: start"); - frame_support::debug::native::trace!("ValidateTransaction: start/native"); - let encoded_len = uxt.using_encoded(|d| d.len()); - frame_support::debug::trace!("ValidateTransaction: encoded"); - frame_support::debug::native::trace!("ValidateTransaction: encoded ({} ns)", time.elapsed().as_nanos()); - let xt = uxt.check(&Default::default())?; - frame_support::debug::trace!("ValidateTransaction: checked"); - frame_support::debug::native::trace!("ValidateTransaction: checked ({} ns)", time.elapsed().as_nanos()); + use frame_support::tracing_span; - let dispatch_info = xt.get_dispatch_info(); - frame_support::debug::trace!("ValidateTransaction: dispatchinfo"); - frame_support::debug::native::trace!("ValidateTransaction: dispatchinfo ({} ns)", time.elapsed().as_nanos()); - let res = xt.validate::(source, &dispatch_info, encoded_len); - frame_support::debug::trace!("ValidateTransaction: done"); - frame_support::debug::native::trace!("ValidateTransaction: done ({} ns)", time.elapsed().as_nanos()); - res + 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::(source, &dispatch_info, encoded_len); + }; + + result } /// Start an offchain worker and generate extrinsics. diff --git a/frame/support/src/lib.rs b/frame/support/src/lib.rs index 9a32d9a779e0b..c5e39fc9387f3 100644 --- a/frame/support/src/lib.rs +++ b/frame/support/src/lib.rs @@ -222,6 +222,37 @@ macro_rules! assert_ok { } } +/// Opens a new tracing span. A no-op in WASM. +/// +/// The returned span can be later entered into using `tracing_span_enter`. +#[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)] From 3b7b13637f8609cb94f4cdd47066de8049bc6d71 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tomasz=20Drwi=C4=99ga?= Date: Thu, 16 Apr 2020 17:58:56 +0200 Subject: [PATCH 4/4] Fix docs. --- frame/support/src/lib.rs | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/frame/support/src/lib.rs b/frame/support/src/lib.rs index c5e39fc9387f3..eed5c95b17eb3 100644 --- a/frame/support/src/lib.rs +++ b/frame/support/src/lib.rs @@ -222,9 +222,10 @@ macro_rules! assert_ok { } } -/// Opens a new tracing span. A no-op in WASM. +/// Runs given code within a tracing span, measuring it's execution time. /// -/// The returned span can be later entered into using `tracing_span_enter`. +/// 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 )*) => {