From bc0b8fbddf2b2e5ea7b5d3de7d709856766e5f5b Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Tomasz=20Drwi=C4=99ga?= <tomusdrw@users.noreply.github.com>
Date: Fri, 17 Apr 2020 08:42:50 +0200
Subject: [PATCH] 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 | 1 +
substrate/client/transaction-pool/Cargo.toml | 15 ++++-----
substrate/client/transaction-pool/src/api.rs | 5 +++
substrate/frame/executive/src/lib.rs | 22 +++++++++++---
substrate/frame/support/src/lib.rs | 32 ++++++++++++++++++++
5 files changed, 64 insertions(+), 11 deletions(-)
diff --git a/substrate/Cargo.lock b/substrate/Cargo.lock
index a3f24d6748c..051e6448b36 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 a6a5ec67e77..2a757652f92 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 bf104c8d781..2e590ccad8a 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 32f4c8f1b1d..747fc858668 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 9a32d9a779e..eed5c95b17e 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)]
--
GitLab