Skip to content

Commit

Permalink
refactor: use external crate for displaying tracing spans (#4781)
Browse files Browse the repository at this point in the history
When debugging #4771, I had to copy-paste tracing_timings module to get
a useful profiling output, which isn't ideal. So I improved and
published that code to crates.io as `tracing-span-tree`.

In particular, this new implementation prints the trace in the correct
order, and it also has an `.aggregate(true)` mode for cases where you
run the profiled code in a loop and want a summary.

Example without aggregation:

```
  328.25ms         vm_script_smoke_test
    306.34ms         run_vm
      306.32ms         run_wasmer
        37.16µs          get_key
        301.50ms         compile_and_serialize_wasmer
        4.44ms           run_method
          2.53ms           run_method/instantiate
          128.17µs         run_method/call
          1.74ms           run_method/drop_instance
    4.50ms           run_vm
      4.49ms           run_wasmer
        31.81µs          get_key
        4.25ms           run_method
          2.45ms           run_method/instantiate
          45.46µs          run_method/call
          1.72ms           run_method/drop_instance
    4.43ms           run_vm
      4.42ms           run_wasmer
        22.43µs          get_key
        4.21ms           run_method
          2.41ms           run_method/instantiate
          42.84µs          run_method/call
          1.72ms           run_method/drop_instance
    4.81ms           run_vm
      4.80ms           run_wasmer
        22.09µs          get_key
        4.58ms           run_method
          2.40ms           run_method/instantiate
          419.57µs         run_method/call
          1.73ms           run_method/drop_instance
```

Example with aggregation (unit-less number is the number of aggregated calls):

```
  333.98ms         vm_script_smoke_test
    325.54ms  4      run_vm
      325.48ms  4      run_wasmer
        307.07ms         compile_and_serialize_wasmer
        129.19µs  4      get_key
        17.32ms   4      run_method
          612.46µs  4      run_method/call
          6.63ms    4      run_method/drop_instance
          9.94ms    4      run_method/instantiate
```

Test Plan
---------

This is a debugging utility which is not enabled in production, so I just manually verified that the output makes sense.
  • Loading branch information
matklad authored Sep 8, 2021
1 parent eaa9f65 commit 4e761c5
Show file tree
Hide file tree
Showing 6 changed files with 17 additions and 88 deletions.
13 changes: 11 additions & 2 deletions Cargo.lock

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

3 changes: 1 addition & 2 deletions runtime/near-vm-runner-standalone/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -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"] }
Expand Down
3 changes: 1 addition & 2 deletions runtime/near-vm-runner-standalone/src/main.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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();
Expand Down
4 changes: 2 additions & 2 deletions runtime/near-vm-runner-standalone/src/script.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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);
Expand Down
78 changes: 0 additions & 78 deletions runtime/near-vm-runner-standalone/src/tracing_timings.rs

This file was deleted.

4 changes: 2 additions & 2 deletions runtime/near-vm-runner/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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();
```
Expand Down

0 comments on commit 4e761c5

Please sign in to comment.