Skip to content

Commit

Permalink
Improve tracing (paritytech#5698)
Browse files Browse the repository at this point in the history 
* Improve tracing implementation

* Enable tracing in runtime interfaces

* Switch to `TRACE` level
  • Loading branch information
@bkchr
bkchr authored Apr 20, 2020
1 parent 217d5c6 commit b9a9589
Show file tree
Hide file tree
Showing 18 changed files with 206 additions and 119 deletions.
14 changes: 12 additions & 2 deletions Cargo.lock
View file

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

1 change: 1 addition & 0 deletions Cargo.toml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -159,6 +159,7 @@ members = [
"primitives/timestamp",
"primitives/test-primitives",
"primitives/transaction-pool",
"primitives/tracing",
"primitives/trie",
"primitives/utils",
"primitives/wasm-interface",
Expand Down
14 changes: 1 addition & 13 deletions client/tracing/src/lib.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
2 changes: 1 addition & 1 deletion client/transaction-pool/Cargo.toml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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]
Expand Down
14 changes: 7 additions & 7 deletions client/transaction-pool/src/api.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -89,17 +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();
sp_tracing::enter_span!("validate_transaction");
let runtime_api = client.runtime_api();
let has_v2 = runtime_api
let has_v2 = sp_tracing::tracing_span! { "check_version";
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();
.unwrap_or_default()
};

sp_tracing::enter_span!("runtime::validate_transaction");
let res = if has_v2 {
runtime_api.validate_transaction(&at, source, uxt)
} else {
Expand Down
2 changes: 2 additions & 0 deletions frame/executive/Cargo.toml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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" }

Expand All @@ -37,5 +38,6 @@ std = [
"frame-system/std",
"serde",
"sp-runtime/std",
"sp-tracing/std",
"sp-std/std",
]
23 changes: 9 additions & 14 deletions frame/executive/src/lib.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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::<UnsignedValidator>(source, &dispatch_info, encoded_len);
};
let dispatch_info = tracing_span!{ "dispatch_info"; xt.get_dispatch_info() };

result
tracing_span! {
"validate";
xt.validate::<UnsignedValidator>(source, &dispatch_info, encoded_len)
}
}

/// Start an offchain worker and generate extrinsics.
Expand Down
4 changes: 2 additions & 2 deletions frame/support/Cargo.toml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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" }
Expand All @@ -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"
Expand All @@ -37,14 +37,14 @@ frame-system = { version = "2.0.0-dev", path = "../system" }
[features]
default = ["std"]
std = [
"tracing",
"once_cell",
"bitmask/std",
"serde",
"sp-io/std",
"codec/std",
"sp-std/std",
"sp-runtime/std",
"sp-tracing/std",
"sp-arithmetic/std",
"frame-metadata/std",
"sp-inherents/std",
Expand Down
56 changes: 10 additions & 46 deletions frame/support/src/dispatch.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 )* }
}
}
Expand All @@ -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 )* }
}
}
Expand All @@ -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 )* }
}
}
Expand All @@ -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 )* }
}
}
Expand All @@ -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 )* }
}
}
Expand Down Expand Up @@ -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(())
}
};

Expand All @@ -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 )*
}
};

Expand Down
37 changes: 3 additions & 34 deletions frame/support/src/lib.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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)]
Expand Down
2 changes: 2 additions & 0 deletions primitives/runtime-interface/Cargo.toml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 }
Expand All @@ -34,6 +35,7 @@ default = [ "std" ]
std = [
"sp-wasm-interface/std",
"sp-std/std",
"sp-tracing/std",
"codec/std",
"sp-externalities",
"primitive-types/std",
Expand Down
2 changes: 2 additions & 0 deletions primitives/runtime-interface/proc-macro/src/runtime_interface/bare_function_interface.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -146,6 +146,7 @@ fn function_std_impl(
is_wasm_only: bool,
) -> Result<TokenStream> {
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(
Expand All @@ -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
}
}
Expand Down
Loading

0 comments on commit b9a9589

Please sign in to comment.