diff --git a/substrate/Cargo.lock b/substrate/Cargo.lock index f7f8510641..078f0c6708 100644 --- a/substrate/Cargo.lock +++ b/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" diff --git a/substrate/Cargo.toml b/substrate/Cargo.toml index 5c4e93d84c..f5ecad013c 100644 --- a/substrate/Cargo.toml +++ b/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", diff --git a/substrate/client/tracing/src/lib.rs b/substrate/client/tracing/src/lib.rs index c00bca9275..d450700ed3 100644 --- a/substrate/client/tracing/src/lib.rs +++ b/substrate/client/tracing/src/lib.rs @@ -20,20 +20,8 @@ //! //! # Usage //! -//! Monitor performance throughout the codebase via the creation of `Span`s. -//! 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. +//! See `sp-tracing` for examples on how to use tracing. //! -//! 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; diff --git a/substrate/client/transaction-pool/Cargo.toml b/substrate/client/transaction-pool/Cargo.toml index c96e4c0332..6d4f69676c 100644 --- a/substrate/client/transaction-pool/Cargo.toml +++ b/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] diff --git a/substrate/client/transaction-pool/src/api.rs b/substrate/client/transaction-pool/src/api.rs index 2e590ccad8..bd7e11a3a6 100644 --- a/substrate/client/transaction-pool/src/api.rs +++ b/substrate/client/transaction-pool/src/api.rs @@ -89,17 +89,17 @@ impl sc_transaction_graph::ChainApi for FullChainApi, _>( &at, |v| v >= 2, ) - .unwrap_or_default(); - std::mem::drop(guard); - let span = tracing::span!(tracing::Level::DEBUG, "validate_transaction"); - let _guard = span.enter(); + .unwrap_or_default() + }; + + sp_tracing::enter_span!("runtime::validate_transaction"); let res = if has_v2 { runtime_api.validate_transaction(&at, source, uxt) } else { diff --git a/substrate/frame/executive/Cargo.toml b/substrate/frame/executive/Cargo.toml index f46dc8462d..3e0e1c938a 100644 --- a/substrate/frame/executive/Cargo.toml +++ b/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", ] diff --git a/substrate/frame/executive/src/lib.rs b/substrate/frame/executive/src/lib.rs index 747fc85866..f3a4388dcf 100644 --- a/substrate/frame/executive/src/lib.rs +++ b/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"; - let encoded_len = uxt.using_encoded(|d| d.len()); - }; + sp_tracing::enter_span!("validate_transaction"); - tracing_span!{ "validate_transaction::check"; - let xt = uxt.check(&Default::default())?; - }; + let encoded_len = tracing_span!{ "using_encoded"; uxt.using_encoded(|d| d.len()) }; - tracing_span!{ "validate_transaction::dispatch_info"; - let dispatch_info = xt.get_dispatch_info(); - }; + let xt = tracing_span!{ "check"; uxt.check(&Default::default())? }; - tracing_span!{ "validate_transaction::validate"; - let result = xt.validate::(source, &dispatch_info, encoded_len); - }; + let dispatch_info = tracing_span!{ "dispatch_info"; xt.get_dispatch_info() }; - result + tracing_span! { + "validate"; + xt.validate::(source, &dispatch_info, encoded_len) + } } /// Start an offchain worker and generate extrinsics. diff --git a/substrate/frame/support/Cargo.toml b/substrate/frame/support/Cargo.toml index aee2dd79fc..0168705da7 100644 --- a/substrate/frame/support/Cargo.toml +++ b/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", diff --git a/substrate/frame/support/src/dispatch.rs b/substrate/frame/support/src/dispatch.rs index 8512ccb0a8..4287f2c1ce 100644 --- a/substrate/frame/support/src/dispatch.rs +++ b/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; - if_std! { - use $crate::tracing; - let span = tracing::span!(tracing::Level::DEBUG, "on_initialize"); - let _enter = span.enter(); - } + $crate::sp_tracing::enter_span!("on_initialize"); { $( $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; - if_std! { - use $crate::tracing; - let span = tracing::span!(tracing::Level::DEBUG, "on_initialize"); - let _enter = span.enter(); - } + $crate::sp_tracing::enter_span!("on_initialize"); { $( $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; - if_std! { - use $crate::tracing; - let span = tracing::span!(tracing::Level::DEBUG, "on_runtime_upgrade"); - let _enter = span.enter(); - } + $crate::sp_tracing::enter_span!("on_runtime_upgrade"); { $( $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; - if_std! { - use $crate::tracing; - let span = tracing::span!(tracing::Level::DEBUG, "on_finalize"); - let _enter = span.enter(); - } + $crate::sp_tracing::enter_span!("on_finalize"); { $( $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; - if_std! { - use $crate::tracing; - let span = tracing::span!(tracing::Level::DEBUG, "on_finalize"); - let _enter = span.enter(); - } + $crate::sp_tracing::enter_span!("on_finalize"); { $( $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! { - use $crate::tracing; - let span = tracing::span!(tracing::Level::DEBUG, stringify!($name)); - let _enter = span.enter(); - } - { - { $( $impl )* } - Ok(()) - } + $crate::sp_tracing::enter_span!(stringify!($name)); + { $( $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; - if_std! { - use $crate::tracing; - let span = tracing::span!(tracing::Level::DEBUG, stringify!($name)); - let _enter = span.enter(); - } - { $( $impl )* } + $crate::sp_tracing::enter_span!(stringify!($name)); + $( $impl )* } }; diff --git a/substrate/frame/support/src/lib.rs b/substrate/frame/support/src/lib.rs index eed5c95b17..8a88496eda 100644 --- a/substrate/frame/support/src/lib.rs +++ b/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)] diff --git a/substrate/primitives/runtime-interface/Cargo.toml b/substrate/primitives/runtime-interface/Cargo.toml index 362d79f150..1d0ae8f951 100644 --- a/substrate/primitives/runtime-interface/Cargo.toml +++ b/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", diff --git a/substrate/primitives/runtime-interface/proc-macro/src/runtime_interface/bare_function_interface.rs b/substrate/primitives/runtime-interface/proc-macro/src/runtime_interface/bare_function_interface.rs index e7c34fbf99..8e83556f04 100644 --- a/substrate/primitives/runtime-interface/proc-macro/src/runtime_interface/bare_function_interface.rs +++ b/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 { 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 } } diff --git a/substrate/primitives/runtime-interface/proc-macro/src/runtime_interface/host_function_interface.rs b/substrate/primitives/runtime-interface/proc-macro/src/runtime_interface/host_function_interface.rs index 205ee87105..46de98c3c3 100644 --- a/substrate/primitives/runtime-interface/proc-macro/src/runtime_interface/host_function_interface.rs +++ b/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, ) -> std::result::Result, String> { + #crate_::sp_tracing::enter_span!(#name); #( #wasm_to_ffi_values )* #( #ffi_to_host_values )* #host_function_call diff --git a/substrate/primitives/runtime-interface/src/lib.rs b/substrate/primitives/runtime-interface/src/lib.rs index fd158d4b8a..4f748825e5 100644 --- a/substrate/primitives/runtime-interface/src/lib.rs +++ b/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; diff --git a/substrate/primitives/runtime-interface/test/Cargo.toml b/substrate/primitives/runtime-interface/test/Cargo.toml index b3cdb906be..0809eeb8a1 100644 --- a/substrate/primitives/runtime-interface/test/Cargo.toml +++ b/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" diff --git a/substrate/primitives/runtime-interface/test/src/lib.rs b/substrate/primitives/runtime-interface/test/src/lib.rs index 110eda980f..8815a17a08 100644 --- a/substrate/primitives/runtime-interface/test/src/lib.rs +++ b/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; fn call_wasm_method(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>); + + #[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::(&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")); +} diff --git a/substrate/primitives/tracing/Cargo.toml b/substrate/primitives/tracing/Cargo.toml new file mode 100644 index 0000000000..8eb3bc2bea --- /dev/null +++ b/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 "] +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" ] diff --git a/substrate/primitives/tracing/src/lib.rs b/substrate/primitives/tracing/src/lib.rs new file mode 100644 index 0000000000..e5bc93cf9e --- /dev/null +++ b/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 . + +//! 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 ) => {{}} +}