diff --git a/Cargo.lock b/Cargo.lock index 033a590dcc3..db826456595 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3341,8 +3341,7 @@ dependencies = [ "serde", "serde_json", "strum", - "tracing", - "tracing-subscriber", + "tracing-span-tree 0.1.0 (registry+https://github.com/rust-lang/crates.io-index)", ] [[package]] @@ -4428,7 +4427,7 @@ dependencies = [ "state-viewer", "tempfile", "testlib", - "tracing-span-tree", + "tracing-span-tree 0.1.0 (git+https://github.com/matklad/tracing-span-tree)", "walrus", "wat", ] @@ -5359,7 +5358,17 @@ dependencies = [ [[package]] name = "tracing-span-tree" version = "0.1.0" -source = "git+https://github.com/matklad/tracing-span-tree#c75a3da12384a4dc0e265bdf8d7d9b2f83fad064" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "877726b1570d7764022ef20cc61479b5bcfc1118b90521ce61f6cc9e4f5ffbd8" +dependencies = [ + "tracing", + "tracing-subscriber", +] + +[[package]] +name = "tracing-span-tree" +version = "0.1.0" +source = "git+https://github.com/matklad/tracing-span-tree#e8864ad0274bc9342b88e1ee3388f7b6a36a47f2" dependencies = [ "tracing", "tracing-subscriber", diff --git a/runtime/near-vm-runner-standalone/Cargo.toml b/runtime/near-vm-runner-standalone/Cargo.toml index b2f7df36eb9..5570c764e11 100644 --- a/runtime/near-vm-runner-standalone/Cargo.toml +++ b/runtime/near-vm-runner-standalone/Cargo.toml @@ -24,8 +24,7 @@ clap = "=3.0.0-beta.2" base64 = "0.13" strum = "0.20" num-rational = "0.3" -tracing = "0.1" -tracing-subscriber = "0.2" +tracing-span-tree = "0.1" near-vm-logic = { path = "../near-vm-logic", version = "3.0.0", features = ["costs_counting"]} near-vm-runner = { path = "../near-vm-runner", version = "3.0.0", features = ["wasmtime_vm", "wasmer1_vm"] } diff --git a/runtime/near-vm-runner-standalone/src/main.rs b/runtime/near-vm-runner-standalone/src/main.rs index 408034e9258..7e4db636c1a 100644 --- a/runtime/near-vm-runner-standalone/src/main.rs +++ b/runtime/near-vm-runner-standalone/src/main.rs @@ -7,7 +7,6 @@ //! Optional `--context-file=/tmp/context.json --config-file=/tmp/config.json` could be added //! to provide custom context and VM config. mod script; -mod tracing_timings; use crate::script::Script; use clap::Clap; @@ -121,7 +120,7 @@ fn main() { let cli_args = CliArgs::parse(); if cli_args.timings { - tracing_timings::enable(); + tracing_span_tree::span_tree().enable(); } let mut script = Script::default(); diff --git a/runtime/near-vm-runner-standalone/src/script.rs b/runtime/near-vm-runner-standalone/src/script.rs index dbb130c445b..6390b65f530 100644 --- a/runtime/near-vm-runner-standalone/src/script.rs +++ b/runtime/near-vm-runner-standalone/src/script.rs @@ -192,7 +192,7 @@ fn default_vm_context() -> VMContext { fn vm_script_smoke_test() { use near_vm_logic::ReturnData; - crate::tracing_timings::enable(); + tracing_span_tree::span_tree().enable(); let mut script = Script::default(); script.contract_cache(true); @@ -242,7 +242,7 @@ fn profile_data_is_per_outcome() { fn test_evm_slow_deserialize_repro() { fn evm_slow_deserialize_repro(vm_kind: VMKind) { println!("evm_slow_deserialize_repro of {:?}", &vm_kind); - crate::tracing_timings::enable(); + tracing_span_tree::span_tree().enable(); let mut script = Script::default(); script.vm_kind(vm_kind); diff --git a/runtime/near-vm-runner-standalone/src/tracing_timings.rs b/runtime/near-vm-runner-standalone/src/tracing_timings.rs deleted file mode 100644 index 59da00c6134..00000000000 --- a/runtime/near-vm-runner-standalone/src/tracing_timings.rs +++ /dev/null @@ -1,78 +0,0 @@ -//! Consumer of `tracing` data, which prints a hierarchical profile. -//! -//! Based on https://github.com/davidbarsky/tracing-tree, but does less, while -//! actually printing timings for spans. - -use std::fmt; -use std::time::Instant; - -use tracing::debug; -use tracing::field::{Field, Visit}; -use tracing::span::Attributes; -use tracing::{Event, Id, Subscriber}; -use tracing_subscriber::layer::Context; -use tracing_subscriber::prelude::*; -use tracing_subscriber::registry::LookupSpan; -use tracing_subscriber::Layer; - -pub fn enable() { - let subscriber = tracing_subscriber::Registry::default().with(Timings); - tracing::subscriber::set_global_default(subscriber) - .unwrap_or_else(|_| debug!("Global subscriber is already set")); -} - -struct Timings; - -struct Data { - start: Instant, -} - -impl Data { - fn new(attrs: &Attributes<'_>) -> Self { - let mut span = Self { start: Instant::now() }; - attrs.record(&mut span); - span - } -} - -impl Visit for Data { - fn record_debug(&mut self, _field: &Field, _value: &dyn fmt::Debug) {} -} - -impl Layer for Timings -where - S: Subscriber + for<'span> LookupSpan<'span> + fmt::Debug, -{ - fn new_span(&self, attrs: &Attributes, id: &Id, ctx: Context) { - let span = ctx.span(id).unwrap(); - - let data = Data::new(attrs); - span.extensions_mut().insert(data); - } - - fn on_event(&self, _event: &Event<'_>, _ctx: Context) {} - - fn on_close(&self, id: Id, ctx: Context) { - let span = ctx.span(&id).unwrap(); - #[allow(deprecated)] - let level = ctx.scope().count(); - - let ext = span.extensions(); - let data = ext.get::().unwrap(); - - let bold = "\u{001b}[1m"; - let reset = "\u{001b}[0m"; - eprintln!( - "{:width$} {:3.2?} {bold}{}{reset}", - "", - data.start.elapsed(), - span.name(), - bold = bold, - reset = reset, - width = level * 2 - ); - if level == 0 { - eprintln!() - } - } -} diff --git a/runtime/near-vm-runner/README.md b/runtime/near-vm-runner/README.md index 83a90464d8f..81b60ccb01e 100644 --- a/runtime/near-vm-runner/README.md +++ b/runtime/near-vm-runner/README.md @@ -66,10 +66,10 @@ tracing_subscriber::fmt::Subscriber::builder() code_to_profile_here(); ``` -Alternatively, in the `standalone` crate we have a more compact hierarchical subscriber +Alternatively, there's an alternative hierarchical profiler ```rust -crate::tracing_timings::enable(); +tracing_span_tree::span_tree().enable();; code_to_profile_here(); ``` diff --git a/runtime/runtime-params-estimator/src/v2.rs b/runtime/runtime-params-estimator/src/v2.rs index 6a844fcd992..bfc398c8021 100644 --- a/runtime/runtime-params-estimator/src/v2.rs +++ b/runtime/runtime-params-estimator/src/v2.rs @@ -428,7 +428,7 @@ fn slow() { metrics_to_measure: Some(vec!["ActionDeployContractBase".to_string()]), }; - tracing_span_tree::enable_aggregated(); + tracing_span_tree::span_tree().enable(); let mut ctx = Ctx::new(&config); action_deploy_contract_base(&mut ctx); } @@ -469,6 +469,6 @@ fn fast() { s.blocks.push(block) } - tracing_span_tree::enable_aggregated(); + tracing_span_tree::span_tree().enable(); s.run().unwrap(); }