From 068e9eaae8591c51f037e7e99a4683b6159e6983 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Fran=C3=A7ois?= Date: Fri, 6 May 2022 19:29:44 +0000 Subject: [PATCH] simple tool to compare traces between executions (#4628) # Objective - Have an easy way to compare spans between executions ## Solution - Add a tool to compare spans from chrome traces ```bash > cargo run --release -p spancmp -- --help Compiling spancmp v0.1.0 Finished release [optimized] target(s) in 1.10s Running `target/release/spancmp --help` spancmp USAGE: spancmp [OPTIONS] [SECOND_TRACE] ARGS: OPTIONS: -h, --help Print help information -p, --pattern Filter spans by name matching the pattern -t, --threshold Filter spans that have an average shorther than the threshold [default: 0] ``` for each span, it will display the count, minimum duration, average duration and max duration. It can be filtered by a pattern on the span name or by a minimum average duration. just displaying a trace ![Screenshot 2022-04-28 at 21 56 21](https://user-images.githubusercontent.com/8672791/165835310-f465c6f2-9e6b-4808-803e-884b06e49292.png) comparing two traces ![Screenshot 2022-04-28 at 21 56 55](https://user-images.githubusercontent.com/8672791/165835353-097d266b-a70c-41b8-a8c1-27804011dc97.png) Co-authored-by: Robert Swain --- Cargo.toml | 2 +- tools/ci/src/main.rs | 12 +- tools/spancmp/Cargo.toml | 16 +++ tools/spancmp/src/main.rs | 162 ++++++++++++++++++++++++ tools/spancmp/src/parse.rs | 96 +++++++++++++++ tools/spancmp/src/pretty.rs | 237 ++++++++++++++++++++++++++++++++++++ 6 files changed, 523 insertions(+), 2 deletions(-) create mode 100644 tools/spancmp/Cargo.toml create mode 100644 tools/spancmp/src/main.rs create mode 100644 tools/spancmp/src/parse.rs create mode 100644 tools/spancmp/src/pretty.rs diff --git a/Cargo.toml b/Cargo.toml index e19ca3575a..7984244be7 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -13,7 +13,7 @@ repository = "https://github.com/bevyengine/bevy" [workspace] exclude = ["benches", "crates/bevy_ecs_compile_fail_tests"] -members = ["crates/*", "examples/ios", "tools/ci", "errors"] +members = ["crates/*", "examples/ios", "tools/ci", "tools/spancmp", "errors"] [features] default = [ diff --git a/tools/ci/src/main.rs b/tools/ci/src/main.rs index 672bcdc640..6326315d86 100644 --- a/tools/ci/src/main.rs +++ b/tools/ci/src/main.rs @@ -12,6 +12,7 @@ bitflags! { const DOC_CHECK = 0b00100000; const BENCH_CHECK = 0b01000000; const EXAMPLE_CHECK = 0b10000000; + const COMPILE_CHECK = 0b100000000; } } @@ -32,7 +33,9 @@ fn main() { Some("example-check") => Check::EXAMPLE_CHECK, Some("lints") => Check::FORMAT | Check::CLIPPY, Some("doc") => Check::DOC_TEST | Check::DOC_CHECK, - Some("compile") => Check::COMPILE_FAIL | Check::BENCH_CHECK | Check::EXAMPLE_CHECK, + Some("compile") => { + Check::COMPILE_FAIL | Check::BENCH_CHECK | Check::EXAMPLE_CHECK | Check::COMPILE_CHECK + } _ => Check::all(), }; @@ -97,4 +100,11 @@ fn main() { .run() .expect("Please fix failing doc-tests in output above."); } + + if what_to_run.contains(Check::COMPILE_CHECK) { + // Build examples and check they compile + cmd!("cargo check --workspace") + .run() + .expect("Please fix failing doc-tests in output above."); + } } diff --git a/tools/spancmp/Cargo.toml b/tools/spancmp/Cargo.toml new file mode 100644 index 0000000000..1256cafad8 --- /dev/null +++ b/tools/spancmp/Cargo.toml @@ -0,0 +1,16 @@ +[package] +name = "spancmp" +version = "0.1.0" +edition = "2021" +description = "compare spans for Bevy" +publish = false +license = "MIT OR Apache-2.0" + +[dependencies] +serde_json = "1.0" +serde = { version = "1.0", features = ["derive"] } +clap = { version = "3.1.12", features = ["derive"] } +regex = "1.5" +termcolor = "1.1" +bevy_reflect = { path = "../../crates/bevy_reflect", version = "0.8.0-dev" } +lazy_static = "1.4" diff --git a/tools/spancmp/src/main.rs b/tools/spancmp/src/main.rs new file mode 100644 index 0000000000..a106a40b38 --- /dev/null +++ b/tools/spancmp/src/main.rs @@ -0,0 +1,162 @@ +//! helper to extract span stats from a chrome trace file +//! spec: + +use std::ops::Div; + +use clap::Parser; +use parse::read_trace; +use regex::Regex; +use termcolor::{ColorChoice, StandardStream}; + +use crate::pretty::{print_spanstats, set_bold, simplify_name}; + +mod parse; +mod pretty; + +#[derive(Parser, Debug)] +struct Args { + #[clap(short, long, default_value_t = 0.0)] + /// Filter spans that have an average shorther than the threshold + threshold: f32, + + #[clap(short, long)] + /// Filter spans by name matching the pattern + pattern: Option, + + #[clap(short, long)] + /// Simplify system names + short: bool, + + trace: String, + /// Optional, second trace to compare + second_trace: Option, +} + +fn main() { + let cli = Args::parse(); + + // Setup stdout to support colors + let mut stdout = StandardStream::stdout(ColorChoice::Auto); + + // Read the first trace file + let reference = read_trace(cli.trace); + if let Some(comparison) = cli.second_trace { + // Read the second trace file + let mut comparison = read_trace(comparison); + + reference + .iter() + .filter(|(_, stats)| filter_by_threshold(stats, cli.threshold)) + .filter(|(name, _)| filter_by_pattern(name, cli.pattern.as_ref())) + .for_each(|(span, reference)| { + // for each span in the first trace + set_bold(&mut stdout, true); + if cli.short { + println!("{}", simplify_name(span)); + } else { + println!("{}", span); + } + set_bold(&mut stdout, false); + print!(" "); + let comparison = comparison.remove(span); + print_spanstats(&mut stdout, Some(reference), comparison.as_ref(), false); + }); + comparison + .iter() + .filter(|(_, stats)| filter_by_threshold(stats, cli.threshold)) + .filter(|(name, _)| filter_by_pattern(name, cli.pattern.as_ref())) + .for_each(|(span, comparison)| { + // print the spans only present in the second trace + set_bold(&mut stdout, true); + if cli.short { + println!("{}", simplify_name(span)); + } else { + println!("{}", span); + } + set_bold(&mut stdout, false); + print!(" "); + print_spanstats(&mut stdout, None, Some(comparison), false); + }); + } else { + // just print stats from the first trace + reference + .iter() + .filter(|(_, stats)| filter_by_threshold(stats, cli.threshold)) + .filter(|(name, _)| filter_by_pattern(name, cli.pattern.as_ref())) + .for_each(|(span, reference)| { + set_bold(&mut stdout, true); + if cli.short { + println!("{}", simplify_name(span)); + } else { + println!("{}", span); + } + set_bold(&mut stdout, false); + print!(" "); + print_spanstats(&mut stdout, Some(reference), None, true); + }); + } +} + +fn filter_by_threshold(span_stats: &SpanStats, threshold: f32) -> bool { + span_stats.avg > threshold +} + +fn filter_by_pattern(name: &str, pattern: Option<&Regex>) -> bool { + if let Some(pattern) = pattern { + pattern.is_match(name) + } else { + true + } +} + +#[derive(Debug)] +pub struct SpanStats { + pub count: usize, + pub avg: f32, + pub min: f32, + pub max: f32, +} + +impl Default for SpanStats { + fn default() -> Self { + Self { + count: 0, + avg: 0.0, + min: f32::MAX, + max: 0.0, + } + } +} + +impl SpanStats { + fn add_span(&mut self, duration: f32) { + if duration < self.min { + self.min = duration; + } + if duration > self.max { + self.max = duration; + } + self.avg = (self.avg * self.count as f32 + duration) / (self.count as f32 + 1.0); + self.count += 1; + } +} + +pub struct SpanRelative { + count: f32, + avg: f32, + min: f32, + max: f32, +} + +impl Div for &SpanStats { + type Output = SpanRelative; + + fn div(self, rhs: Self) -> Self::Output { + Self::Output { + count: self.count as f32 / rhs.count as f32, + avg: self.avg / rhs.avg, + min: self.min / rhs.min, + max: self.max / rhs.max, + } + } +} diff --git a/tools/spancmp/src/parse.rs b/tools/spancmp/src/parse.rs new file mode 100644 index 0000000000..d75b1562b2 --- /dev/null +++ b/tools/spancmp/src/parse.rs @@ -0,0 +1,96 @@ +use std::{ + cell::RefCell, + collections::HashMap, + fs::File, + io::{BufReader, Read}, + rc::Rc, +}; + +use serde::Deserialize; +use serde_json::Deserializer; + +use crate::SpanStats; + +/// A span from the trace +#[derive(Deserialize, Debug)] +struct Span { + /// name + name: String, + /// phase + ph: String, + /// timestamp + ts: f32, +} + +/// Ignore entries in the trace that are not a span +#[derive(Deserialize, Debug)] +struct Ignore {} + +/// deserialize helper +#[derive(Deserialize, Debug)] +#[serde(untagged)] +enum SpanOrIgnore { + /// deserialize as a span + Span(Span), + /// catchall that didn't match a span + Ignore(Ignore), +} + +#[derive(Clone)] +struct SkipperWrapper { + reader: Rc>>, +} + +impl SkipperWrapper { + fn from(mut reader: BufReader) -> SkipperWrapper { + let _ = reader.seek_relative(1); + + Self { + reader: Rc::new(RefCell::new(reader)), + } + } + + fn skip(&self) { + let _ = self.reader.borrow_mut().seek_relative(1); + } +} + +impl Read for SkipperWrapper { + fn read(&mut self, buf: &mut [u8]) -> Result { + self.reader.borrow_mut().read(buf) + } +} + +pub fn read_trace(file: String) -> HashMap { + let file = File::open(file).unwrap(); + let reader = BufReader::new(file); + let reader_wrapper = SkipperWrapper::from(reader); + + let spans = Deserializer::from_reader(reader_wrapper.clone()).into_iter::(); + + let mut open_spans: HashMap = HashMap::new(); + let mut all_spans_stats: HashMap = HashMap::new(); + spans + .flat_map(move |s| { + reader_wrapper.skip(); + + if let Ok(SpanOrIgnore::Span(span)) = s { + Some(span) + } else { + None + } + }) + .for_each(|s| { + if s.ph == "B" { + open_spans.insert(s.name.clone(), s.ts); + } else if s.ph == "E" { + let begin = open_spans.remove(&s.name).unwrap(); + all_spans_stats + .entry(s.name) + .or_default() + .add_span(s.ts - begin); + } + }); + + all_spans_stats +} diff --git a/tools/spancmp/src/pretty.rs b/tools/spancmp/src/pretty.rs new file mode 100644 index 0000000000..e51d453312 --- /dev/null +++ b/tools/spancmp/src/pretty.rs @@ -0,0 +1,237 @@ +use bevy_reflect::TypeRegistration; +use lazy_static::lazy_static; +use regex::Regex; +use termcolor::{Color, ColorSpec, StandardStream, WriteColor}; + +use crate::SpanStats; + +pub fn print_spanstats( + stdout: &mut StandardStream, + reference: Option<&SpanStats>, + comparison: Option<&SpanStats>, + reference_only: bool, +) { + match (reference, comparison) { + (Some(reference), Some(comparison)) if !reference_only => { + let relative = comparison / reference; + + print!("[count: {:8} | {:8} | ", reference.count, comparison.count); + print_relative(stdout, relative.count); + print!("] [min: "); + print_delta_time_us(reference.min); + print!(" | "); + print_delta_time_us(comparison.min); + print!(" | "); + print_relative(stdout, relative.min); + print!("] [avg: "); + print_delta_time_us(reference.avg); + print!(" | "); + print_delta_time_us(comparison.avg); + print!(" | "); + print_relative(stdout, relative.avg); + print!("] [max: "); + print_delta_time_us(reference.max); + print!(" | "); + print_delta_time_us(comparison.max); + print!(" | "); + print_relative(stdout, relative.max); + println!("]"); + } + (Some(reference), None) if !reference_only => { + print!( + "[count: {:8} | | ] [min: ", + reference.count + ); + print_delta_time_us(reference.min); + print!(" | | ] [avg: "); + print_delta_time_us(reference.avg); + print!(" | | ] [max: "); + print_delta_time_us(reference.max); + println!(" | | ]"); + } + (None, Some(comparison)) => { + print!("[count: | {:8} | ", comparison.count); + print!("] [min: | "); + print_delta_time_us(comparison.min); + print!(" | ] [avg: | "); + print_delta_time_us(comparison.avg); + print!(" | ] [max: | "); + print_delta_time_us(comparison.max); + println!(" | ]"); + } + (Some(reference), _) if reference_only => { + print!("[count: {:8}] [min: ", reference.count); + print_delta_time_us(reference.min); + print!("] [avg: "); + print_delta_time_us(reference.avg); + print!("] [max: "); + print_delta_time_us(reference.max); + println!("]"); + } + _ => {} + } +} + +const MARGIN_PERCENT: f32 = 2.0; +fn print_relative(stdout: &mut StandardStream, v: f32) { + let v_delta_percent = if v.is_nan() { 0.0 } else { (v - 1.0) * 100.0 }; + set_fg( + stdout, + if v_delta_percent > MARGIN_PERCENT { + Color::Red + } else if v_delta_percent < -MARGIN_PERCENT { + Color::Green + } else { + Color::White + }, + ); + if v_delta_percent > MARGIN_PERCENT { + print!("+"); + } else if v_delta_percent >= -MARGIN_PERCENT { + print!(" "); + } else { + print!("-"); + } + print_base10f32_fixed_width(v_delta_percent.abs(), 1.0); + print!("%"); + set_fg(stdout, Color::White); +} + +// Try to print time values using 4 numeric digits, a decimal point, and the unit +const ONE_US_IN_SECONDS: f32 = 1e-6; + +fn print_delta_time_us(dt_us: f32) { + print_base10f32_fixed_width(dt_us, ONE_US_IN_SECONDS); + print!("s"); +} + +fn print_base10f32_fixed_width(v: f32, v_scale: f32) { + Scale::from_value_and_scale(v, v_scale).print_with_scale(v, v_scale); +} + +#[derive(Debug)] +pub struct Scale { + name: &'static str, + scale_factor: f32, +} + +impl Scale { + pub const TERA: f32 = 1e12; + pub const GIGA: f32 = 1e9; + pub const MEGA: f32 = 1e6; + pub const KILO: f32 = 1e3; + pub const UNIT: f32 = 1e0; + pub const MILLI: f32 = 1e-3; + pub const MICRO: f32 = 1e-6; + pub const NANO: f32 = 1e-9; + pub const PICO: f32 = 1e-12; + + pub fn from_value_and_scale(v: f32, v_scale: f32) -> Self { + assert!(v >= 0.0); + if v == 0.0 { + Self { + name: " ", + scale_factor: Self::UNIT, + } + } else if v * v_scale >= Self::TERA { + Self { + name: "T", + scale_factor: Self::TERA, + } + } else if v * v_scale >= Self::GIGA { + Self { + name: "G", + scale_factor: Self::GIGA, + } + } else if v * v_scale >= Self::MEGA { + Self { + name: "M", + scale_factor: Self::MEGA, + } + } else if v * v_scale >= Self::KILO { + Self { + name: "k", + scale_factor: Self::KILO, + } + } else if v * v_scale >= Self::UNIT { + Self { + name: " ", + scale_factor: Self::UNIT, + } + } else if v * v_scale >= Self::MILLI { + Self { + name: "m", + scale_factor: Self::MILLI, + } + } else if v * v_scale >= Self::MICRO { + Self { + name: "ยต", + scale_factor: Self::MICRO, + } + } else if v * v_scale >= Self::NANO { + Self { + name: "n", + scale_factor: Self::NANO, + } + } else { + Self { + name: "p", + scale_factor: Self::PICO, + } + } + } + + pub fn print(&self, v: f32) { + // NOTE: Hacks for rounding to decimal places to ensure precision is correct + let precision = if ((v * 10.0).round() / 10.0) >= 100.0 { + 1 + } else if ((v * 100.0).round() / 100.0) >= 10.0 { + 2 + } else { + 3 + }; + print!("{:5.precision$}{}", v, self.name, precision = precision); + } + + pub fn print_with_scale(&self, v: f32, v_scale: f32) { + self.print(v * v_scale / self.scale_factor); + } +} + +lazy_static! { + static ref SYSTEM_NAME: Regex = Regex::new(r#"system: name="([^"]+)""#).unwrap(); + static ref SYSTEM_OVERHEAD: Regex = Regex::new(r#"system overhead: name="([^"]+)""#).unwrap(); + static ref SYSTEM_COMMANDS: Regex = Regex::new(r#"system_commands: name="([^"]+)""#).unwrap(); +} + +pub fn simplify_name(name: &str) -> String { + if let Some(captures) = SYSTEM_NAME.captures(name) { + return format!( + r#"system: name="{}""#, + TypeRegistration::get_short_name(&captures[1]) + ); + } + if let Some(captures) = SYSTEM_OVERHEAD.captures(name) { + return format!( + r#"system overhead: name="{}""#, + TypeRegistration::get_short_name(&captures[1]) + ); + } + if let Some(captures) = SYSTEM_COMMANDS.captures(name) { + return format!( + r#"system_commands: name="{}""#, + TypeRegistration::get_short_name(&captures[1]) + ); + } + name.to_string() +} + +fn set_fg(stdout: &mut StandardStream, color: Color) { + stdout + .set_color(ColorSpec::new().set_fg(Some(color))) + .unwrap(); +} + +pub fn set_bold(stdout: &mut StandardStream, bold: bool) { + stdout.set_color(ColorSpec::new().set_bold(bold)).unwrap(); +}