Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Merged by Bors] - simple tool to compare traces between executions #4628

Closed
wants to merge 16 commits into from
Closed

[Merged by Bors] - simple tool to compare traces between executions #4628

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
16 commits
Select commit Hold shift + click to select a range
a6dc92e
simple tool to compare traces
mockersf Apr 28, 2022
48de83e
clippy
mockersf Apr 28, 2022
934edd2
fix order for comparison
mockersf May 2, 2022
67af174
new format
mockersf May 3, 2022
84657a9
cleanup
mockersf May 3, 2022
083ed6f
fix value
mockersf May 3, 2022
4361ff7
additional comment
mockersf May 3, 2022
d0d22b8
can simplify system names
mockersf May 4, 2022
09ad43a
spancmp: Improved formatting
superdump May 3, 2022
4802e02
spancmp: Fix single-trace and span-only-in-second formatting
superdump May 3, 2022
9ebc428
add missing newlines
mockersf May 4, 2022
461dccc
bold span name
mockersf May 4, 2022
86b05fa
read as a stream
mockersf May 4, 2022
0c34ef7
split into modules
mockersf May 4, 2022
001f75a
making sure spancmp is checked by CI
mockersf May 4, 2022
75017bd
revert changes on number of frames
mockersf May 4, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Prev Previous commit
Next Next commit
split into modules
  • Loading branch information
@mockersf
mockersf committed May 4, 2022
commit 0c34ef7cd9a7ed99e141fd42853cbf68cccd2ab9
343 changes: 12 additions & 331 deletions tools/spancmp/src/main.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,48 +1,17 @@
//! helper to extract span stats from a chrome trace file
//! spec: <https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.puwqg050lyuy>

use std::{
cell::RefCell,
collections::HashMap,
fs::File,
io::{BufReader, Read},
ops::Div,
rc::Rc,
};
use std::ops::Div;

use clap::Parser;
use lazy_static::lazy_static;
use parse::read_trace;
use regex::Regex;
use serde::Deserialize;
use serde_json::Deserializer;
use termcolor::{Color, ColorChoice, ColorSpec, StandardStream, WriteColor};
use termcolor::{ColorChoice, StandardStream};

use bevy_reflect::TypeRegistration;
use crate::pretty::{print_spanstats, set_bold, simplify_name};

/// 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),
}
mod parse;
mod pretty;

#[derive(Parser, Debug)]
struct Args {
Expand Down Expand Up @@ -140,138 +109,12 @@ fn filter_by_pattern(name: &str, pattern: Option<&Regex>) -> bool {
}
}

#[derive(Clone)]
struct SkipperWrapper {
reader: Rc<RefCell<BufReader<File>>>,
}

impl SkipperWrapper {
fn from(mut reader: BufReader<File>) -> 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<usize, std::io::Error> {
self.reader.borrow_mut().read(buf)
}
}

fn read_trace(file: String) -> HashMap<String, SpanStats> {
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::<SpanOrIgnore>();

let mut open_spans: HashMap<String, f32> = HashMap::new();
let mut all_spans_stats: HashMap<String, SpanStats> = 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
}

#[derive(Debug)]
struct SpanStats {
count: usize,
avg: f32,
min: f32,
max: f32,
}

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!("]");
}
_ => {}
}
pub struct SpanStats {
pub count: usize,
pub avg: f32,
pub min: f32,
pub max: f32,
}

impl Default for SpanStats {
Expand All @@ -298,7 +141,7 @@ impl SpanStats {
}
}

struct SpanRelative {
pub struct SpanRelative {
count: f32,
avg: f32,
min: f32,
Expand All @@ -317,165 +160,3 @@ impl Div for &SpanStats {
}
}
}

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();
}
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();
}
fn set_bold(stdout: &mut StandardStream, bold: bool) {
stdout.set_color(ColorSpec::new().set_bold(bold)).unwrap();
}
Loading