From 7a71d92142ccb20fbec45b1189a52d22eff369b7 Mon Sep 17 00:00:00 2001 From: yonip23 Date: Thu, 22 Oct 2020 23:57:01 +0300 Subject: [PATCH 01/16] added statistics to dump --- .gitignore | 1 + tests/src/tests_tracing.rs | 3 +- timed/Cargo.toml | 4 +-- timed/src/lib.rs | 57 +++++++++++++++++++++++++++++++----- timed_proc_macros/src/lib.rs | 7 +++-- 5 files changed, 58 insertions(+), 14 deletions(-) diff --git a/.gitignore b/.gitignore index df5c5ef..20f5a12 100644 --- a/.gitignore +++ b/.gitignore @@ -1,3 +1,4 @@ /target Cargo.lock timed_proc_macros.iml +/timed.iml diff --git a/tests/src/tests_tracing.rs b/tests/src/tests_tracing.rs index 8f1ce06..6c1e15d 100644 --- a/tests/src/tests_tracing.rs +++ b/tests/src/tests_tracing.rs @@ -1,5 +1,6 @@ use std::{thread, time}; use timed; +use timed::TracingStats; #[allow(dead_code)] fn sleep() { @@ -41,7 +42,7 @@ pub mod foo { #[test] #[timed::timed(tracing = true)] fn test_tracing() { - timed::init_tracing!("Test"); + timed::init_tracing!("Test", TracingStats::Statistics); println!("Running main"); sleep(); diff --git a/timed/Cargo.toml b/timed/Cargo.toml index cbed64c..04bf741 100644 --- a/timed/Cargo.toml +++ b/timed/Cargo.toml @@ -15,6 +15,6 @@ include = [ # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html [dependencies] -timed_proc_macros = { version = "0.1.1" } -#timed_proc_macros = { path = "../timed_proc_macros" } +#timed_proc_macros = { version = "0.1.1" } +timed_proc_macros = { path = "../timed_proc_macros" } lazy_static = "1.4.0" \ No newline at end of file diff --git a/timed/src/lib.rs b/timed/src/lib.rs index 39fec93..bbd886e 100644 --- a/timed/src/lib.rs +++ b/timed/src/lib.rs @@ -49,16 +49,20 @@ pub use timed_proc_macros::timed; #[macro_use] extern crate lazy_static; + use std::collections::HashMap; use std::sync::Mutex; +use std::time::Duration; +use crate::Phase::Finish; lazy_static! { static ref TRACES: Mutex>> = Mutex::new(HashMap::new()); } +#[derive(Eq, PartialEq)] pub enum TracingStats { None, - Percentage, + Statistics, } pub struct Trace { @@ -67,10 +71,19 @@ pub struct Trace { stats: TracingStats, } -#[derive(Debug, Clone)] +#[derive(Clone)] pub enum Phase { - B, - E, + Start, + Finish(Duration), +} + +impl Phase { + fn to_string(&self) -> String { + match self { + Phase::Start => "Start".to_string(), + Finish(_) => "Finish".to_string() + } + } } #[derive(Clone)] @@ -95,23 +108,48 @@ impl Trace { let start = std::time::Instant::now(); let mut traces = TRACES.lock().unwrap(); let entry = traces.entry(id.to_string()).or_insert(vec![]); + let mut stats_map = HashMap::new(); + let mut total_time_nanos: u128 = 0; processor("["); for (i, hop) in entry.iter().enumerate() { + if stats == &TracingStats::Statistics { + if let Finish(d) = hop.ph { + if !stats_map.contains_key(hop.name.as_str()) { + stats_map.insert(hop.name.clone(), vec![]); + } + + stats_map.get_mut(hop.name.as_str()).unwrap().push(d); + total_time_nanos += d.as_nanos(); + } + } + let is_last = i == entry.len() - 1; let trace = format!( - "{{ \"pid\": 0, \"ts\": {}, \"ph\": \"{:?}\", \"name\": \"{}\" }}", - hop.ts, hop.ph, hop.name + "{{ \"pid\": 0, \"ts\": {}, \"ph\": \"{}\", \"name\": \"{}\" }}", + hop.ts, hop.ph.to_string(), hop.name ); processor(&format!(" {}{}", trace, if !is_last { "," } else { "" })); } processor("]"); - processor(&format!("Dumping traces took {:?}", start.elapsed())); match stats { TracingStats::None => {} - TracingStats::Percentage => {} + TracingStats::Statistics => { + processor(&format!(":::Statistics:::\nall functions total time: {:?}", Duration::from_nanos(total_time_nanos as u64))); + stats_map.iter().for_each(|(k, v)| { + let current_total: u128 = v.iter().map(|d| d.as_nanos()).sum(); + processor(&format!("function: {:<30}calls: {:<10}total time: {:<11} ({:.5}%)", + k, + v.len(), + format!("{:?}", Duration::from_nanos(current_total as u64)), + 100.0 * current_total as f64 / total_time_nanos as f64 + )); + }); + } } + + processor(&format!("Dumping traces took {:?}", start.elapsed())); } pub fn new(id: &str, processor: Option, stats: Option) -> Trace { @@ -147,4 +185,7 @@ macro_rules! init_tracing { ($name:expr, $closure:tt, $stats:expr) => { let __trace = timed::Trace::new($name, Some($closure), Some($stats)); }; + ($name:expr, $stats:expr) => { + let __trace = timed::Trace::new($name, None, Some($stats)); + }; } diff --git a/timed_proc_macros/src/lib.rs b/timed_proc_macros/src/lib.rs index c30ab9f..ec2afab 100644 --- a/timed_proc_macros/src/lib.rs +++ b/timed_proc_macros/src/lib.rs @@ -36,7 +36,7 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O .duration_since(std::time::SystemTime::UNIX_EPOCH) .unwrap() .as_micros(); - timed::Trace::collect(timed::Hop { ph: timed::Phase::B, name: #function_name.to_string(), ts}); + timed::Trace::collect(timed::Hop { ph: timed::Phase::Start, name: #function_name.to_string(), ts}); } }; let end = quote! { @@ -45,7 +45,7 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O .duration_since(std::time::SystemTime::UNIX_EPOCH) .unwrap() .as_micros(); - timed::Trace::collect(timed::Hop { ph: timed::Phase::E, name: #function_name.to_string(), ts}); + timed::Trace::collect(timed::Hop { ph: timed::Phase::Finish(elapsed), name: #function_name.to_string(), ts}); } }; (Some(begin), Some(end)) @@ -59,7 +59,7 @@ fn codegen_duration( function_name: &syn::Ident, ) -> proc_macro2::TokenStream { quote! { - #printer("function={} duration={:?}", stringify!(#function_name), start.elapsed()); + #printer("function={} duration={:?}", stringify!(#function_name), elapsed); } } @@ -131,6 +131,7 @@ pub fn timed(args: TokenStream, input: TokenStream) -> TokenStream { #tracing_begin let start = std::time::Instant::now(); let res = { #body }; + let elapsed = start.elapsed(); #print_duration #tracing_end res From aab70f3246c8228c5beb09acac52f8ceaef02931 Mon Sep 17 00:00:00 2001 From: yonip23 Date: Fri, 23 Oct 2020 00:34:09 +0300 Subject: [PATCH 02/16] prettyfied statistics printing + added full path to function names --- timed/src/lib.rs | 5 +++-- timed_proc_macros/src/lib.rs | 14 ++++++++------ 2 files changed, 11 insertions(+), 8 deletions(-) diff --git a/timed/src/lib.rs b/timed/src/lib.rs index bbd886e..130a02d 100644 --- a/timed/src/lib.rs +++ b/timed/src/lib.rs @@ -136,16 +136,17 @@ impl Trace { match stats { TracingStats::None => {} TracingStats::Statistics => { - processor(&format!(":::Statistics:::\nall functions total time: {:?}", Duration::from_nanos(total_time_nanos as u64))); + processor("========================\n Statistics\n========================"); stats_map.iter().for_each(|(k, v)| { let current_total: u128 = v.iter().map(|d| d.as_nanos()).sum(); - processor(&format!("function: {:<30}calls: {:<10}total time: {:<11} ({:.5}%)", + processor(&format!("- {}\n\t> calls: {:>6}\n\t> total time: {:<11} ({:.5}%)", k, v.len(), format!("{:?}", Duration::from_nanos(current_total as u64)), 100.0 * current_total as f64 / total_time_nanos as f64 )); }); + processor(&format!("========================\nall functions total time: {:?}", Duration::from_nanos(total_time_nanos as u64))); } } diff --git a/timed_proc_macros/src/lib.rs b/timed_proc_macros/src/lib.rs index ec2afab..9681585 100644 --- a/timed_proc_macros/src/lib.rs +++ b/timed_proc_macros/src/lib.rs @@ -32,6 +32,7 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O if let Some(true) = options.tracing { let begin = quote! { { + let module_path = std::module_path!(); let ts = std::time::SystemTime::now() .duration_since(std::time::SystemTime::UNIX_EPOCH) .unwrap() @@ -41,6 +42,7 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O }; let end = quote! { { + let module_path = std::module_path!(); let ts = std::time::SystemTime::now() .duration_since(std::time::SystemTime::UNIX_EPOCH) .unwrap() @@ -56,10 +58,10 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O fn codegen_duration( printer: &proc_macro2::TokenStream, - function_name: &syn::Ident, + function_name: &str, ) -> proc_macro2::TokenStream { quote! { - #printer("function={} duration={:?}", stringify!(#function_name), elapsed); + #printer("function={} duration={:?}", #function_name, elapsed); } } @@ -119,11 +121,11 @@ pub fn timed(args: TokenStream, input: TokenStream) -> TokenStream { block: body, .. } = &function; - - let name = &function.sig.ident; + let name = format!("{}::{}", std::module_path!(), &function.sig.ident); + let name_str = name.as_str(); let printer = codegen_printer(&options); - let print_duration = codegen_duration(&printer, &name); - let (tracing_begin, tracing_end) = codegen_tracing(&options, &name.to_string()); + let print_duration = codegen_duration(&printer, name_str); + let (tracing_begin, tracing_end) = codegen_tracing(&options, name_str); let result = quote! { #(#attrs)* From c6c96f50debe51471b6d40f305abbe549972b2a5 Mon Sep 17 00:00:00 2001 From: yonip23 Date: Fri, 23 Oct 2020 01:57:16 +0300 Subject: [PATCH 03/16] minor changes --- timed/src/lib.rs | 8 +++----- timed_proc_macros/src/lib.rs | 2 -- 2 files changed, 3 insertions(+), 7 deletions(-) diff --git a/timed/src/lib.rs b/timed/src/lib.rs index 130a02d..5a805f1 100644 --- a/timed/src/lib.rs +++ b/timed/src/lib.rs @@ -115,11 +115,9 @@ impl Trace { for (i, hop) in entry.iter().enumerate() { if stats == &TracingStats::Statistics { if let Finish(d) = hop.ph { - if !stats_map.contains_key(hop.name.as_str()) { - stats_map.insert(hop.name.clone(), vec![]); - } - - stats_map.get_mut(hop.name.as_str()).unwrap().push(d); + stats_map.entry(hop.name.clone()) + .or_insert(vec![]) + .push(d); total_time_nanos += d.as_nanos(); } } diff --git a/timed_proc_macros/src/lib.rs b/timed_proc_macros/src/lib.rs index 9681585..190c8bc 100644 --- a/timed_proc_macros/src/lib.rs +++ b/timed_proc_macros/src/lib.rs @@ -32,7 +32,6 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O if let Some(true) = options.tracing { let begin = quote! { { - let module_path = std::module_path!(); let ts = std::time::SystemTime::now() .duration_since(std::time::SystemTime::UNIX_EPOCH) .unwrap() @@ -42,7 +41,6 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O }; let end = quote! { { - let module_path = std::module_path!(); let ts = std::time::SystemTime::now() .duration_since(std::time::SystemTime::UNIX_EPOCH) .unwrap() From fcb3c70387891e517291f00b312ef7e88b23e850 Mon Sep 17 00:00:00 2001 From: yonip23 Date: Fri, 23 Oct 2020 22:47:56 +0300 Subject: [PATCH 04/16] - sorted statistics print by time (desc) - moved module_path call to inside quote! - changed phase to B and E - separated statistics test --- .gitignore | 4 +-- tests/src/tests_tracing.rs | 12 ++++++++- timed/src/lib.rs | 52 +++++++++++++++++++++++++----------- timed_proc_macros/src/lib.rs | 28 +++++-------------- 4 files changed, 57 insertions(+), 39 deletions(-) diff --git a/.gitignore b/.gitignore index 20f5a12..5f8062c 100644 --- a/.gitignore +++ b/.gitignore @@ -1,4 +1,4 @@ /target Cargo.lock -timed_proc_macros.iml -/timed.iml +*.iml +*.xml diff --git a/tests/src/tests_tracing.rs b/tests/src/tests_tracing.rs index 6c1e15d..ccdfabd 100644 --- a/tests/src/tests_tracing.rs +++ b/tests/src/tests_tracing.rs @@ -42,7 +42,17 @@ pub mod foo { #[test] #[timed::timed(tracing = true)] fn test_tracing() { - timed::init_tracing!("Test", TracingStats::Statistics); + timed::init_tracing!("Test"); + + println!("Running main"); + sleep(); + foo(); +} + +#[test] +#[timed::timed(tracing = true)] +fn test_tracing_with_stats() { + timed::init_tracing!("TestWithStats", TracingStats::Statistics); println!("Running main"); sleep(); diff --git a/timed/src/lib.rs b/timed/src/lib.rs index 5a805f1..35d73f2 100644 --- a/timed/src/lib.rs +++ b/timed/src/lib.rs @@ -78,10 +78,11 @@ pub enum Phase { } impl Phase { + // These are B and E for chrome tracing fn to_string(&self) -> String { match self { - Phase::Start => "Start".to_string(), - Finish(_) => "Finish".to_string() + Phase::Start => "B".to_string(), + Finish(_) => "E".to_string() } } } @@ -133,19 +134,7 @@ impl Trace { match stats { TracingStats::None => {} - TracingStats::Statistics => { - processor("========================\n Statistics\n========================"); - stats_map.iter().for_each(|(k, v)| { - let current_total: u128 = v.iter().map(|d| d.as_nanos()).sum(); - processor(&format!("- {}\n\t> calls: {:>6}\n\t> total time: {:<11} ({:.5}%)", - k, - v.len(), - format!("{:?}", Duration::from_nanos(current_total as u64)), - 100.0 * current_total as f64 / total_time_nanos as f64 - )); - }); - processor(&format!("========================\nall functions total time: {:?}", Duration::from_nanos(total_time_nanos as u64))); - } + TracingStats::Statistics => Trace::print_statistics(&processor, &stats_map, total_time_nanos) } processor(&format!("Dumping traces took {:?}", start.elapsed())); @@ -162,6 +151,39 @@ impl Trace { Self::register(&trace.id); trace } + + fn print_statistics(processor: &fn(&str), stats_map: &HashMap>, total_time_nanos: u128) { + struct FnStats { + name: String, + calls: usize, + overall_time: Duration, + } + impl FnStats { + fn to_string(&self, total_time_nanos: f64) -> String { + format!("- {}\n\t> calls: {:>6}\n\t> total time: {:<11} ({:.5}%)", + self.name, + self.calls, + format!("{:?}", self.overall_time), + 100.0 * self.overall_time.as_nanos() as f64 / total_time_nanos + ) + } + } + + let mut fn_stats = vec![]; + processor("========================\n Statistics\n========================"); + stats_map.iter().for_each(|(k, v)| { + let current_total = v.iter().map(|d| d.as_nanos()).sum::() as u64; + fn_stats.push(FnStats { + name: k.to_string(), + calls: v.len(), + overall_time: Duration::from_nanos(current_total), + }); + }); + + fn_stats.sort_by(|x, y| y.overall_time.as_nanos().cmp(&x.overall_time.as_nanos())); + fn_stats.iter().for_each(|f| processor(&f.to_string(total_time_nanos as f64))); + processor(&format!("========================\nall functions total time: {:?}", Duration::from_nanos(total_time_nanos as u64))); + } } impl Drop for Trace { diff --git a/timed_proc_macros/src/lib.rs b/timed_proc_macros/src/lib.rs index 190c8bc..ba26256 100644 --- a/timed_proc_macros/src/lib.rs +++ b/timed_proc_macros/src/lib.rs @@ -12,20 +12,6 @@ struct MacroArgs { tracing: Option, } -// struct Tracing; -// impl Drop for Tracing { -// fn drop(&mut self) { -// let traces = TRACES.lock().unwrap(); -// println!("Begin Dumping traces:\n-----"); -// println!("["); -// for i in 0..traces.len() { -// println!(" {}{}", traces[i], if i == traces.len() - 1 { "" } else { ","}); -// } -// println!("]"); -// println!("-----\nEnd Dumping traces"); -// } -// } - use proc_macro2::TokenStream as Code; fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, Option) { @@ -36,7 +22,7 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O .duration_since(std::time::SystemTime::UNIX_EPOCH) .unwrap() .as_micros(); - timed::Trace::collect(timed::Hop { ph: timed::Phase::Start, name: #function_name.to_string(), ts}); + timed::Trace::collect(timed::Hop { ph: timed::Phase::Start, name: format!("{}::{}", module_path, #function_name), ts}); } }; let end = quote! { @@ -45,7 +31,7 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O .duration_since(std::time::SystemTime::UNIX_EPOCH) .unwrap() .as_micros(); - timed::Trace::collect(timed::Hop { ph: timed::Phase::Finish(elapsed), name: #function_name.to_string(), ts}); + timed::Trace::collect(timed::Hop { ph: timed::Phase::Finish(elapsed), name: format!("{}::{}", module_path, #function_name), ts}); } }; (Some(begin), Some(end)) @@ -59,7 +45,7 @@ fn codegen_duration( function_name: &str, ) -> proc_macro2::TokenStream { quote! { - #printer("function={} duration={:?}", #function_name, elapsed); + #printer("function={} duration={:?}", format!("{}::{}", module_path, #function_name), elapsed); } } @@ -119,15 +105,15 @@ pub fn timed(args: TokenStream, input: TokenStream) -> TokenStream { block: body, .. } = &function; - let name = format!("{}::{}", std::module_path!(), &function.sig.ident); - let name_str = name.as_str(); + let name = function.sig.ident.to_string(); let printer = codegen_printer(&options); - let print_duration = codegen_duration(&printer, name_str); - let (tracing_begin, tracing_end) = codegen_tracing(&options, name_str); + let print_duration = codegen_duration(&printer, name.as_str()); + let (tracing_begin, tracing_end) = codegen_tracing(&options, name.as_str()); let result = quote! { #(#attrs)* #vis #sig { + let module_path = std::module_path!(); #tracing_begin let start = std::time::Instant::now(); let res = { #body }; From bfdfa758ae1d50b8f7fc538178bb3625a4780ee7 Mon Sep 17 00:00:00 2001 From: yonip23 Date: Sat, 24 Oct 2020 23:07:22 +0300 Subject: [PATCH 05/16] changed tracing api plz dont kill me (to see the usage take a look at `tests_tracing.rs` --- README.md | 6 +- tests/examples/demo_tracing.rs | 5 +- tests/src/tests_expand.rs | 5 +- tests/src/tests_macro.rs | 5 +- tests/src/tests_tracing.rs | 38 ++++++++++-- timed/src/lib.rs | 105 ++++++++++++++++++--------------- 6 files changed, 110 insertions(+), 54 deletions(-) diff --git a/README.md b/README.md index c54486b..c08f4a3 100644 --- a/README.md +++ b/README.md @@ -100,7 +100,11 @@ fn bar() { #[timed::timed(tracing = true)] fn main() { - timed::init_tracing!("Main"); + timed::init_tracing!( + "Main", + TraceOptions::new() + .with_chrome_trace(|x: &str| println!("{}", x)).build() + ); foo(); } diff --git a/tests/examples/demo_tracing.rs b/tests/examples/demo_tracing.rs index 2b817ac..ae7228a 100644 --- a/tests/examples/demo_tracing.rs +++ b/tests/examples/demo_tracing.rs @@ -16,6 +16,9 @@ fn bar() { #[timed::timed(tracing = true)] fn main() { - timed::init_tracing!("Main"); + timed::init_tracing!("Main", timed::TraceOptions::new() + .with_chrome_trace( + |x: &str| println!("{}", x) + ).build()); foo(); } diff --git a/tests/src/tests_expand.rs b/tests/src/tests_expand.rs index 19c1442..23f144a 100644 --- a/tests/src/tests_expand.rs +++ b/tests/src/tests_expand.rs @@ -18,6 +18,9 @@ fn bar() { #[timed::timed(tracing = true)] fn main() { - timed::init_tracing!("Test", (|x| { println!("{}", x) })); + timed::init_tracing!("Test", timed::TraceOptions::new() + .with_chrome_trace( + |x: &str| println!("{}", x) + ).build()); foo(); } diff --git a/tests/src/tests_macro.rs b/tests/src/tests_macro.rs index 4f7bc1c..b6ee69f 100644 --- a/tests/src/tests_macro.rs +++ b/tests/src/tests_macro.rs @@ -1,3 +1,6 @@ fn main() { - timed::init_tracing!("Hei"); + timed::init_tracing!("Hei", timed::TraceOptions::new() + .with_chrome_trace( + |x: &str| println!("{}", x) + ).build()); } diff --git a/tests/src/tests_tracing.rs b/tests/src/tests_tracing.rs index ccdfabd..8688b29 100644 --- a/tests/src/tests_tracing.rs +++ b/tests/src/tests_tracing.rs @@ -1,6 +1,5 @@ use std::{thread, time}; use timed; -use timed::TracingStats; #[allow(dead_code)] fn sleep() { @@ -41,8 +40,11 @@ pub mod foo { #[test] #[timed::timed(tracing = true)] -fn test_tracing() { - timed::init_tracing!("Test"); +fn test_tracing_chrome_tracing() { + timed::init_tracing!("Test", timed::TraceOptions::new() + .with_chrome_trace( + |x: &str| println!("{}", x) + ).build()); println!("Running main"); sleep(); @@ -52,7 +54,35 @@ fn test_tracing() { #[test] #[timed::timed(tracing = true)] fn test_tracing_with_stats() { - timed::init_tracing!("TestWithStats", TracingStats::Statistics); + timed::init_tracing!("TestWithStats", timed::TraceOptions::new() + .with_statistics( + |x: &str| println!("{}", x) + ).build()); + + println!("Running main"); + sleep(); + foo(); +} + +#[test] +#[timed::timed(tracing = true)] +fn test_tracing_with_both() { + timed::init_tracing!("TestWithBoth", timed::TraceOptions::new() + .with_statistics( + |x: &str| println!("{}", x) + ).with_chrome_trace( + |x: &str| println!("{}", x) + ).build()); + + println!("Running main"); + sleep(); + foo(); +} + +#[test] +#[timed::timed(tracing = true)] +fn test_tracing_with_none() { + timed::init_tracing!("TestWithNone", timed::TraceOptions::new().build()); println!("Running main"); sleep(); diff --git a/timed/src/lib.rs b/timed/src/lib.rs index 35d73f2..aa3d50f 100644 --- a/timed/src/lib.rs +++ b/timed/src/lib.rs @@ -59,16 +59,38 @@ lazy_static! { static ref TRACES: Mutex>> = Mutex::new(HashMap::new()); } -#[derive(Eq, PartialEq)] -pub enum TracingStats { - None, - Statistics, +#[derive(Copy, Clone)] +pub struct TraceOptions { + pub statistics: Option, + pub chrome_trace: Option, +} + +impl TraceOptions { + pub fn new() -> TraceOptions { + TraceOptions { + statistics: None, + chrome_trace: None + } + } + + pub fn with_statistics(&mut self, f: fn(&str)) -> &mut TraceOptions { + self.statistics = Some(f); + self + } + + pub fn with_chrome_trace(&mut self, f: fn(&str)) -> &mut TraceOptions { + self.chrome_trace = Some(f); + self + } + + pub fn build(self) -> TraceOptions { + self + } } pub struct Trace { id: String, - processor: fn(&str), - stats: TracingStats, + options: TraceOptions, } #[derive(Clone)] @@ -105,16 +127,21 @@ impl Trace { } } - pub fn dump(id: &str, processor: fn(&str), stats: &TracingStats) { - let start = std::time::Instant::now(); + pub fn dump(id: &str, options: &TraceOptions) { + if options.chrome_trace.is_none() && options.statistics.is_none() { return; } + let mut traces = TRACES.lock().unwrap(); let entry = traces.entry(id.to_string()).or_insert(vec![]); let mut stats_map = HashMap::new(); let mut total_time_nanos: u128 = 0; + let mut chrome_trace_string = String::new(); + + if options.chrome_trace.is_some() { + chrome_trace_string.push_str("[\n"); + } - processor("["); for (i, hop) in entry.iter().enumerate() { - if stats == &TracingStats::Statistics { + if options.statistics.is_some() { if let Finish(d) = hop.ph { stats_map.entry(hop.name.clone()) .or_insert(vec![]) @@ -123,30 +150,28 @@ impl Trace { } } - let is_last = i == entry.len() - 1; - let trace = format!( - "{{ \"pid\": 0, \"ts\": {}, \"ph\": \"{}\", \"name\": \"{}\" }}", - hop.ts, hop.ph.to_string(), hop.name - ); - processor(&format!(" {}{}", trace, if !is_last { "," } else { "" })); + if options.chrome_trace.is_some() { + let is_last = i == entry.len() - 1; + let trace = format!( + "{{ \"pid\": 0, \"ts\": {}, \"ph\": \"{}\", \"name\": \"{}\" }}", + hop.ts, hop.ph.to_string(), hop.name + ); + chrome_trace_string.push_str(&format!(" {}{}\n", trace, if !is_last { "," } else { "" })); + } } - processor("]"); - match stats { - TracingStats::None => {} - TracingStats::Statistics => Trace::print_statistics(&processor, &stats_map, total_time_nanos) + if options.chrome_trace.is_some() { + chrome_trace_string.push_str("]"); } - processor(&format!("Dumping traces took {:?}", start.elapsed())); + options.chrome_trace.map(|f| f(&chrome_trace_string)); + options.statistics.map(|f| Trace::print_statistics(&f, &stats_map, total_time_nanos)); } - pub fn new(id: &str, processor: Option, stats: Option) -> Trace { + pub fn new(id: &str, options: TraceOptions) -> Trace { let trace = Trace { id: id.into(), - processor: processor.unwrap_or(|x: &str| { - println!("{}", x); - }), - stats: stats.unwrap_or(TracingStats::None), + options, }; Self::register(&trace.id); trace @@ -186,27 +211,15 @@ impl Trace { } } -impl Drop for Trace { - fn drop(&mut self) { - Trace::dump(&self.id, self.processor, &self.stats); - } -} - #[macro_export] macro_rules! init_tracing { - () => { - let __trace = timed::Trace::new("Tracing", None, None); - }; - ($name:expr) => { - let __trace = timed::Trace::new($name, None, None); - }; - ($name:expr, $closure:tt) => { - let __trace = timed::Trace::new($name, Some($closure), None); - }; - ($name:expr, $closure:tt, $stats:expr) => { - let __trace = timed::Trace::new($name, Some($closure), Some($stats)); - }; - ($name:expr, $stats:expr) => { - let __trace = timed::Trace::new($name, None, Some($stats)); + ($name:expr, $options:expr) => { + let __trace = timed::Trace::new($name, $options); }; } + +impl Drop for Trace { + fn drop(&mut self) { + Trace::dump(&self.id, &self.options); + } +} From a0b43ea9146577b9b718b3b2b73e604230be33c4 Mon Sep 17 00:00:00 2001 From: yonip23 Date: Sun, 25 Oct 2020 01:29:10 +0200 Subject: [PATCH 06/16] changes: - cargo fmt - removed init_tracing macro and used builder design - replace traces drop behavior with explicit call (finish) --- README.md | 11 ++-- tests/examples/demo_duration.rs | 23 ++++--- tests/examples/demo_tracing.rs | 11 ++-- tests/src/tests_expand.rs | 10 +-- tests/src/tests_macro.rs | 8 +-- tests/src/tests_tracing.rs | 35 +++++----- timed/src/lib.rs | 113 +++++++++++++++++--------------- 7 files changed, 119 insertions(+), 92 deletions(-) diff --git a/README.md b/README.md index c08f4a3..912a5c6 100644 --- a/README.md +++ b/README.md @@ -100,12 +100,13 @@ fn bar() { #[timed::timed(tracing = true)] fn main() { - timed::init_tracing!( - "Main", - TraceOptions::new() - .with_chrome_trace(|x: &str| println!("{}", x)).build() - ); + let trace = timed::TraceOptions::new() + .with_chrome_trace(|x: &str| println!("{}", x)) + .build_named("Main"); + foo(); + + trace.finish(); } ``` diff --git a/tests/examples/demo_duration.rs b/tests/examples/demo_duration.rs index 6b7946f..e4132f4 100644 --- a/tests/examples/demo_duration.rs +++ b/tests/examples/demo_duration.rs @@ -1,26 +1,33 @@ use timed::timed; -#[macro_use] extern crate log; +#[macro_use] +extern crate log; #[timed] -fn add(x: i32, y: i32) -> i32 { x + y } +fn add(x: i32, y: i32) -> i32 { + x + y +} #[timed] -fn mul(x: i32, y: i32) -> i32 { x * y } +fn mul(x: i32, y: i32) -> i32 { + x * y +} #[timed(printer = "println!")] -fn mul_println(x: i32, y: i32) -> i32 { x * y} +fn mul_println(x: i32, y: i32) -> i32 { + x * y +} #[timed(printer = "info!")] -fn mul_info(x: i32, y: i32) -> i32 { x * y } - +fn mul_info(x: i32, y: i32) -> i32 { + x * y +} #[test] fn timing() { - pretty_env_logger::init(); assert_eq!(add(1, 2), 3); assert_eq!(mul(1, 2), 2); assert_eq!(mul_println(1, 2), 2); assert_eq!(mul_info(1, 2), 2); -} \ No newline at end of file +} diff --git a/tests/examples/demo_tracing.rs b/tests/examples/demo_tracing.rs index ae7228a..60f3851 100644 --- a/tests/examples/demo_tracing.rs +++ b/tests/examples/demo_tracing.rs @@ -16,9 +16,12 @@ fn bar() { #[timed::timed(tracing = true)] fn main() { - timed::init_tracing!("Main", timed::TraceOptions::new() - .with_chrome_trace( - |x: &str| println!("{}", x) - ).build()); + let trace = timed::TraceOptions::new() + .with_chrome_trace(|x: &str| println!("{}", x)) + .with_statistics(|x: &str| println!("{}", x)) + .build_named("Main"); + foo(); + + trace.finish(); } diff --git a/tests/src/tests_expand.rs b/tests/src/tests_expand.rs index 23f144a..1d88f07 100644 --- a/tests/src/tests_expand.rs +++ b/tests/src/tests_expand.rs @@ -18,9 +18,11 @@ fn bar() { #[timed::timed(tracing = true)] fn main() { - timed::init_tracing!("Test", timed::TraceOptions::new() - .with_chrome_trace( - |x: &str| println!("{}", x) - ).build()); + let trace = timed::TraceOptions::new() + .with_chrome_trace(|x: &str| println!("{}", x)) + .build_named("Tests"); + foo(); + + trace.finish(); } diff --git a/tests/src/tests_macro.rs b/tests/src/tests_macro.rs index b6ee69f..2ce9182 100644 --- a/tests/src/tests_macro.rs +++ b/tests/src/tests_macro.rs @@ -1,6 +1,6 @@ fn main() { - timed::init_tracing!("Hei", timed::TraceOptions::new() - .with_chrome_trace( - |x: &str| println!("{}", x) - ).build()); + timed::TraceOptions::new() + .with_chrome_trace(|x: &str| println!("{}", x)) + .with_statistics(|x: &str| println!("{}", x)) + .build_named("Hei"); } diff --git a/tests/src/tests_tracing.rs b/tests/src/tests_tracing.rs index 8688b29..37d01cf 100644 --- a/tests/src/tests_tracing.rs +++ b/tests/src/tests_tracing.rs @@ -30,6 +30,7 @@ pub mod foo { pub mod bar { pub mod baz { use timed::timed; + #[timed(tracing = true)] pub fn foobar() { println!("Foobar"); @@ -41,50 +42,54 @@ pub mod foo { #[test] #[timed::timed(tracing = true)] fn test_tracing_chrome_tracing() { - timed::init_tracing!("Test", timed::TraceOptions::new() - .with_chrome_trace( - |x: &str| println!("{}", x) - ).build()); + let trace = timed::TraceOptions::new() + .with_chrome_trace(|x: &str| println!("{}", x)) + .build_named("Test"); println!("Running main"); sleep(); foo(); + + trace.finish(); } #[test] #[timed::timed(tracing = true)] fn test_tracing_with_stats() { - timed::init_tracing!("TestWithStats", timed::TraceOptions::new() - .with_statistics( - |x: &str| println!("{}", x) - ).build()); + let trace = timed::TraceOptions::new() + .with_statistics(|x: &str| println!("{}", x)) + .build_named("TestWithStats"); println!("Running main"); sleep(); foo(); + + trace.finish(); } #[test] #[timed::timed(tracing = true)] fn test_tracing_with_both() { - timed::init_tracing!("TestWithBoth", timed::TraceOptions::new() - .with_statistics( - |x: &str| println!("{}", x) - ).with_chrome_trace( - |x: &str| println!("{}", x) - ).build()); + let trace = timed::TraceOptions::new() + .with_statistics(|x: &str| println!("{}", x)) + .with_chrome_trace(|x: &str| println!("{}", x)) + .build_named("TestWithBoth"); println!("Running main"); sleep(); foo(); + + trace.finish(); } #[test] #[timed::timed(tracing = true)] fn test_tracing_with_none() { - timed::init_tracing!("TestWithNone", timed::TraceOptions::new().build()); + let trace = timed::TraceOptions::new().build_named("TestWithNone"); println!("Running main"); sleep(); foo(); + + trace.finish(); } diff --git a/timed/src/lib.rs b/timed/src/lib.rs index aa3d50f..119ec88 100644 --- a/timed/src/lib.rs +++ b/timed/src/lib.rs @@ -50,16 +50,16 @@ pub use timed_proc_macros::timed; #[macro_use] extern crate lazy_static; +use crate::Phase::Finish; use std::collections::HashMap; use std::sync::Mutex; use std::time::Duration; -use crate::Phase::Finish; lazy_static! { static ref TRACES: Mutex>> = Mutex::new(HashMap::new()); } -#[derive(Copy, Clone)] +#[derive(Copy, Clone, Default)] pub struct TraceOptions { pub statistics: Option, pub chrome_trace: Option, @@ -67,10 +67,7 @@ pub struct TraceOptions { impl TraceOptions { pub fn new() -> TraceOptions { - TraceOptions { - statistics: None, - chrome_trace: None - } + TraceOptions::default() } pub fn with_statistics(&mut self, f: fn(&str)) -> &mut TraceOptions { @@ -83,8 +80,8 @@ impl TraceOptions { self } - pub fn build(self) -> TraceOptions { - self + pub fn build_named(self, name: &str) -> Trace { + Trace::new(name, self) } } @@ -104,7 +101,7 @@ impl Phase { fn to_string(&self) -> String { match self { Phase::Start => "B".to_string(), - Finish(_) => "E".to_string() + Finish(_) => "E".to_string(), } } } @@ -127,57 +124,76 @@ impl Trace { } } - pub fn dump(id: &str, options: &TraceOptions) { - if options.chrome_trace.is_none() && options.statistics.is_none() { return; } + pub fn new(id: &str, options: TraceOptions) -> Trace { + let trace = Trace { + id: id.into(), + options, + }; + Self::register(&trace.id); + trace + } + + pub fn finish(self) { + self.dump(); + } + + fn dump(&self) { + if self.options.chrome_trace.is_none() && self.options.statistics.is_none() { + return; + } let mut traces = TRACES.lock().unwrap(); - let entry = traces.entry(id.to_string()).or_insert(vec![]); + let entry = traces.entry(self.id.to_string()).or_insert(vec![]); let mut stats_map = HashMap::new(); let mut total_time_nanos: u128 = 0; let mut chrome_trace_string = String::new(); - if options.chrome_trace.is_some() { + if self.options.chrome_trace.is_some() { chrome_trace_string.push_str("[\n"); } for (i, hop) in entry.iter().enumerate() { - if options.statistics.is_some() { + if self.options.statistics.is_some() { if let Finish(d) = hop.ph { - stats_map.entry(hop.name.clone()) - .or_insert(vec![]) - .push(d); + stats_map.entry(hop.name.clone()).or_insert(vec![]).push(d); total_time_nanos += d.as_nanos(); } } - if options.chrome_trace.is_some() { + if self.options.chrome_trace.is_some() { let is_last = i == entry.len() - 1; let trace = format!( "{{ \"pid\": 0, \"ts\": {}, \"ph\": \"{}\", \"name\": \"{}\" }}", - hop.ts, hop.ph.to_string(), hop.name + hop.ts, + hop.ph.to_string(), + hop.name ); - chrome_trace_string.push_str(&format!(" {}{}\n", trace, if !is_last { "," } else { "" })); + chrome_trace_string.push_str(&format!( + " {}{}\n", + trace, + if !is_last { "," } else { "" } + )); } } - if options.chrome_trace.is_some() { + if self.options.chrome_trace.is_some() { chrome_trace_string.push_str("]"); } - options.chrome_trace.map(|f| f(&chrome_trace_string)); - options.statistics.map(|f| Trace::print_statistics(&f, &stats_map, total_time_nanos)); - } + if let Some(f) = self.options.chrome_trace { + f(&chrome_trace_string); + } - pub fn new(id: &str, options: TraceOptions) -> Trace { - let trace = Trace { - id: id.into(), - options, - }; - Self::register(&trace.id); - trace + if let Some(f) = self.options.statistics { + Trace::print_statistics(&f, &stats_map, total_time_nanos); + } } - fn print_statistics(processor: &fn(&str), stats_map: &HashMap>, total_time_nanos: u128) { + fn print_statistics( + processor: &fn(&str), + stats_map: &HashMap>, + total_time_nanos: u128, + ) { struct FnStats { name: String, calls: usize, @@ -185,11 +201,12 @@ impl Trace { } impl FnStats { fn to_string(&self, total_time_nanos: f64) -> String { - format!("- {}\n\t> calls: {:>6}\n\t> total time: {:<11} ({:.5}%)", - self.name, - self.calls, - format!("{:?}", self.overall_time), - 100.0 * self.overall_time.as_nanos() as f64 / total_time_nanos + format!( + "- {}\n\t> calls: {:>6}\n\t> total time: {:<11} ({:.5}%)", + self.name, + self.calls, + format!("{:?}", self.overall_time), + 100.0 * self.overall_time.as_nanos() as f64 / total_time_nanos ) } } @@ -206,20 +223,12 @@ impl Trace { }); fn_stats.sort_by(|x, y| y.overall_time.as_nanos().cmp(&x.overall_time.as_nanos())); - fn_stats.iter().for_each(|f| processor(&f.to_string(total_time_nanos as f64))); - processor(&format!("========================\nall functions total time: {:?}", Duration::from_nanos(total_time_nanos as u64))); - } -} - -#[macro_export] -macro_rules! init_tracing { - ($name:expr, $options:expr) => { - let __trace = timed::Trace::new($name, $options); - }; -} - -impl Drop for Trace { - fn drop(&mut self) { - Trace::dump(&self.id, &self.options); + fn_stats + .iter() + .for_each(|f| processor(&f.to_string(total_time_nanos as f64))); + processor(&format!( + "========================\nall functions total time: {:?}", + Duration::from_nanos(total_time_nanos as u64) + )); } } From b877483cf88657fa90da110175ca3d5d0c81129e Mon Sep 17 00:00:00 2001 From: yonip23 Date: Sat, 31 Oct 2020 02:03:13 +0200 Subject: [PATCH 07/16] midway --- tests/Cargo.toml | 2 + tests/src/tests_macro.rs | 9 +- tests/src/tests_tracing.rs | 92 +++++++------- timed/Cargo.toml | 3 +- timed/src/chrome_trace.rs | 59 +++++++++ timed/src/interface.rs | 24 ++++ timed/src/lib.rs | 224 +++++++++++++---------------------- timed/src/statistics.rs | 56 +++++++++ timed_proc_macros/src/lib.rs | 4 +- 9 files changed, 284 insertions(+), 189 deletions(-) create mode 100644 timed/src/chrome_trace.rs create mode 100644 timed/src/interface.rs create mode 100644 timed/src/statistics.rs diff --git a/tests/Cargo.toml b/tests/Cargo.toml index 5b11951..8b43f42 100644 --- a/tests/Cargo.toml +++ b/tests/Cargo.toml @@ -16,6 +16,8 @@ pretty_env_logger = "0.4" serde_json = "1.0.58" lazy_static = "1.4.0" +[dev-dependencies] +rusty-fork = "0.3.0" [[bin]] name = "tests_macro" diff --git a/tests/src/tests_macro.rs b/tests/src/tests_macro.rs index 2ce9182..a94a024 100644 --- a/tests/src/tests_macro.rs +++ b/tests/src/tests_macro.rs @@ -1,6 +1,7 @@ +use timed::{ChromeTraceResult, StatisticsResult}; + fn main() { - timed::TraceOptions::new() - .with_chrome_trace(|x: &str| println!("{}", x)) - .with_statistics(|x: &str| println!("{}", x)) - .build_named("Hei"); + let _ = timed::init_tracing(*timed::TraceOptions::new() + .with_chrome_trace(|x: &ChromeTraceResult| println!("{}", x.to_string())) + .with_statistics(|x: &StatisticsResult| println!("{:?}", x))); } diff --git a/tests/src/tests_tracing.rs b/tests/src/tests_tracing.rs index 37d01cf..baa7d89 100644 --- a/tests/src/tests_tracing.rs +++ b/tests/src/tests_tracing.rs @@ -1,5 +1,7 @@ use std::{thread, time}; use timed; +use timed::{StatisticsResult, ChromeTraceResult}; +use rusty_fork::rusty_fork_test; #[allow(dead_code)] fn sleep() { @@ -39,57 +41,61 @@ pub mod foo { } } -#[test] -#[timed::timed(tracing = true)] -fn test_tracing_chrome_tracing() { - let trace = timed::TraceOptions::new() - .with_chrome_trace(|x: &str| println!("{}", x)) - .build_named("Test"); +rusty_fork_test! { + #[test] + #[timed::timed(tracing = true)] + fn test_tracing_chrome_tracing() { + let _ = timed::init_tracing(*timed::TraceOptions::new() + .with_chrome_trace(|x: &ChromeTraceResult| println!("{}", x.to_string()))).unwrap(); - println!("Running main"); - sleep(); - foo(); + println!("Running main"); + sleep(); + foo(); - trace.finish(); + let _ = timed::finish_tracing().unwrap(); + } } -#[test] -#[timed::timed(tracing = true)] -fn test_tracing_with_stats() { - let trace = timed::TraceOptions::new() - .with_statistics(|x: &str| println!("{}", x)) - .build_named("TestWithStats"); +rusty_fork_test! { + #[test] + #[timed::timed(tracing = true)] + fn test_tracing_with_stats() { + let _ = timed::init_tracing(*timed::TraceOptions::new() + .with_statistics(|x: &StatisticsResult| println!("{:?}", x))).unwrap(); - println!("Running main"); - sleep(); - foo(); + println!("Running main"); + sleep(); + foo(); - trace.finish(); + let _ = timed::finish_tracing().unwrap(); + } } - -#[test] -#[timed::timed(tracing = true)] -fn test_tracing_with_both() { - let trace = timed::TraceOptions::new() - .with_statistics(|x: &str| println!("{}", x)) - .with_chrome_trace(|x: &str| println!("{}", x)) - .build_named("TestWithBoth"); - - println!("Running main"); - sleep(); - foo(); - - trace.finish(); +rusty_fork_test! { + #[test] + #[timed::timed(tracing = true)] + fn test_tracing_with_both() { + let _ = timed::init_tracing(*timed::TraceOptions::new() + .with_statistics(|x: &StatisticsResult| println!("{:?}", x)) + .with_chrome_trace(|x: &ChromeTraceResult| println!("{}", x.to_string()))).unwrap(); + + println!("Running main"); + sleep(); + foo(); + + let _ = timed::finish_tracing().unwrap(); + } } -#[test] -#[timed::timed(tracing = true)] -fn test_tracing_with_none() { - let trace = timed::TraceOptions::new().build_named("TestWithNone"); +rusty_fork_test! { + #[test] + #[timed::timed(tracing = true)] + fn test_tracing_with_none() { + let _ = timed::init_tracing(timed::TraceOptions::new()).unwrap(); - println!("Running main"); - sleep(); - foo(); + println!("Running main"); + sleep(); + foo(); - trace.finish(); -} + let _ = timed::finish_tracing().unwrap(); + } +} \ No newline at end of file diff --git a/timed/Cargo.toml b/timed/Cargo.toml index 04bf741..c3d4ed8 100644 --- a/timed/Cargo.toml +++ b/timed/Cargo.toml @@ -17,4 +17,5 @@ include = [ [dependencies] #timed_proc_macros = { version = "0.1.1" } timed_proc_macros = { path = "../timed_proc_macros" } -lazy_static = "1.4.0" \ No newline at end of file +lazy_static = "1.4.0" +thiserror = "1.0.21" \ No newline at end of file diff --git a/timed/src/chrome_trace.rs b/timed/src/chrome_trace.rs new file mode 100644 index 0000000..b93452e --- /dev/null +++ b/timed/src/chrome_trace.rs @@ -0,0 +1,59 @@ +use std::time::Duration; + +#[derive(Clone)] +pub enum Phase { + Start, + Finish(Duration), +} + +impl Phase { + // These are B and E for chrome tracing + pub(crate) fn to_string(&self) -> String { + match self { + Phase::Start => "B".to_string(), + Phase::Finish(_) => "E".to_string(), + } + } +} + +#[derive(Clone)] +pub struct ChromeTraceRecord { + pub ts: u128, + pub ph: Phase, + pub name: String, +} + +pub struct ChromeTraceResult { + pub(crate) records: Vec +} + +impl ChromeTraceResult { + pub(crate) fn new() -> ChromeTraceResult { + ChromeTraceResult { + records: vec![] + } + } + + pub fn to_string(&self) -> String { + let mut chrome_trace_string = "[\n".to_string(); + + for (i, record) in self.records.iter().enumerate() { + let is_last = i == self.records.len() - 1; + let trace = format!( + "{{ \"pid\": 0, \"ts\": {}, \"ph\": \"{}\", \"name\": \"{}\" }}", + record.ts, + record.ph.to_string(), + record.name + ); + chrome_trace_string.push_str(&format!( + " {}{}\n", + trace, + if !is_last { "," } else { "" } + )); + } + + chrome_trace_string.push_str("]"); + + return chrome_trace_string; + } +} \ No newline at end of file diff --git a/timed/src/interface.rs b/timed/src/interface.rs new file mode 100644 index 0000000..b9d094d --- /dev/null +++ b/timed/src/interface.rs @@ -0,0 +1,24 @@ +use crate::{Trace, ChromeTraceResult, StatisticsResult, ChromeTraceRecord}; +use std::sync::Mutex; + +#[derive(Copy, Clone, Default)] +pub struct TraceOptions { + pub statistics: Option, + pub chrome_trace: Option, +} + +impl TraceOptions { + pub fn new() -> TraceOptions { + TraceOptions::default() + } + + pub fn with_statistics(&mut self, f: fn(&StatisticsResult)) -> &mut TraceOptions { + self.statistics = Some(f); + self + } + + pub fn with_chrome_trace(&mut self, f: fn(&ChromeTraceResult)) -> &mut TraceOptions { + self.chrome_trace = Some(f); + self + } +} \ No newline at end of file diff --git a/timed/src/lib.rs b/timed/src/lib.rs index 119ec88..2f10185 100644 --- a/timed/src/lib.rs +++ b/timed/src/lib.rs @@ -45,96 +45,62 @@ //! //! ``` +mod interface; +mod chrome_trace; +mod statistics; + +pub use interface::*; +pub use chrome_trace::*; +pub use statistics::*; pub use timed_proc_macros::timed; #[macro_use] extern crate lazy_static; +extern crate thiserror; use crate::Phase::Finish; use std::collections::HashMap; -use std::sync::Mutex; -use std::time::Duration; - -lazy_static! { - static ref TRACES: Mutex>> = Mutex::new(HashMap::new()); +use std::sync::{Arc, Mutex}; +use thiserror::Error; + +#[derive(Error, Debug)] +pub enum TimedError { + #[error("Tracing can only be initialized once")] + TracingInitializationFailed, + #[error("Tracing finish failed: {0}")] + TracingFinishFailed(String) } -#[derive(Copy, Clone, Default)] -pub struct TraceOptions { - pub statistics: Option, - pub chrome_trace: Option, -} - -impl TraceOptions { - pub fn new() -> TraceOptions { - TraceOptions::default() - } - - pub fn with_statistics(&mut self, f: fn(&str)) -> &mut TraceOptions { - self.statistics = Some(f); - self - } - - pub fn with_chrome_trace(&mut self, f: fn(&str)) -> &mut TraceOptions { - self.chrome_trace = Some(f); - self - } +type Result = std::result::Result; - pub fn build_named(self, name: &str) -> Trace { - Trace::new(name, self) - } +lazy_static! { + static ref TRACE: Arc> = Arc::new(Mutex::new(Trace::empty())); } pub struct Trace { - id: String, options: TraceOptions, -} - -#[derive(Clone)] -pub enum Phase { - Start, - Finish(Duration), -} - -impl Phase { - // These are B and E for chrome tracing - fn to_string(&self) -> String { - match self { - Phase::Start => "B".to_string(), - Finish(_) => "E".to_string(), - } - } -} - -#[derive(Clone)] -pub struct Hop { - pub ts: u128, - pub ph: Phase, - pub name: String, + trace_data: Vec, + is_initialized: bool, + is_finished: bool, } impl Trace { - pub fn register(id: &str) { - TRACES.lock().unwrap().insert(id.to_string(), vec![]); - } - - pub fn collect(hop: Hop) { - for trace_group in TRACES.lock().unwrap().iter_mut() { - trace_group.1.push(hop.clone()); + pub(crate) fn empty() -> Trace { + Trace { + options: TraceOptions::default(), + trace_data: vec![], + is_initialized: false, + is_finished: false } } - - pub fn new(id: &str, options: TraceOptions) -> Trace { - let trace = Trace { - id: id.into(), - options, - }; - Self::register(&trace.id); - trace + pub(crate) fn set_options(&mut self, options: TraceOptions) { + self.options = options; + self.is_initialized = true; } - pub fn finish(self) { + pub fn finish(&mut self) { self.dump(); + self.is_finished = true; } fn dump(&self) { @@ -142,93 +108,73 @@ impl Trace { return; } - let mut traces = TRACES.lock().unwrap(); - let entry = traces.entry(self.id.to_string()).or_insert(vec![]); let mut stats_map = HashMap::new(); - let mut total_time_nanos: u128 = 0; - let mut chrome_trace_string = String::new(); - - if self.options.chrome_trace.is_some() { - chrome_trace_string.push_str("[\n"); - } + let mut chrome_trace_result = ChromeTraceResult::new(); - for (i, hop) in entry.iter().enumerate() { + self.trace_data.iter().for_each(|chrome_trace_record| { if self.options.statistics.is_some() { - if let Finish(d) = hop.ph { - stats_map.entry(hop.name.clone()).or_insert(vec![]).push(d); - total_time_nanos += d.as_nanos(); + if let Finish(d) = chrome_trace_record.ph { + stats_map.entry(chrome_trace_record.name.clone()).or_insert(vec![]).push(d); } } if self.options.chrome_trace.is_some() { - let is_last = i == entry.len() - 1; - let trace = format!( - "{{ \"pid\": 0, \"ts\": {}, \"ph\": \"{}\", \"name\": \"{}\" }}", - hop.ts, - hop.ph.to_string(), - hop.name - ); - chrome_trace_string.push_str(&format!( - " {}{}\n", - trace, - if !is_last { "," } else { "" } - )); + chrome_trace_result.records.push(chrome_trace_record.clone()); } - } + }); - if self.options.chrome_trace.is_some() { - chrome_trace_string.push_str("]"); + if let Some(chrome_trace_callback) = self.options.chrome_trace.as_ref() { + chrome_trace_callback(&chrome_trace_result); } - if let Some(f) = self.options.chrome_trace { - f(&chrome_trace_string); + if let Some(statistics_callback) = self.options.statistics.as_ref() { + statistics_callback(&StatisticsResult::from_raw_map(&stats_map)); } + } +} - if let Some(f) = self.options.statistics { - Trace::print_statistics(&f, &stats_map, total_time_nanos); - } +pub fn collect(chrome_trace_record: ChromeTraceRecord) { + TRACE.lock().unwrap().trace_data.push(chrome_trace_record); +} + +pub fn init_tracing(options: TraceOptions) -> Result<()> { + let mut trace = &mut *TRACE.lock().unwrap(); + + if !trace.is_initialized { + trace.set_options(options); + + return Ok(()); } - fn print_statistics( - processor: &fn(&str), - stats_map: &HashMap>, - total_time_nanos: u128, - ) { - struct FnStats { - name: String, - calls: usize, - overall_time: Duration, - } - impl FnStats { - fn to_string(&self, total_time_nanos: f64) -> String { - format!( - "- {}\n\t> calls: {:>6}\n\t> total time: {:<11} ({:.5}%)", - self.name, - self.calls, - format!("{:?}", self.overall_time), - 100.0 * self.overall_time.as_nanos() as f64 / total_time_nanos - ) - } - } + return Err(TimedError::TracingInitializationFailed); +} - let mut fn_stats = vec![]; - processor("========================\n Statistics\n========================"); - stats_map.iter().for_each(|(k, v)| { - let current_total = v.iter().map(|d| d.as_nanos()).sum::() as u64; - fn_stats.push(FnStats { - name: k.to_string(), - calls: v.len(), - overall_time: Duration::from_nanos(current_total), - }); - }); +pub fn finish_tracing() -> Result<()> { + let mut trace = &mut *TRACE.lock().unwrap(); - fn_stats.sort_by(|x, y| y.overall_time.as_nanos().cmp(&x.overall_time.as_nanos())); - fn_stats - .iter() - .for_each(|f| processor(&f.to_string(total_time_nanos as f64))); - processor(&format!( - "========================\nall functions total time: {:?}", - Duration::from_nanos(total_time_nanos as u64) - )); + if trace.is_initialized { + if !trace.is_finished { + trace.finish(); + return Ok(()); + } + + return Err(TimedError::TracingFinishFailed("Tracing finish can only be called once".to_string())); } + + return Err(TimedError::TracingFinishFailed("Tracing initialization must be called before finish".to_string())); } + +#[macro_export] +macro_rules! init_tracing { + ($options:expr) => { + { + let mut trace = *TRACE.lock().unwrap(); + + if !trace.is_initialized { + trace.set_options($options); + } + + panic!("init_tracing can only be called once"); + } + } +} \ No newline at end of file diff --git a/timed/src/statistics.rs b/timed/src/statistics.rs new file mode 100644 index 0000000..757dafd --- /dev/null +++ b/timed/src/statistics.rs @@ -0,0 +1,56 @@ +use std::cmp::Ordering; +use std::time::Duration; +use std::collections::HashMap; + +#[derive(Clone, Debug)] +pub struct StatisticsRecord { + pub(crate) name: String, + pub(crate) calls: usize, + pub(crate) overall_time: Duration +} + +impl Ord for StatisticsRecord { + // This is reversed so that longer time will be above shorter time after sorting. + fn cmp(&self, other: &Self) -> Ordering { + other.overall_time.cmp(&self.overall_time) + } +} + +impl PartialOrd for StatisticsRecord { + fn partial_cmp(&self, other: &Self) -> Option { + Some(self.cmp(other)) + } +} + +impl PartialEq for StatisticsRecord { + fn eq(&self, other: &Self) -> bool { + self.overall_time == other.overall_time + } +} + +impl Eq for StatisticsRecord {} + +#[derive(Debug)] +pub struct StatisticsResult { + records: Vec +} + +impl StatisticsResult { + pub(crate) fn from_raw_map(stats_map: &HashMap>) -> StatisticsResult { + let mut fn_stats = vec![]; + stats_map.iter().for_each(|(k, v)| { + let current_total = v.iter().map(|d| d.as_nanos()).sum::() as u64; + fn_stats.push(StatisticsRecord { + name: k.to_string(), + calls: v.len(), + overall_time: Duration::from_nanos(current_total), + }); + }); + + fn_stats.sort(); + + return StatisticsResult { + records: fn_stats + } + } +} \ No newline at end of file diff --git a/timed_proc_macros/src/lib.rs b/timed_proc_macros/src/lib.rs index ba26256..0830a3d 100644 --- a/timed_proc_macros/src/lib.rs +++ b/timed_proc_macros/src/lib.rs @@ -22,7 +22,7 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O .duration_since(std::time::SystemTime::UNIX_EPOCH) .unwrap() .as_micros(); - timed::Trace::collect(timed::Hop { ph: timed::Phase::Start, name: format!("{}::{}", module_path, #function_name), ts}); + timed::collect(timed::ChromeTraceRecord { ph: timed::Phase::Start, name: format!("{}::{}", module_path, #function_name), ts}); } }; let end = quote! { @@ -31,7 +31,7 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O .duration_since(std::time::SystemTime::UNIX_EPOCH) .unwrap() .as_micros(); - timed::Trace::collect(timed::Hop { ph: timed::Phase::Finish(elapsed), name: format!("{}::{}", module_path, #function_name), ts}); + timed::collect(timed::ChromeTraceRecord { ph: timed::Phase::Finish(elapsed), name: format!("{}::{}", module_path, #function_name), ts}); } }; (Some(begin), Some(end)) From b6a9166def7c8072a1b3b5da29efb28f0125780d Mon Sep 17 00:00:00 2001 From: yonip23 Date: Thu, 5 Nov 2020 00:18:20 +0200 Subject: [PATCH 08/16] temp - after statistics table --- tests/examples/demo_tracing.rs | 2 +- tests/src/tests_duration.rs | 194 ++++++++++++------------ tests/src/tests_expand.rs | 2 +- tests/src/tests_macro.rs | 5 +- tests/src/tests_tracing.rs | 116 +++++++------- timed/Cargo.toml | 3 +- timed/src/default_exts.rs | 102 +++++++++++++ timed/src/interface.rs | 40 +++-- timed/src/lib.rs | 133 +++++----------- timed/src/{chrome_trace.rs => trace.rs} | 35 +++-- timed_proc_macros/src/lib.rs | 52 ++----- 11 files changed, 358 insertions(+), 326 deletions(-) create mode 100644 timed/src/default_exts.rs rename timed/src/{chrome_trace.rs => trace.rs} (62%) diff --git a/tests/examples/demo_tracing.rs b/tests/examples/demo_tracing.rs index 60f3851..d2a9136 100644 --- a/tests/examples/demo_tracing.rs +++ b/tests/examples/demo_tracing.rs @@ -16,7 +16,7 @@ fn bar() { #[timed::timed(tracing = true)] fn main() { - let trace = timed::TraceOptions::new() + let trace = timed::TraceCollectorChain::new() .with_chrome_trace(|x: &str| println!("{}", x)) .with_statistics(|x: &str| println!("{}", x)) .build_named("Main"); diff --git a/tests/src/tests_duration.rs b/tests/src/tests_duration.rs index e54afc4..f044e46 100644 --- a/tests/src/tests_duration.rs +++ b/tests/src/tests_duration.rs @@ -1,97 +1,97 @@ -use std::{thread, time}; -use timed::timed; - -use std::sync::Once; -#[allow(dead_code)] -static INIT: Once = Once::new(); - -/// Setup function that is only run once, even if called multiple times. -#[allow(dead_code)] -fn init_logger() { - INIT.call_once(|| { - pretty_env_logger::init(); - }); -} - -#[timed] -fn foo(x: i32, y: i32) -> i32 { - thread::sleep(time::Duration::from_millis(100)); - x + y -} - -#[timed] -fn bar(x: i32) -> i32 { - thread::sleep(time::Duration::from_millis(100)); - x -} - -#[timed] -fn baz() -> i32 { - 42 -} - -#[timed] -fn foobar() { - thread::sleep(time::Duration::from_millis(100)); -} - -#[timed] -fn add(x: i32, y: i32) -> i32 { - x + y -} - -#[timed] -fn mul(x: i32, y: i32) -> i32 { - x * y -} - -#[timed(printer = "println!")] -fn mul_println(x: i32, y: i32) -> i32 { - x * y -} - -#[timed(printer = "info!")] -fn mul_info(x: i32, y: i32) -> i32 { - x * y -} - -#[timed(printer = "warn!")] -fn mul_error(x: i32, y: i32) -> i32 { - x * y -} - -#[timed] -async fn ping_google() { - reqwest::get("https://google.com").await.unwrap(); -} - -#[test] -fn simple() { - foo(1, 2); - bar(1); - baz(); - foobar(); - - assert_eq!(add(1, 2), 3); - assert_eq!(mul(1, 2), 2); -} - -#[test] -fn with_logging() { - init_logger(); - - mul_info(1, 1); - mul_info(1, 1); - mul_error(1, 1); -} - -#[tokio::test] -async fn with_async() { - ping_google().await -} - -#[tokio::test] -async fn test_async_quotes() { - use crate::tests_utils::get_random_quote; - get_random_quote().await -} +// use std::{thread, time}; +// use timed::timed; +// +// use std::sync::Once; +// #[allow(dead_code)] +// static INIT: Once = Once::new(); +// +// /// Setup function that is only run once, even if called multiple times. +// #[allow(dead_code)] +// fn init_logger() { +// INIT.call_once(|| { +// pretty_env_logger::init(); +// }); +// } +// +// #[timed] +// fn foo(x: i32, y: i32) -> i32 { +// thread::sleep(time::Duration::from_millis(100)); +// x + y +// } +// +// #[timed] +// fn bar(x: i32) -> i32 { +// thread::sleep(time::Duration::from_millis(100)); +// x +// } +// +// #[timed] +// fn baz() -> i32 { +// 42 +// } +// +// #[timed] +// fn foobar() { +// thread::sleep(time::Duration::from_millis(100)); +// } +// +// #[timed] +// fn add(x: i32, y: i32) -> i32 { +// x + y +// } +// +// #[timed] +// fn mul(x: i32, y: i32) -> i32 { +// x * y +// } +// +// #[timed(printer = "println!")] +// fn mul_println(x: i32, y: i32) -> i32 { +// x * y +// } +// +// #[timed(printer = "info!")] +// fn mul_info(x: i32, y: i32) -> i32 { +// x * y +// } +// +// #[timed(printer = "warn!")] +// fn mul_error(x: i32, y: i32) -> i32 { +// x * y +// } +// +// #[timed] +// async fn ping_google() { +// reqwest::get("https://google.com").await.unwrap(); +// } +// +// #[test] +// fn simple() { +// foo(1, 2); +// bar(1); +// baz(); +// foobar(); +// +// assert_eq!(add(1, 2), 3); +// assert_eq!(mul(1, 2), 2); +// } +// +// #[test] +// fn with_logging() { +// init_logger(); +// +// mul_info(1, 1); +// mul_info(1, 1); +// mul_error(1, 1); +// } +// +// #[tokio::test] +// async fn with_async() { +// ping_google().await +// } +// +// #[tokio::test] +// async fn test_async_quotes() { +// use crate::tests_utils::get_random_quote; +// get_random_quote().await +// } diff --git a/tests/src/tests_expand.rs b/tests/src/tests_expand.rs index 1d88f07..07e7dc5 100644 --- a/tests/src/tests_expand.rs +++ b/tests/src/tests_expand.rs @@ -18,7 +18,7 @@ fn bar() { #[timed::timed(tracing = true)] fn main() { - let trace = timed::TraceOptions::new() + let trace = timed::TraceCollectorChain::new() .with_chrome_trace(|x: &str| println!("{}", x)) .build_named("Tests"); diff --git a/tests/src/tests_macro.rs b/tests/src/tests_macro.rs index a94a024..1be2481 100644 --- a/tests/src/tests_macro.rs +++ b/tests/src/tests_macro.rs @@ -1,7 +1,6 @@ use timed::{ChromeTraceResult, StatisticsResult}; fn main() { - let _ = timed::init_tracing(*timed::TraceOptions::new() - .with_chrome_trace(|x: &ChromeTraceResult| println!("{}", x.to_string())) - .with_statistics(|x: &StatisticsResult| println!("{:?}", x))); + // let _ = timed::init_tracing(timed::TraceCollectorChain::new() + // .chain_output(timed::anonymous_collector!(|x: &timed::TraceRecord| println!("{}", x.to_chrome_trace())))); } diff --git a/tests/src/tests_tracing.rs b/tests/src/tests_tracing.rs index baa7d89..b48984d 100644 --- a/tests/src/tests_tracing.rs +++ b/tests/src/tests_tracing.rs @@ -1,8 +1,12 @@ use std::{thread, time}; -use timed; -use timed::{StatisticsResult, ChromeTraceResult}; + use rusty_fork::rusty_fork_test; +use timed; +use timed::{ChromeTraceResult, StatisticsResult, TraceRecord, RecordBuffer}; +use std::sync::{Arc, Mutex}; +use timed::default_exts::StatisticsExt; + #[allow(dead_code)] fn sleep() { thread::sleep(time::Duration::from_millis(10)); @@ -41,61 +45,65 @@ pub mod foo { } } -rusty_fork_test! { - #[test] - #[timed::timed(tracing = true)] - fn test_tracing_chrome_tracing() { - let _ = timed::init_tracing(*timed::TraceOptions::new() - .with_chrome_trace(|x: &ChromeTraceResult| println!("{}", x.to_string()))).unwrap(); - - println!("Running main"); - sleep(); - foo(); - - let _ = timed::finish_tracing().unwrap(); - } -} +// rusty_fork_test! { +#[test] +#[timed::timed(tracing = true)] +fn test_tracing_chrome_tracing() { + let mut statistics = RecordBuffer::new(); -rusty_fork_test! { - #[test] - #[timed::timed(tracing = true)] - fn test_tracing_with_stats() { - let _ = timed::init_tracing(*timed::TraceOptions::new() - .with_statistics(|x: &StatisticsResult| println!("{:?}", x))).unwrap(); + let _ = timed::init_tracing(timed::TraceCollectorChain::new() + .chain_output(Arc::clone(&statistics))).unwrap(); - println!("Running main"); - sleep(); + println!("Running main"); + sleep(); + for i in 0..5 { foo(); - - let _ = timed::finish_tracing().unwrap(); } -} -rusty_fork_test! { - #[test] - #[timed::timed(tracing = true)] - fn test_tracing_with_both() { - let _ = timed::init_tracing(*timed::TraceOptions::new() - .with_statistics(|x: &StatisticsResult| println!("{:?}", x)) - .with_chrome_trace(|x: &ChromeTraceResult| println!("{}", x.to_string()))).unwrap(); - println!("Running main"); - sleep(); - foo(); - - let _ = timed::finish_tracing().unwrap(); - } + statistics.lock().unwrap().print_statistics(); } - -rusty_fork_test! { - #[test] - #[timed::timed(tracing = true)] - fn test_tracing_with_none() { - let _ = timed::init_tracing(timed::TraceOptions::new()).unwrap(); - - println!("Running main"); - sleep(); - foo(); - - let _ = timed::finish_tracing().unwrap(); - } -} \ No newline at end of file +// } + +// rusty_fork_test! { +// #[test] +// #[timed::timed(tracing = true)] +// fn test_tracing_with_stats() { +// let _ = timed::init_tracing(*timed::TraceCollectorChain::new() +// .with_statistics(|x: &StatisticsResult| println!("{:?}", x))).unwrap(); +// +// println!("Running main"); +// sleep(); +// foo(); +// +// let _ = timed::finish_tracing().unwrap(); +// } +// } +// rusty_fork_test! { +// #[test] +// #[timed::timed(tracing = true)] +// fn test_tracing_with_both() { +// let _ = timed::init_tracing(*timed::TraceCollectorChain::new() +// .with_statistics(|x: &StatisticsResult| println!("{:?}", x)) +// .with_chrome_trace(|x: &ChromeTraceResult| println!("{}", x.to_chrome_trace()))).unwrap(); +// +// println!("Running main"); +// sleep(); +// foo(); +// +// let _ = timed::finish_tracing().unwrap(); +// } +// } +// +// rusty_fork_test! { +// #[test] +// #[timed::timed(tracing = true)] +// fn test_tracing_with_none() { +// let _ = timed::init_tracing(timed::TraceCollectorChain::new()).unwrap(); +// +// println!("Running main"); +// sleep(); +// foo(); +// +// let _ = timed::finish_tracing().unwrap(); +// } +// } \ No newline at end of file diff --git a/timed/Cargo.toml b/timed/Cargo.toml index c3d4ed8..c553095 100644 --- a/timed/Cargo.toml +++ b/timed/Cargo.toml @@ -18,4 +18,5 @@ include = [ #timed_proc_macros = { version = "0.1.1" } timed_proc_macros = { path = "../timed_proc_macros" } lazy_static = "1.4.0" -thiserror = "1.0.21" \ No newline at end of file +thiserror = "1.0.21" +prettytable-rs = "^0.8" \ No newline at end of file diff --git a/timed/src/default_exts.rs b/timed/src/default_exts.rs new file mode 100644 index 0000000..d089448 --- /dev/null +++ b/timed/src/default_exts.rs @@ -0,0 +1,102 @@ +use std::cmp::Ordering; +use std::collections::HashMap; +use std::time::Duration; +use prettytable::{Table, Row, Cell}; +use crate::{Phase, RecordBuffer}; + +#[derive(Clone, Debug)] +struct StatisticsRecord { + name: String, + calls: Vec, + overall_time: Duration, + is_sorted: bool, +} + +impl StatisticsRecord { + fn new(name: String) -> StatisticsRecord { + StatisticsRecord { + name, + calls: vec![], + overall_time: Duration::from_nanos(0), + is_sorted: false, + } + } + + pub fn nth_percentile_time(&mut self, percentile: f32) -> Option<&Duration> { + if !self.is_sorted { + self.calls.sort(); + self.is_sorted = true; + } + + let mut i = (percentile * self.calls.len() as f32).round() as usize; + if i > 0 { + i -= 1; + } + + return self.calls.get(i); + } + + pub fn avg(&self) -> Duration { + Duration::from_nanos(self.calls.iter() + .sum::().as_nanos() as u64 / self.calls.len() as u64) + } +} + +impl Ord for StatisticsRecord { + // This is reversed so that longer time will be above shorter time after sorting. + fn cmp(&self, other: &Self) -> Ordering { + other.overall_time.cmp(&self.overall_time) + } +} + +impl PartialOrd for StatisticsRecord { + fn partial_cmp(&self, other: &Self) -> Option { + Some(self.cmp(other)) + } +} + +impl PartialEq for StatisticsRecord { + fn eq(&self, other: &Self) -> bool { + self.overall_time == other.overall_time + } +} + +impl Eq for StatisticsRecord {} + +pub trait StatisticsExt { + fn print_statistics(&mut self); +} + +impl StatisticsExt for RecordBuffer { + fn print_statistics(&mut self) { + let mut stats = HashMap::new(); + + self.drain() + .iter() + .for_each(|record| { + if let Phase::Finish(d) = record.phase { + let mut entry = stats.entry(record.function_name.clone()) + .or_insert(StatisticsRecord::new(record.function_name.clone())); + entry.calls.push(d); + entry.overall_time += d; + } + }); + + let mut table = Table::new(); + table.add_row(row!["function name", "calls", "overall time", "avg time", "max time", "p90 time", "p50 time", "p10 time"]); + stats.iter_mut().for_each(|(_, sr)| { + table.add_row(row![ + sr.name, + sr.calls.len(), + format!("{:?}", sr.overall_time), + format!("{:?}", sr.avg()), + format!("{:?}", sr.nth_percentile_time(1.0).unwrap()), + format!("{:?}", sr.nth_percentile_time(0.9).unwrap()), + format!("{:?}", sr.nth_percentile_time(0.5).unwrap()), + format!("{:?}", sr.nth_percentile_time(0.1).unwrap()) + ]); + }); + + table.printstd(); + } +} \ No newline at end of file diff --git a/timed/src/interface.rs b/timed/src/interface.rs index b9d094d..5ede956 100644 --- a/timed/src/interface.rs +++ b/timed/src/interface.rs @@ -1,24 +1,36 @@ -use crate::{Trace, ChromeTraceResult, StatisticsResult, ChromeTraceRecord}; -use std::sync::Mutex; +use std::sync::{Arc, Mutex}; -#[derive(Copy, Clone, Default)] -pub struct TraceOptions { - pub statistics: Option, - pub chrome_trace: Option, +use crate::TraceRecord; + +pub struct RecordBuffer { + data: Vec } -impl TraceOptions { - pub fn new() -> TraceOptions { - TraceOptions::default() +impl RecordBuffer { + pub fn new() -> Arc> { + Arc::new(Mutex::new(RecordBuffer { data: vec![] })) } - pub fn with_statistics(&mut self, f: fn(&StatisticsResult)) -> &mut TraceOptions { - self.statistics = Some(f); - self + pub fn add(&mut self, record: TraceRecord) { + self.data.push(record); + } + + pub fn drain(&mut self) -> Vec { + self.data.drain(..).collect() + } +} + +pub struct TraceCollectorChain { + pub buffers: Vec>>, +} + +impl TraceCollectorChain { + pub fn new() -> TraceCollectorChain { + TraceCollectorChain { buffers: vec![] } } - pub fn with_chrome_trace(&mut self, f: fn(&ChromeTraceResult)) -> &mut TraceOptions { - self.chrome_trace = Some(f); + pub fn chain_output(&mut self, buffer: Arc>) -> &mut TraceCollectorChain { + self.buffers.push(buffer); self } } \ No newline at end of file diff --git a/timed/src/lib.rs b/timed/src/lib.rs index 2f10185..9770a0b 100644 --- a/timed/src/lib.rs +++ b/timed/src/lib.rs @@ -45,103 +45,53 @@ //! //! ``` -mod interface; -mod chrome_trace; -mod statistics; - -pub use interface::*; -pub use chrome_trace::*; -pub use statistics::*; -pub use timed_proc_macros::timed; - #[macro_use] extern crate lazy_static; +#[macro_use] +extern crate prettytable; extern crate thiserror; -use crate::Phase::Finish; use std::collections::HashMap; use std::sync::{Arc, Mutex}; + use thiserror::Error; +pub use interface::*; +pub use statistics::*; +pub use timed_proc_macros::timed; +pub use trace::*; + +use crate::Phase::Finish; + +mod interface; +mod trace; +mod statistics; +pub mod default_exts; + #[derive(Error, Debug)] pub enum TimedError { #[error("Tracing can only be initialized once")] TracingInitializationFailed, #[error("Tracing finish failed: {0}")] - TracingFinishFailed(String) + TracingFinishFailed(String), } type Result = std::result::Result; lazy_static! { - static ref TRACE: Arc> = Arc::new(Mutex::new(Trace::empty())); -} - -pub struct Trace { - options: TraceOptions, - trace_data: Vec, - is_initialized: bool, - is_finished: bool, -} - -impl Trace { - pub(crate) fn empty() -> Trace { - Trace { - options: TraceOptions::default(), - trace_data: vec![], - is_initialized: false, - is_finished: false - } - } - pub(crate) fn set_options(&mut self, options: TraceOptions) { - self.options = options; - self.is_initialized = true; - } - - pub fn finish(&mut self) { - self.dump(); - self.is_finished = true; - } - - fn dump(&self) { - if self.options.chrome_trace.is_none() && self.options.statistics.is_none() { - return; - } - - let mut stats_map = HashMap::new(); - let mut chrome_trace_result = ChromeTraceResult::new(); - - self.trace_data.iter().for_each(|chrome_trace_record| { - if self.options.statistics.is_some() { - if let Finish(d) = chrome_trace_record.ph { - stats_map.entry(chrome_trace_record.name.clone()).or_insert(vec![]).push(d); - } - } - - if self.options.chrome_trace.is_some() { - chrome_trace_result.records.push(chrome_trace_record.clone()); - } - }); - - if let Some(chrome_trace_callback) = self.options.chrome_trace.as_ref() { - chrome_trace_callback(&chrome_trace_result); - } - - if let Some(statistics_callback) = self.options.statistics.as_ref() { - statistics_callback(&StatisticsResult::from_raw_map(&stats_map)); - } - } + static ref CHAIN: Arc> = Arc::new(Mutex::new(TraceCollectorChain::new())); } -pub fn collect(chrome_trace_record: ChromeTraceRecord) { - TRACE.lock().unwrap().trace_data.push(chrome_trace_record); +pub fn collect(trace_record: TraceRecord) { + CHAIN.lock().unwrap().buffers.iter_mut().for_each(|collector| + collector.lock().unwrap().add(trace_record.clone())); } -pub fn init_tracing(options: TraceOptions) -> Result<()> { - let mut trace = &mut *TRACE.lock().unwrap(); +pub fn init_tracing(chain: &mut TraceCollectorChain) -> Result<()> { + let mut trace = &mut *CHAIN.lock().unwrap(); - if !trace.is_initialized { - trace.set_options(options); + if trace.buffers.is_empty() { + trace.buffers.append(&mut chain.buffers); return Ok(()); } @@ -149,32 +99,17 @@ pub fn init_tracing(options: TraceOptions) -> Result<()> { return Err(TimedError::TracingInitializationFailed); } -pub fn finish_tracing() -> Result<()> { - let mut trace = &mut *TRACE.lock().unwrap(); - - if trace.is_initialized { - if !trace.is_finished { - trace.finish(); - return Ok(()); - } - - return Err(TimedError::TracingFinishFailed("Tracing finish can only be called once".to_string())); - } - - return Err(TimedError::TracingFinishFailed("Tracing initialization must be called before finish".to_string())); -} - #[macro_export] -macro_rules! init_tracing { - ($options:expr) => { - { - let mut trace = *TRACE.lock().unwrap(); - - if !trace.is_initialized { - trace.set_options($options); +macro_rules! anonymous_collector { + ($closure:expr) => { + Box::new((|| { + struct Anonymous; + impl timed::Collector for Anonymous { + fn collect(&mut self, record: &timed::TraceRecord) { + $closure(record); + } } - - panic!("init_tracing can only be called once"); - } + Anonymous + })()) } } \ No newline at end of file diff --git a/timed/src/chrome_trace.rs b/timed/src/trace.rs similarity index 62% rename from timed/src/chrome_trace.rs rename to timed/src/trace.rs index b93452e..e1e702f 100644 --- a/timed/src/chrome_trace.rs +++ b/timed/src/trace.rs @@ -1,6 +1,6 @@ use std::time::Duration; -#[derive(Clone)] +#[derive(Clone, Debug)] pub enum Phase { Start, Finish(Duration), @@ -16,15 +16,26 @@ impl Phase { } } -#[derive(Clone)] -pub struct ChromeTraceRecord { - pub ts: u128, - pub ph: Phase, - pub name: String, +#[derive(Clone, Debug)] +pub struct TraceRecord { + pub function_name: String, + pub timestamp: u128, + pub phase: Phase, +} + +impl TraceRecord { + pub fn to_chrome_trace(&self) -> String { + format!( + "{{ \"pid\": 0, \"ts\": {}, \"ph\": \"{}\", \"name\": \"{}\" }}", + self.timestamp, + self.phase.to_string(), + self.function_name + ) + } } pub struct ChromeTraceResult { - pub(crate) records: Vec + pub(crate) records: Vec } impl ChromeTraceResult { @@ -34,20 +45,14 @@ impl ChromeTraceResult { } } - pub fn to_string(&self) -> String { + pub fn to_chrome_trace(&self) -> String { let mut chrome_trace_string = "[\n".to_string(); for (i, record) in self.records.iter().enumerate() { let is_last = i == self.records.len() - 1; - let trace = format!( - "{{ \"pid\": 0, \"ts\": {}, \"ph\": \"{}\", \"name\": \"{}\" }}", - record.ts, - record.ph.to_string(), - record.name - ); chrome_trace_string.push_str(&format!( " {}{}\n", - trace, + record.to_chrome_trace(), if !is_last { "," } else { "" } )); } diff --git a/timed_proc_macros/src/lib.rs b/timed_proc_macros/src/lib.rs index 0830a3d..4bd2ba7 100644 --- a/timed_proc_macros/src/lib.rs +++ b/timed_proc_macros/src/lib.rs @@ -7,9 +7,7 @@ use syn::{AttributeArgs, ItemFn}; #[derive(Debug, FromMeta)] struct MacroArgs { #[darling(default)] - printer: Option, - #[darling(default)] - tracing: Option, + tracing: Option } use proc_macro2::TokenStream as Code; @@ -22,7 +20,11 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O .duration_since(std::time::SystemTime::UNIX_EPOCH) .unwrap() .as_micros(); - timed::collect(timed::ChromeTraceRecord { ph: timed::Phase::Start, name: format!("{}::{}", module_path, #function_name), ts}); + timed::collect(timed::TraceRecord { + function_name: format!("{}::{}", module_path, #function_name), + timestamp: ts, + phase: timed::Phase::Start + }); } }; let end = quote! { @@ -31,7 +33,11 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O .duration_since(std::time::SystemTime::UNIX_EPOCH) .unwrap() .as_micros(); - timed::collect(timed::ChromeTraceRecord { ph: timed::Phase::Finish(elapsed), name: format!("{}::{}", module_path, #function_name), ts}); + timed::collect(timed::TraceRecord { + function_name: format!("{}::{}", module_path, #function_name), + timestamp: ts, + phase: timed::Phase::Finish(elapsed) + }); } }; (Some(begin), Some(end)) @@ -40,39 +46,6 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O } } -fn codegen_duration( - printer: &proc_macro2::TokenStream, - function_name: &str, -) -> proc_macro2::TokenStream { - quote! { - #printer("function={} duration={:?}", format!("{}::{}", module_path, #function_name), elapsed); - } -} - -fn codegen_printer(options: &MacroArgs) -> proc_macro2::TokenStream { - let (printer, needs_bang) = match &options.printer { - Some(printer) => { - if printer.ends_with('!') { - (&printer[..&printer.len() - 1], true) - } else { - (printer.as_str(), false) - } - } - None => ("println", true), - }; - - let bang = if needs_bang { - Some(syn::token::Bang(Span::call_site())) - } else { - None - }; - - let printer = syn::Ident::new(printer, Span::call_site()); - quote! { - #printer#bang - } -} - /// Macro that times your function execution. #[proc_macro_attribute] pub fn timed(args: TokenStream, input: TokenStream) -> TokenStream { @@ -106,8 +79,6 @@ pub fn timed(args: TokenStream, input: TokenStream) -> TokenStream { .. } = &function; let name = function.sig.ident.to_string(); - let printer = codegen_printer(&options); - let print_duration = codegen_duration(&printer, name.as_str()); let (tracing_begin, tracing_end) = codegen_tracing(&options, name.as_str()); let result = quote! { @@ -118,7 +89,6 @@ pub fn timed(args: TokenStream, input: TokenStream) -> TokenStream { let start = std::time::Instant::now(); let res = { #body }; let elapsed = start.elapsed(); - #print_duration #tracing_end res } From c07a700da3d1e238ed7dd56afe4293dce6c0b6ec Mon Sep 17 00:00:00 2001 From: yonip23 Date: Fri, 6 Nov 2020 12:44:51 +0200 Subject: [PATCH 09/16] default exts --- tests/src/tests_macro.rs | 2 - tests/src/tests_tracing.rs | 13 +++-- timed/src/default_exts/chrome_trace.rs | 55 ++++++++++++++++++ timed/src/default_exts/mod.rs | 2 + .../statistics.rs} | 7 ++- timed/src/interface.rs | 24 +++++++- timed/src/lib.rs | 4 -- timed/src/statistics.rs | 56 ------------------- timed/src/trace.rs | 40 ------------- 9 files changed, 93 insertions(+), 110 deletions(-) create mode 100644 timed/src/default_exts/chrome_trace.rs create mode 100644 timed/src/default_exts/mod.rs rename timed/src/{default_exts.rs => default_exts/statistics.rs} (95%) delete mode 100644 timed/src/statistics.rs diff --git a/tests/src/tests_macro.rs b/tests/src/tests_macro.rs index 1be2481..9779545 100644 --- a/tests/src/tests_macro.rs +++ b/tests/src/tests_macro.rs @@ -1,5 +1,3 @@ -use timed::{ChromeTraceResult, StatisticsResult}; - fn main() { // let _ = timed::init_tracing(timed::TraceCollectorChain::new() // .chain_output(timed::anonymous_collector!(|x: &timed::TraceRecord| println!("{}", x.to_chrome_trace())))); diff --git a/tests/src/tests_tracing.rs b/tests/src/tests_tracing.rs index b48984d..a2e7080 100644 --- a/tests/src/tests_tracing.rs +++ b/tests/src/tests_tracing.rs @@ -3,9 +3,10 @@ use std::{thread, time}; use rusty_fork::rusty_fork_test; use timed; -use timed::{ChromeTraceResult, StatisticsResult, TraceRecord, RecordBuffer}; +use timed::{TraceRecord, RecordBuffer}; use std::sync::{Arc, Mutex}; -use timed::default_exts::StatisticsExt; +use timed::default_exts::statistics::StatisticsExt; +use timed::default_exts::chrome_trace::ChromeTraceExt; #[allow(dead_code)] fn sleep() { @@ -50,9 +51,11 @@ pub mod foo { #[timed::timed(tracing = true)] fn test_tracing_chrome_tracing() { let mut statistics = RecordBuffer::new(); + let mut chrome_trace = RecordBuffer::new(); let _ = timed::init_tracing(timed::TraceCollectorChain::new() - .chain_output(Arc::clone(&statistics))).unwrap(); + .chain_output(Arc::clone(&statistics)) + .chain_output(Arc::clone(&chrome_trace))).unwrap(); println!("Running main"); sleep(); @@ -60,7 +63,9 @@ fn test_tracing_chrome_tracing() { foo(); } - statistics.lock().unwrap().print_statistics(); + // println!("{:?}", statistics.lock().unwrap().drain()); + statistics.lock().unwrap().get_statistics().printstd(); + println!("{}", chrome_trace.lock().unwrap().get_chrome_trace().to_chrome_trace()); } // } diff --git a/timed/src/default_exts/chrome_trace.rs b/timed/src/default_exts/chrome_trace.rs new file mode 100644 index 0000000..07c0461 --- /dev/null +++ b/timed/src/default_exts/chrome_trace.rs @@ -0,0 +1,55 @@ +use crate::{RecordBuffer, TraceRecord}; + +pub trait ChromeTraceExt { + fn get_chrome_trace(&mut self) -> ChromeTraceResult; +} + +pub trait ChromeTraceRecordExt { + fn to_chrome_trace(&self) -> String; +} + +impl ChromeTraceRecordExt for TraceRecord { + fn to_chrome_trace(&self) -> String { + format!( + "{{ \"pid\": 0, \"ts\": {}, \"ph\": \"{}\", \"name\": \"{}\" }}", + self.timestamp, + self.phase.to_string(), + self.function_name + ) + } +} + +pub struct ChromeTraceResult { + pub(crate) records: Vec +} + +impl ChromeTraceResult { + pub(crate) fn new(data: &Vec) -> ChromeTraceResult { + ChromeTraceResult { + records: data.clone() + } + } + + pub fn to_chrome_trace(&self) -> String { + let mut chrome_trace_string = "[\n".to_string(); + + for (i, record) in self.records.iter().enumerate() { + let is_last = i == self.records.len() - 1; + chrome_trace_string.push_str(&format!( + " {}{}\n", + record.to_chrome_trace(), + if !is_last { "," } else { "" } + )); + } + + chrome_trace_string.push_str("]"); + + return chrome_trace_string; + } +} + +impl ChromeTraceExt for RecordBuffer { + fn get_chrome_trace(&mut self) -> ChromeTraceResult { + ChromeTraceResult::new(&self.drain()) + } +} \ No newline at end of file diff --git a/timed/src/default_exts/mod.rs b/timed/src/default_exts/mod.rs new file mode 100644 index 0000000..407a762 --- /dev/null +++ b/timed/src/default_exts/mod.rs @@ -0,0 +1,2 @@ +pub mod statistics; +pub mod chrome_trace; \ No newline at end of file diff --git a/timed/src/default_exts.rs b/timed/src/default_exts/statistics.rs similarity index 95% rename from timed/src/default_exts.rs rename to timed/src/default_exts/statistics.rs index d089448..e270054 100644 --- a/timed/src/default_exts.rs +++ b/timed/src/default_exts/statistics.rs @@ -3,6 +3,7 @@ use std::collections::HashMap; use std::time::Duration; use prettytable::{Table, Row, Cell}; use crate::{Phase, RecordBuffer}; +use std::fs::File; #[derive(Clone, Debug)] struct StatisticsRecord { @@ -64,11 +65,11 @@ impl PartialEq for StatisticsRecord { impl Eq for StatisticsRecord {} pub trait StatisticsExt { - fn print_statistics(&mut self); + fn get_statistics(&mut self) -> Table; } impl StatisticsExt for RecordBuffer { - fn print_statistics(&mut self) { + fn get_statistics(&mut self) -> Table { let mut stats = HashMap::new(); self.drain() @@ -97,6 +98,6 @@ impl StatisticsExt for RecordBuffer { ]); }); - table.printstd(); + return table; } } \ No newline at end of file diff --git a/timed/src/interface.rs b/timed/src/interface.rs index 5ede956..ffa39b0 100644 --- a/timed/src/interface.rs +++ b/timed/src/interface.rs @@ -1,6 +1,28 @@ use std::sync::{Arc, Mutex}; +use std::time::Duration; -use crate::TraceRecord; +#[derive(Clone, Debug)] +pub enum Phase { + Start, + Finish(Duration), +} + +impl Phase { + // These are B and E for chrome tracing + pub(crate) fn to_string(&self) -> String { + match self { + Phase::Start => "B".to_string(), + Phase::Finish(_) => "E".to_string(), + } + } +} + +#[derive(Clone, Debug)] +pub struct TraceRecord { + pub function_name: String, + pub timestamp: u128, + pub phase: Phase, +} pub struct RecordBuffer { data: Vec diff --git a/timed/src/lib.rs b/timed/src/lib.rs index 9770a0b..bcea076 100644 --- a/timed/src/lib.rs +++ b/timed/src/lib.rs @@ -57,15 +57,11 @@ use std::sync::{Arc, Mutex}; use thiserror::Error; pub use interface::*; -pub use statistics::*; pub use timed_proc_macros::timed; -pub use trace::*; use crate::Phase::Finish; mod interface; -mod trace; -mod statistics; pub mod default_exts; #[derive(Error, Debug)] diff --git a/timed/src/statistics.rs b/timed/src/statistics.rs deleted file mode 100644 index 757dafd..0000000 --- a/timed/src/statistics.rs +++ /dev/null @@ -1,56 +0,0 @@ -use std::cmp::Ordering; -use std::time::Duration; -use std::collections::HashMap; - -#[derive(Clone, Debug)] -pub struct StatisticsRecord { - pub(crate) name: String, - pub(crate) calls: usize, - pub(crate) overall_time: Duration -} - -impl Ord for StatisticsRecord { - // This is reversed so that longer time will be above shorter time after sorting. - fn cmp(&self, other: &Self) -> Ordering { - other.overall_time.cmp(&self.overall_time) - } -} - -impl PartialOrd for StatisticsRecord { - fn partial_cmp(&self, other: &Self) -> Option { - Some(self.cmp(other)) - } -} - -impl PartialEq for StatisticsRecord { - fn eq(&self, other: &Self) -> bool { - self.overall_time == other.overall_time - } -} - -impl Eq for StatisticsRecord {} - -#[derive(Debug)] -pub struct StatisticsResult { - records: Vec -} - -impl StatisticsResult { - pub(crate) fn from_raw_map(stats_map: &HashMap>) -> StatisticsResult { - let mut fn_stats = vec![]; - stats_map.iter().for_each(|(k, v)| { - let current_total = v.iter().map(|d| d.as_nanos()).sum::() as u64; - fn_stats.push(StatisticsRecord { - name: k.to_string(), - calls: v.len(), - overall_time: Duration::from_nanos(current_total), - }); - }); - - fn_stats.sort(); - - return StatisticsResult { - records: fn_stats - } - } -} \ No newline at end of file diff --git a/timed/src/trace.rs b/timed/src/trace.rs index e1e702f..bcd616c 100644 --- a/timed/src/trace.rs +++ b/timed/src/trace.rs @@ -21,44 +21,4 @@ pub struct TraceRecord { pub function_name: String, pub timestamp: u128, pub phase: Phase, -} - -impl TraceRecord { - pub fn to_chrome_trace(&self) -> String { - format!( - "{{ \"pid\": 0, \"ts\": {}, \"ph\": \"{}\", \"name\": \"{}\" }}", - self.timestamp, - self.phase.to_string(), - self.function_name - ) - } -} - -pub struct ChromeTraceResult { - pub(crate) records: Vec -} - -impl ChromeTraceResult { - pub(crate) fn new() -> ChromeTraceResult { - ChromeTraceResult { - records: vec![] - } - } - - pub fn to_chrome_trace(&self) -> String { - let mut chrome_trace_string = "[\n".to_string(); - - for (i, record) in self.records.iter().enumerate() { - let is_last = i == self.records.len() - 1; - chrome_trace_string.push_str(&format!( - " {}{}\n", - record.to_chrome_trace(), - if !is_last { "," } else { "" } - )); - } - - chrome_trace_string.push_str("]"); - - return chrome_trace_string; - } } \ No newline at end of file From e635f72df7bba9aa86d2e99331ddfdfbaf789674 Mon Sep 17 00:00:00 2001 From: yonip23 Date: Wed, 11 Nov 2020 18:35:49 +0200 Subject: [PATCH 10/16] i dont know what im doing... --- tests/Cargo.toml | 9 --- tests/src/lib.rs | 1 - tests/src/tests_tracing.rs | 113 +++++++-------------------- timed/src/default_exts/statistics.rs | 5 +- timed/src/lib.rs | 5 +- timed_proc_macros/src/lib.rs | 1 - 6 files changed, 31 insertions(+), 103 deletions(-) diff --git a/tests/Cargo.toml b/tests/Cargo.toml index 8b43f42..e341fb6 100644 --- a/tests/Cargo.toml +++ b/tests/Cargo.toml @@ -18,12 +18,3 @@ lazy_static = "1.4.0" [dev-dependencies] rusty-fork = "0.3.0" - -[[bin]] -name = "tests_macro" -path = "src/tests_macro.rs" - - -[[bin]] -name = "tests_expand" -path = "src/tests_expand.rs" \ No newline at end of file diff --git a/tests/src/lib.rs b/tests/src/lib.rs index 5a4725f..287af1c 100644 --- a/tests/src/lib.rs +++ b/tests/src/lib.rs @@ -1,6 +1,5 @@ mod tests_macro; -#[macro_use] extern crate log; mod tests_duration; diff --git a/tests/src/tests_tracing.rs b/tests/src/tests_tracing.rs index a2e7080..f9353e1 100644 --- a/tests/src/tests_tracing.rs +++ b/tests/src/tests_tracing.rs @@ -3,8 +3,8 @@ use std::{thread, time}; use rusty_fork::rusty_fork_test; use timed; -use timed::{TraceRecord, RecordBuffer}; -use std::sync::{Arc, Mutex}; +use timed::RecordBuffer; +use std::sync::Arc; use timed::default_exts::statistics::StatisticsExt; use timed::default_exts::chrome_trace::ChromeTraceExt; @@ -14,101 +14,44 @@ fn sleep() { } #[timed::timed(tracing = true)] -fn foo() { - bar(); +fn outer_sleep() { sleep(); - baz(); + inner_sleep(); } #[timed::timed(tracing = true)] -fn bar() { - sleep(); - baz(); +fn inner_sleep() { sleep(); } -#[timed::timed(tracing = true)] -fn baz() { - sleep(); - foo::bar::baz::foobar(); -} +rusty_fork_test! { + #[test] + #[timed::timed(tracing = true)] + fn test_tracing_statistics() { + let mut statistics = RecordBuffer::new(); + + let _ = timed::init_tracing(timed::TraceCollectorChain::new() + .chain_output(Arc::clone(&statistics))).unwrap(); -pub mod foo { - pub mod bar { - pub mod baz { - use timed::timed; + println!("Running main"); + outer_sleep(); - #[timed(tracing = true)] - pub fn foobar() { - println!("Foobar"); - } - } + statistics.lock().unwrap().get_statistics().printstd(); } } -// rusty_fork_test! { -#[test] -#[timed::timed(tracing = true)] -fn test_tracing_chrome_tracing() { - let mut statistics = RecordBuffer::new(); - let mut chrome_trace = RecordBuffer::new(); +rusty_fork_test! { + #[test] + #[timed::timed(tracing = true)] + fn test_tracing_chrome_trace() { + let mut chrome_trace = RecordBuffer::new(); - let _ = timed::init_tracing(timed::TraceCollectorChain::new() - .chain_output(Arc::clone(&statistics)) - .chain_output(Arc::clone(&chrome_trace))).unwrap(); + let _ = timed::init_tracing(timed::TraceCollectorChain::new() + .chain_output(Arc::clone(&chrome_trace))).unwrap(); - println!("Running main"); - sleep(); - for i in 0..5 { - foo(); - } + println!("Running main"); + outer_sleep(); - // println!("{:?}", statistics.lock().unwrap().drain()); - statistics.lock().unwrap().get_statistics().printstd(); - println!("{}", chrome_trace.lock().unwrap().get_chrome_trace().to_chrome_trace()); -} -// } - -// rusty_fork_test! { -// #[test] -// #[timed::timed(tracing = true)] -// fn test_tracing_with_stats() { -// let _ = timed::init_tracing(*timed::TraceCollectorChain::new() -// .with_statistics(|x: &StatisticsResult| println!("{:?}", x))).unwrap(); -// -// println!("Running main"); -// sleep(); -// foo(); -// -// let _ = timed::finish_tracing().unwrap(); -// } -// } -// rusty_fork_test! { -// #[test] -// #[timed::timed(tracing = true)] -// fn test_tracing_with_both() { -// let _ = timed::init_tracing(*timed::TraceCollectorChain::new() -// .with_statistics(|x: &StatisticsResult| println!("{:?}", x)) -// .with_chrome_trace(|x: &ChromeTraceResult| println!("{}", x.to_chrome_trace()))).unwrap(); -// -// println!("Running main"); -// sleep(); -// foo(); -// -// let _ = timed::finish_tracing().unwrap(); -// } -// } -// -// rusty_fork_test! { -// #[test] -// #[timed::timed(tracing = true)] -// fn test_tracing_with_none() { -// let _ = timed::init_tracing(timed::TraceCollectorChain::new()).unwrap(); -// -// println!("Running main"); -// sleep(); -// foo(); -// -// let _ = timed::finish_tracing().unwrap(); -// } -// } \ No newline at end of file + println!("{}", chrome_trace.lock().unwrap().get_chrome_trace().to_chrome_trace()); + } +} \ No newline at end of file diff --git a/timed/src/default_exts/statistics.rs b/timed/src/default_exts/statistics.rs index e270054..cf28bed 100644 --- a/timed/src/default_exts/statistics.rs +++ b/timed/src/default_exts/statistics.rs @@ -1,9 +1,8 @@ use std::cmp::Ordering; use std::collections::HashMap; use std::time::Duration; -use prettytable::{Table, Row, Cell}; +use prettytable::Table; use crate::{Phase, RecordBuffer}; -use std::fs::File; #[derive(Clone, Debug)] struct StatisticsRecord { @@ -76,7 +75,7 @@ impl StatisticsExt for RecordBuffer { .iter() .for_each(|record| { if let Phase::Finish(d) = record.phase { - let mut entry = stats.entry(record.function_name.clone()) + let entry = stats.entry(record.function_name.clone()) .or_insert(StatisticsRecord::new(record.function_name.clone())); entry.calls.push(d); entry.overall_time += d; diff --git a/timed/src/lib.rs b/timed/src/lib.rs index bcea076..3925da3 100644 --- a/timed/src/lib.rs +++ b/timed/src/lib.rs @@ -51,7 +51,6 @@ extern crate lazy_static; extern crate prettytable; extern crate thiserror; -use std::collections::HashMap; use std::sync::{Arc, Mutex}; use thiserror::Error; @@ -59,8 +58,6 @@ use thiserror::Error; pub use interface::*; pub use timed_proc_macros::timed; -use crate::Phase::Finish; - mod interface; pub mod default_exts; @@ -84,7 +81,7 @@ pub fn collect(trace_record: TraceRecord) { } pub fn init_tracing(chain: &mut TraceCollectorChain) -> Result<()> { - let mut trace = &mut *CHAIN.lock().unwrap(); + let trace = &mut *CHAIN.lock().unwrap(); if trace.buffers.is_empty() { trace.buffers.append(&mut chain.buffers); diff --git a/timed_proc_macros/src/lib.rs b/timed_proc_macros/src/lib.rs index 4bd2ba7..7da2cdf 100644 --- a/timed_proc_macros/src/lib.rs +++ b/timed_proc_macros/src/lib.rs @@ -1,6 +1,5 @@ use darling::FromMeta; use proc_macro::TokenStream; -use proc_macro2::Span; use quote::quote; use syn::{AttributeArgs, ItemFn}; From e32fc9d3e303dddd0677b8564da2e6a228434e69 Mon Sep 17 00:00:00 2001 From: Marius Ciubotariu Date: Mon, 7 Dec 2020 00:37:08 +0000 Subject: [PATCH 11/16] wip --- Cargo.toml | 4 +- tests/Cargo.toml | 3 +- tests/Makefile.toml | 28 +++++- tests/examples/demo_duration.rs | 3 +- tests/examples/demo_main.rs | 6 ++ tests/examples/demo_main_info.rs | 8 ++ tests/examples/demo_main_nested.rs | 12 +++ tests/examples/demo_statistics.rs | 42 +++++++++ tests/examples/demo_tracing.rs | 31 ++++--- tests/src/lib.rs | 4 +- tests/src/tests_expand.rs | 13 ++- tests/src/tests_macro.rs | 4 - tests/src/tests_tracing.rs | 69 ++++++++------- timed/src/chrome_trace.rs | 12 +++ timed/src/default_exts/chrome_trace.rs | 55 ------------ timed/src/default_exts/mod.rs | 2 - timed/src/default_exts/statistics.rs | 102 ---------------------- timed/src/error.rs | 7 ++ timed/src/hop.rs | 35 ++++++++ timed/src/interface.rs | 58 ------------- timed/src/lib.rs | 69 ++++----------- timed/src/statistics.rs | 116 +++++++++++++++++++++++++ timed/src/trace.rs | 57 ++++++++---- timed_proc_macros/Makefile.toml | 22 ----- timed_proc_macros/src/lib.rs | 77 +++++++++++++--- 25 files changed, 454 insertions(+), 385 deletions(-) create mode 100644 tests/examples/demo_main.rs create mode 100644 tests/examples/demo_main_info.rs create mode 100644 tests/examples/demo_main_nested.rs create mode 100644 tests/examples/demo_statistics.rs delete mode 100644 tests/src/tests_macro.rs create mode 100644 timed/src/chrome_trace.rs delete mode 100644 timed/src/default_exts/chrome_trace.rs delete mode 100644 timed/src/default_exts/mod.rs delete mode 100644 timed/src/default_exts/statistics.rs create mode 100644 timed/src/error.rs create mode 100644 timed/src/hop.rs delete mode 100644 timed/src/interface.rs create mode 100644 timed/src/statistics.rs delete mode 100644 timed_proc_macros/Makefile.toml diff --git a/Cargo.toml b/Cargo.toml index b4dcf41..6c60dda 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,7 +1,7 @@ [workspace] members = [ + "tests", "timed", - "timed_proc_macros", - "tests" + "timed_proc_macros" ] \ No newline at end of file diff --git a/tests/Cargo.toml b/tests/Cargo.toml index e341fb6..acffc76 100644 --- a/tests/Cargo.toml +++ b/tests/Cargo.toml @@ -15,6 +15,5 @@ log = "0.4" pretty_env_logger = "0.4" serde_json = "1.0.58" lazy_static = "1.4.0" - -[dev-dependencies] rusty-fork = "0.3.0" + diff --git a/tests/Makefile.toml b/tests/Makefile.toml index 0720c89..a5d5fb6 100644 --- a/tests/Makefile.toml +++ b/tests/Makefile.toml @@ -2,9 +2,33 @@ command = "cargo" args = ["build"] -[tasks.run_macros] +[tasks.example_async] command = "cargo" -args = ["run", "--bin", "tests_macro"] +args = ["run", "--example", "demo_async"] + +[tasks.example_duration] +command = "cargo" +args = ["run", "--example", "demo_duration"] + +[tasks.example_main] +command = "cargo" +args = ["run", "--example", "demo_main"] + +[tasks.example_main_info] +command = "cargo" +args = ["run", "--example", "demo_main_info"] + +[tasks.example_main_nested] +command = "cargo" +args = ["run", "--example", "demo_main_nested"] + +[tasks.example_tracing] +command = "cargo" +args = ["run", "--example", "demo_tracing"] + +[tasks.example_statistics] +command = "cargo" +args = ["run", "--example", "demo_statistics"] [tasks.run_expand] command = "cargo" diff --git a/tests/examples/demo_duration.rs b/tests/examples/demo_duration.rs index e4132f4..22428c3 100644 --- a/tests/examples/demo_duration.rs +++ b/tests/examples/demo_duration.rs @@ -22,8 +22,7 @@ fn mul_info(x: i32, y: i32) -> i32 { x * y } -#[test] -fn timing() { +fn main() { pretty_env_logger::init(); assert_eq!(add(1, 2), 3); diff --git a/tests/examples/demo_main.rs b/tests/examples/demo_main.rs new file mode 100644 index 0000000..d479d57 --- /dev/null +++ b/tests/examples/demo_main.rs @@ -0,0 +1,6 @@ +use timed::timed; + +#[timed] +fn main() { + println!("Running main"); +} diff --git a/tests/examples/demo_main_info.rs b/tests/examples/demo_main_info.rs new file mode 100644 index 0000000..ad349e3 --- /dev/null +++ b/tests/examples/demo_main_info.rs @@ -0,0 +1,8 @@ +use log::info; +use timed::timed; + +#[timed(printer = "info!")] +fn main() { + pretty_env_logger::init(); + println!("Running main"); +} diff --git a/tests/examples/demo_main_nested.rs b/tests/examples/demo_main_nested.rs new file mode 100644 index 0000000..0113d04 --- /dev/null +++ b/tests/examples/demo_main_nested.rs @@ -0,0 +1,12 @@ +use timed::timed; + +#[timed] +fn foo() { + println!("foo"); +} + +#[timed] +fn main() { + println!("Running main"); + foo(); +} diff --git a/tests/examples/demo_statistics.rs b/tests/examples/demo_statistics.rs new file mode 100644 index 0000000..591d755 --- /dev/null +++ b/tests/examples/demo_statistics.rs @@ -0,0 +1,42 @@ +mod one { + pub(crate) mod two { + pub(crate) mod three { + #[timed::timed(tracing(enabled = true))] + pub(crate) fn deep() { + println!("Deep"); + } + } + } +} + +#[timed::timed(tracing(enabled = true))] +fn foo() { + bar(); + baz(); +} + +#[timed::timed(tracing(enabled = true))] +fn baz() { + println!("Hello"); + for _ in 0..3 { + one::two::three::deep(); + } +} + +#[timed::timed(tracing(enabled = true))] +fn bar() { + for _ in 0..10 { + baz(); + } +} + +#[timed::timed(tracing(enabled = true))] +fn main() { + + let trace = timed::Trace::new("Main"); + + foo(); + + println!("{}", trace.statistics()); + +} diff --git a/tests/examples/demo_tracing.rs b/tests/examples/demo_tracing.rs index d2a9136..1512781 100644 --- a/tests/examples/demo_tracing.rs +++ b/tests/examples/demo_tracing.rs @@ -1,27 +1,38 @@ -#[timed::timed(tracing = true)] +mod one { + pub(crate) mod two { + pub(crate) mod three { + #[timed::timed(tracing(enabled = true))] + pub(crate) fn deep() { + println!("Deep"); + } + } + } +} + +#[timed::timed(tracing(enabled = true))] fn foo() { bar(); baz(); } -#[timed::timed(tracing = true)] +#[timed::timed(tracing(enabled = true))] fn baz() { - println!("Hello") + println!("Hello"); + one::two::three::deep(); } -#[timed::timed(tracing = true)] +#[timed::timed(tracing(enabled = true))] fn bar() { baz(); } -#[timed::timed(tracing = true)] +#[timed::timed(tracing(enabled = true))] fn main() { - let trace = timed::TraceCollectorChain::new() - .with_chrome_trace(|x: &str| println!("{}", x)) - .with_statistics(|x: &str| println!("{}", x)) - .build_named("Main"); + + let trace = timed::Trace::new("Main"); foo(); - trace.finish(); + println!("{}", trace.chrome_tracing()); + } diff --git a/tests/src/lib.rs b/tests/src/lib.rs index 287af1c..40ffe90 100644 --- a/tests/src/lib.rs +++ b/tests/src/lib.rs @@ -1,7 +1,7 @@ -mod tests_macro; - extern crate log; mod tests_duration; mod tests_tracing; +mod tests_expand; + pub mod tests_utils; diff --git a/tests/src/tests_expand.rs b/tests/src/tests_expand.rs index 07e7dc5..b9b20ab 100644 --- a/tests/src/tests_expand.rs +++ b/tests/src/tests_expand.rs @@ -1,28 +1,25 @@ -#[timed::timed(tracing = true)] +#[timed::timed(tracing(enabled = true))] fn foo() { std::thread::sleep(std::time::Duration::from_micros(1000)); bar(); baz(); } -#[timed::timed(tracing = true)] +#[timed::timed(tracing(enabled = true))] fn baz() { std::thread::sleep(std::time::Duration::from_micros(1000)); } -#[timed::timed(tracing = true)] +#[timed::timed(tracing(enabled = true))] fn bar() { baz(); std::thread::sleep(std::time::Duration::from_micros(1000)); } -#[timed::timed(tracing = true)] +#[timed::timed(tracing(enabled = true))] fn main() { - let trace = timed::TraceCollectorChain::new() - .with_chrome_trace(|x: &str| println!("{}", x)) - .build_named("Tests"); + let trace = timed::Trace::new("Main"); foo(); - trace.finish(); } diff --git a/tests/src/tests_macro.rs b/tests/src/tests_macro.rs deleted file mode 100644 index 9779545..0000000 --- a/tests/src/tests_macro.rs +++ /dev/null @@ -1,4 +0,0 @@ -fn main() { - // let _ = timed::init_tracing(timed::TraceCollectorChain::new() - // .chain_output(timed::anonymous_collector!(|x: &timed::TraceRecord| println!("{}", x.to_chrome_trace())))); -} diff --git a/tests/src/tests_tracing.rs b/tests/src/tests_tracing.rs index f9353e1..4e1664c 100644 --- a/tests/src/tests_tracing.rs +++ b/tests/src/tests_tracing.rs @@ -1,57 +1,62 @@ use std::{thread, time}; +#[macro_use] use rusty_fork::rusty_fork_test; -use timed; -use timed::RecordBuffer; use std::sync::Arc; -use timed::default_exts::statistics::StatisticsExt; -use timed::default_exts::chrome_trace::ChromeTraceExt; +use timed; #[allow(dead_code)] fn sleep() { thread::sleep(time::Duration::from_millis(10)); } -#[timed::timed(tracing = true)] +#[timed::timed(tracing(enabled = true))] fn outer_sleep() { sleep(); inner_sleep(); } -#[timed::timed(tracing = true)] +#[timed::timed(tracing(enabled = true))] fn inner_sleep() { sleep(); } -rusty_fork_test! { - #[test] - #[timed::timed(tracing = true)] - fn test_tracing_statistics() { - let mut statistics = RecordBuffer::new(); +#[test] +#[timed::timed(tracing(enabled = true))] +fn test_tracing_statistics() { + let mut statistics = RecordBuffer::new(); - let _ = timed::init_tracing(timed::TraceCollectorChain::new() - .chain_output(Arc::clone(&statistics))).unwrap(); + let _ = timed::init_tracing( + timed::TraceCollectorChain::new().chain_output(Arc::clone(&statistics)), + ) + .unwrap(); - println!("Running main"); - outer_sleep(); + println!("Running main"); + outer_sleep(); - statistics.lock().unwrap().get_statistics().printstd(); - } + statistics.lock().unwrap().get_statistics().printstd(); } -rusty_fork_test! { - #[test] - #[timed::timed(tracing = true)] - fn test_tracing_chrome_trace() { - let mut chrome_trace = RecordBuffer::new(); - - let _ = timed::init_tracing(timed::TraceCollectorChain::new() - .chain_output(Arc::clone(&chrome_trace))).unwrap(); - - println!("Running main"); - outer_sleep(); - - println!("{}", chrome_trace.lock().unwrap().get_chrome_trace().to_chrome_trace()); - } -} \ No newline at end of file +#[test] +#[timed::timed(tracing(enabled = true))] +fn test_tracing_chrome_trace() { + let mut chrome_trace = RecordBuffer::new(); + + let _ = timed::init_tracing( + timed::TraceCollectorChain::new().chain_output(Arc::clone(&chrome_trace)), + ) + .unwrap(); + + println!("Running main"); + outer_sleep(); + + println!( + "{}", + chrome_trace + .lock() + .unwrap() + .get_chrome_trace() + .to_chrome_trace() + ); +} diff --git a/timed/src/chrome_trace.rs b/timed/src/chrome_trace.rs new file mode 100644 index 0000000..7e0fad7 --- /dev/null +++ b/timed/src/chrome_trace.rs @@ -0,0 +1,12 @@ +use crate::hop::Hop; + +pub fn from(hops: &[Hop]) -> String { + + let result = hops + .iter() + .map(|hop| format!("\t{}", hop.to_chrome_trace())) + .collect::>() + .join(",\n"); + + format!("[\n{}\n]", result) +} \ No newline at end of file diff --git a/timed/src/default_exts/chrome_trace.rs b/timed/src/default_exts/chrome_trace.rs deleted file mode 100644 index 07c0461..0000000 --- a/timed/src/default_exts/chrome_trace.rs +++ /dev/null @@ -1,55 +0,0 @@ -use crate::{RecordBuffer, TraceRecord}; - -pub trait ChromeTraceExt { - fn get_chrome_trace(&mut self) -> ChromeTraceResult; -} - -pub trait ChromeTraceRecordExt { - fn to_chrome_trace(&self) -> String; -} - -impl ChromeTraceRecordExt for TraceRecord { - fn to_chrome_trace(&self) -> String { - format!( - "{{ \"pid\": 0, \"ts\": {}, \"ph\": \"{}\", \"name\": \"{}\" }}", - self.timestamp, - self.phase.to_string(), - self.function_name - ) - } -} - -pub struct ChromeTraceResult { - pub(crate) records: Vec -} - -impl ChromeTraceResult { - pub(crate) fn new(data: &Vec) -> ChromeTraceResult { - ChromeTraceResult { - records: data.clone() - } - } - - pub fn to_chrome_trace(&self) -> String { - let mut chrome_trace_string = "[\n".to_string(); - - for (i, record) in self.records.iter().enumerate() { - let is_last = i == self.records.len() - 1; - chrome_trace_string.push_str(&format!( - " {}{}\n", - record.to_chrome_trace(), - if !is_last { "," } else { "" } - )); - } - - chrome_trace_string.push_str("]"); - - return chrome_trace_string; - } -} - -impl ChromeTraceExt for RecordBuffer { - fn get_chrome_trace(&mut self) -> ChromeTraceResult { - ChromeTraceResult::new(&self.drain()) - } -} \ No newline at end of file diff --git a/timed/src/default_exts/mod.rs b/timed/src/default_exts/mod.rs deleted file mode 100644 index 407a762..0000000 --- a/timed/src/default_exts/mod.rs +++ /dev/null @@ -1,2 +0,0 @@ -pub mod statistics; -pub mod chrome_trace; \ No newline at end of file diff --git a/timed/src/default_exts/statistics.rs b/timed/src/default_exts/statistics.rs deleted file mode 100644 index cf28bed..0000000 --- a/timed/src/default_exts/statistics.rs +++ /dev/null @@ -1,102 +0,0 @@ -use std::cmp::Ordering; -use std::collections::HashMap; -use std::time::Duration; -use prettytable::Table; -use crate::{Phase, RecordBuffer}; - -#[derive(Clone, Debug)] -struct StatisticsRecord { - name: String, - calls: Vec, - overall_time: Duration, - is_sorted: bool, -} - -impl StatisticsRecord { - fn new(name: String) -> StatisticsRecord { - StatisticsRecord { - name, - calls: vec![], - overall_time: Duration::from_nanos(0), - is_sorted: false, - } - } - - pub fn nth_percentile_time(&mut self, percentile: f32) -> Option<&Duration> { - if !self.is_sorted { - self.calls.sort(); - self.is_sorted = true; - } - - let mut i = (percentile * self.calls.len() as f32).round() as usize; - if i > 0 { - i -= 1; - } - - return self.calls.get(i); - } - - pub fn avg(&self) -> Duration { - Duration::from_nanos(self.calls.iter() - .sum::().as_nanos() as u64 / self.calls.len() as u64) - } -} - -impl Ord for StatisticsRecord { - // This is reversed so that longer time will be above shorter time after sorting. - fn cmp(&self, other: &Self) -> Ordering { - other.overall_time.cmp(&self.overall_time) - } -} - -impl PartialOrd for StatisticsRecord { - fn partial_cmp(&self, other: &Self) -> Option { - Some(self.cmp(other)) - } -} - -impl PartialEq for StatisticsRecord { - fn eq(&self, other: &Self) -> bool { - self.overall_time == other.overall_time - } -} - -impl Eq for StatisticsRecord {} - -pub trait StatisticsExt { - fn get_statistics(&mut self) -> Table; -} - -impl StatisticsExt for RecordBuffer { - fn get_statistics(&mut self) -> Table { - let mut stats = HashMap::new(); - - self.drain() - .iter() - .for_each(|record| { - if let Phase::Finish(d) = record.phase { - let entry = stats.entry(record.function_name.clone()) - .or_insert(StatisticsRecord::new(record.function_name.clone())); - entry.calls.push(d); - entry.overall_time += d; - } - }); - - let mut table = Table::new(); - table.add_row(row!["function name", "calls", "overall time", "avg time", "max time", "p90 time", "p50 time", "p10 time"]); - stats.iter_mut().for_each(|(_, sr)| { - table.add_row(row![ - sr.name, - sr.calls.len(), - format!("{:?}", sr.overall_time), - format!("{:?}", sr.avg()), - format!("{:?}", sr.nth_percentile_time(1.0).unwrap()), - format!("{:?}", sr.nth_percentile_time(0.9).unwrap()), - format!("{:?}", sr.nth_percentile_time(0.5).unwrap()), - format!("{:?}", sr.nth_percentile_time(0.1).unwrap()) - ]); - }); - - return table; - } -} \ No newline at end of file diff --git a/timed/src/error.rs b/timed/src/error.rs new file mode 100644 index 0000000..0833628 --- /dev/null +++ b/timed/src/error.rs @@ -0,0 +1,7 @@ +#[derive(Error, Debug)] +pub enum TimedError { + #[error("Tracing can only be initialized once")] + TracingInitializationFailed, + #[error("Tracing finish failed: {0}")] + TracingFinishFailed(String), +} diff --git a/timed/src/hop.rs b/timed/src/hop.rs new file mode 100644 index 0000000..b6c8777 --- /dev/null +++ b/timed/src/hop.rs @@ -0,0 +1,35 @@ +use std::time::Duration; + +#[derive(Clone, Debug)] +pub enum Phase { + Start, + Finish(Duration), +} + +impl Phase { + // These are B and E for chrome tracing + pub(crate) fn to_string(&self) -> String { + match self { + Phase::Start => "B".to_string(), + Phase::Finish(_) => "E".to_string(), + } + } +} + +#[derive(Clone, Debug)] +pub struct Hop { + pub function_name: String, + pub timestamp: u128, + pub phase: Phase, +} + +impl Hop { + pub fn to_chrome_trace(&self) -> String { + format!( + "{{ \"pid\": 0, \"ts\": {}, \"ph\": \"{}\", \"name\": \"{}\" }}", + self.timestamp, + self.phase.to_string(), + self.function_name + ) + } +} \ No newline at end of file diff --git a/timed/src/interface.rs b/timed/src/interface.rs deleted file mode 100644 index ffa39b0..0000000 --- a/timed/src/interface.rs +++ /dev/null @@ -1,58 +0,0 @@ -use std::sync::{Arc, Mutex}; -use std::time::Duration; - -#[derive(Clone, Debug)] -pub enum Phase { - Start, - Finish(Duration), -} - -impl Phase { - // These are B and E for chrome tracing - pub(crate) fn to_string(&self) -> String { - match self { - Phase::Start => "B".to_string(), - Phase::Finish(_) => "E".to_string(), - } - } -} - -#[derive(Clone, Debug)] -pub struct TraceRecord { - pub function_name: String, - pub timestamp: u128, - pub phase: Phase, -} - -pub struct RecordBuffer { - data: Vec -} - -impl RecordBuffer { - pub fn new() -> Arc> { - Arc::new(Mutex::new(RecordBuffer { data: vec![] })) - } - - pub fn add(&mut self, record: TraceRecord) { - self.data.push(record); - } - - pub fn drain(&mut self) -> Vec { - self.data.drain(..).collect() - } -} - -pub struct TraceCollectorChain { - pub buffers: Vec>>, -} - -impl TraceCollectorChain { - pub fn new() -> TraceCollectorChain { - TraceCollectorChain { buffers: vec![] } - } - - pub fn chain_output(&mut self, buffer: Arc>) -> &mut TraceCollectorChain { - self.buffers.push(buffer); - self - } -} \ No newline at end of file diff --git a/timed/src/lib.rs b/timed/src/lib.rs index 3925da3..496dd4e 100644 --- a/timed/src/lib.rs +++ b/timed/src/lib.rs @@ -45,64 +45,27 @@ //! //! ``` -#[macro_use] -extern crate lazy_static; -#[macro_use] -extern crate prettytable; -extern crate thiserror; - use std::sync::{Arc, Mutex}; +use std::collections::HashMap; -use thiserror::Error; - -pub use interface::*; -pub use timed_proc_macros::timed; +#[macro_use] extern crate lazy_static; +#[macro_use] extern crate prettytable; +#[macro_use] extern crate thiserror; -mod interface; -pub mod default_exts; +mod chrome_trace; +mod error; +mod hop; +mod trace; +mod statistics; -#[derive(Error, Debug)] -pub enum TimedError { - #[error("Tracing can only be initialized once")] - TracingInitializationFailed, - #[error("Tracing finish failed: {0}")] - TracingFinishFailed(String), -} +// export Trace +pub use trace::Trace; +pub use hop::{Phase, Hop}; -type Result = std::result::Result; +// Re-exporting the timed proc macro +pub use timed_proc_macros::timed; +// Keeping track of traces lazy_static! { - static ref CHAIN: Arc> = Arc::new(Mutex::new(TraceCollectorChain::new())); -} - -pub fn collect(trace_record: TraceRecord) { - CHAIN.lock().unwrap().buffers.iter_mut().for_each(|collector| - collector.lock().unwrap().add(trace_record.clone())); + static ref TRACES: Mutex>> = Mutex::new(HashMap::new()); } - -pub fn init_tracing(chain: &mut TraceCollectorChain) -> Result<()> { - let trace = &mut *CHAIN.lock().unwrap(); - - if trace.buffers.is_empty() { - trace.buffers.append(&mut chain.buffers); - - return Ok(()); - } - - return Err(TimedError::TracingInitializationFailed); -} - -#[macro_export] -macro_rules! anonymous_collector { - ($closure:expr) => { - Box::new((|| { - struct Anonymous; - impl timed::Collector for Anonymous { - fn collect(&mut self, record: &timed::TraceRecord) { - $closure(record); - } - } - Anonymous - })()) - } -} \ No newline at end of file diff --git a/timed/src/statistics.rs b/timed/src/statistics.rs new file mode 100644 index 0000000..1a2087c --- /dev/null +++ b/timed/src/statistics.rs @@ -0,0 +1,116 @@ +use crate::{Phase}; +use prettytable::Table; +use std::cmp::Ordering; +use std::collections::HashMap; +use std::time::Duration; + +use crate::hop::Hop; + +#[derive(Clone, Debug)] +struct StatisticsRecord { + name: String, + calls: Vec, + overall_time: Duration +} + +impl StatisticsRecord { + fn new(name: String) -> StatisticsRecord { + StatisticsRecord { + name, + calls: vec![], + overall_time: Duration::from_nanos(0), + } + } + + pub fn nth_percentile_time(&self, percentile: f32) -> Option<&Duration> { + let mut calls = self.calls.clone(); + calls.sort(); + + let mut i = (percentile * self.calls.len() as f32).round() as usize; + if i > 0 { + i -= 1; + } + + return self.calls.get(i); + } + + pub fn avg(&self) -> Duration { + Duration::from_nanos( + self.calls.iter().sum::().as_nanos() as u64 / self.calls.len() as u64, + ) + } +} + +impl Ord for StatisticsRecord { + // This is reversed so that longer time will be above shorter time after sorting. + fn cmp(&self, other: &Self) -> Ordering { + other.overall_time.cmp(&self.overall_time) + } +} + +impl PartialOrd for StatisticsRecord { + fn partial_cmp(&self, other: &Self) -> Option { + Some(self.cmp(&other)) + } +} + +impl PartialEq for StatisticsRecord { + fn eq(&self, other: &Self) -> bool { + self.overall_time == other.overall_time + } +} + +impl Eq for StatisticsRecord {} + +pub fn from(hops: &[Hop]) -> String { + let mut stats = HashMap::new(); + + hops + .iter() + .for_each(|record| { + if let Phase::Finish(d) = record.phase { + let entry = stats + .entry(record.function_name.clone()) + .or_insert(StatisticsRecord::new(record.function_name.clone())); + entry.calls.push(d); + entry.overall_time += d; + } + }); + + let mut table = Table::new(); + table.add_row(row![ + "function name", + "calls", + "overall time", + "avg time", + "max time", + "p90 time", + "p50 time", + "p10 time" + ]); + + let mut stats = stats + .iter() + .map(|(_, sr)| sr.clone()) + .collect::>(); + + stats + .sort_by(|a, b| b.overall_time.cmp(&a.overall_time)); + + stats + .iter() + .for_each(|sr| { + table.add_row(row![ + sr.name, + sr.calls.len(), + format!("{:?}", sr.overall_time), + format!("{:?}", sr.avg()), + format!("{:?}", sr.nth_percentile_time(1.0).unwrap()), + format!("{:?}", sr.nth_percentile_time(0.9).unwrap()), + format!("{:?}", sr.nth_percentile_time(0.5).unwrap()), + format!("{:?}", sr.nth_percentile_time(0.1).unwrap()) + ]); + }); + + format!("{}", table) +} diff --git a/timed/src/trace.rs b/timed/src/trace.rs index bcd616c..2cbb3c9 100644 --- a/timed/src/trace.rs +++ b/timed/src/trace.rs @@ -1,24 +1,47 @@ -use std::time::Duration; -#[derive(Clone, Debug)] -pub enum Phase { - Start, - Finish(Duration), +use crate::hop::Hop; +use crate::chrome_trace; +use crate::statistics; + +use thiserror::Error; +use std::collections::HashMap; + +pub struct Trace { + id: String, + start_timestamp: u128, } -impl Phase { - // These are B and E for chrome tracing - pub(crate) fn to_string(&self) -> String { - match self { - Phase::Start => "B".to_string(), - Phase::Finish(_) => "E".to_string(), +impl Trace { + + fn register(id: &str) { + crate::TRACES.lock().unwrap().insert(id.to_string(), vec![]); + } + + pub fn record(hop: Hop) { + for trace_group in crate::TRACES.lock().unwrap().iter_mut() { + trace_group.1.push(hop.clone()); } } -} -#[derive(Clone, Debug)] -pub struct TraceRecord { - pub function_name: String, - pub timestamp: u128, - pub phase: Phase, + pub fn new(id: &str) -> Self { + let trace = Self { + id: id.to_string(), + start_timestamp: 0 + }; + + Trace::register(id); + trace + } + + pub fn chrome_tracing(&self) -> String { + let mut traces = crate::TRACES.lock().unwrap(); + let entries = traces.entry(self.id.clone()).or_insert(vec![]); + chrome_trace::from(entries) + } + + pub fn statistics(&self) -> String { + let mut traces = crate::TRACES.lock().unwrap(); + let entries = traces.entry(self.id.clone()).or_insert(vec![]); + statistics::from(entries) + } } \ No newline at end of file diff --git a/timed_proc_macros/Makefile.toml b/timed_proc_macros/Makefile.toml deleted file mode 100644 index 36d8ddf..0000000 --- a/timed_proc_macros/Makefile.toml +++ /dev/null @@ -1,22 +0,0 @@ -[tasks.build] -command = "cargo" -args = ["build"] - -#[tasks.clean] -#command = "cargo" -#args = ["clean"] -# -#[tasks.build] -#command = "cargo" -#args = ["build"] -#dependencies = ["clean"] -# -#[tasks.tests.expand] -#command = "cargo" -#args = ["run", "--package", "tests", "--bin", "tests_expand"] -#dependencies = ["clean"] - -[tasks.testing] -dependencies = [ - "build", -] \ No newline at end of file diff --git a/timed_proc_macros/src/lib.rs b/timed_proc_macros/src/lib.rs index 7da2cdf..8a7577e 100644 --- a/timed_proc_macros/src/lib.rs +++ b/timed_proc_macros/src/lib.rs @@ -1,26 +1,39 @@ use darling::FromMeta; use proc_macro::TokenStream; +use proc_macro2::Span; use quote::quote; use syn::{AttributeArgs, ItemFn}; +#[derive(Debug, FromMeta)] +struct TracingArgs { + #[darling(default)] + enabled: Option, + #[darling(default)] + main: Option, +} + #[derive(Debug, FromMeta)] struct MacroArgs { #[darling(default)] - tracing: Option + tracing: Option, + // An idea printer could be a 'sink' so it can either println!() each or + // we can collect the data into a vector + #[darling(default)] + printer: Option, } use proc_macro2::TokenStream as Code; fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, Option) { - if let Some(true) = options.tracing { + if let Some(_) = options.tracing { let begin = quote! { { let ts = std::time::SystemTime::now() .duration_since(std::time::SystemTime::UNIX_EPOCH) .unwrap() .as_micros(); - timed::collect(timed::TraceRecord { - function_name: format!("{}::{}", module_path, #function_name), + timed::Trace::record(timed::Hop { + function_name: format!("{}::{}", __timed_module_path, #function_name), timestamp: ts, phase: timed::Phase::Start }); @@ -32,10 +45,10 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O .duration_since(std::time::SystemTime::UNIX_EPOCH) .unwrap() .as_micros(); - timed::collect(timed::TraceRecord { - function_name: format!("{}::{}", module_path, #function_name), + timed::Trace::record(timed::Hop { + function_name: format!("{}::{}", __timed_module_path, #function_name), timestamp: ts, - phase: timed::Phase::Finish(elapsed) + phase: timed::Phase::Finish(__timed_elapsed) }); } }; @@ -45,6 +58,39 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O } } +fn codegen_duration( + printer: &proc_macro2::TokenStream, + function_name: &String, +) -> proc_macro2::TokenStream { + quote! { + #printer("function={} duration={:?}", #function_name, __timed_elapsed); + } +} + +fn codegen_printer(options: &MacroArgs) -> proc_macro2::TokenStream { + let (printer, needs_bang) = match &options.printer { + Some(printer) => { + if printer.ends_with('!') { + (&printer[..&printer.len() - 1], true) + } else { + (printer.as_str(), false) + } + } + None => ("println", true), + }; + + let bang = if needs_bang { + Some(syn::token::Bang(Span::call_site())) + } else { + None + }; + + let printer = syn::Ident::new(printer, Span::call_site()); + quote! { + #printer#bang + } +} + /// Macro that times your function execution. #[proc_macro_attribute] pub fn timed(args: TokenStream, input: TokenStream) -> TokenStream { @@ -78,18 +124,25 @@ pub fn timed(args: TokenStream, input: TokenStream) -> TokenStream { .. } = &function; let name = function.sig.ident.to_string(); + let printer = codegen_printer(&options); + let print_duration = codegen_duration(&printer, &name); let (tracing_begin, tracing_end) = codegen_tracing(&options, name.as_str()); let result = quote! { #(#attrs)* #vis #sig { - let module_path = std::module_path!(); + let __timed_module_path = std::module_path!(); + #tracing_begin - let start = std::time::Instant::now(); - let res = { #body }; - let elapsed = start.elapsed(); + + let __timed_start = std::time::Instant::now(); + let __timed_res = { #body }; + let __timed_elapsed = __timed_start.elapsed(); + #tracing_end - res + #print_duration + + __timed_res } }; From ce35f9a4862beac96305d6e8d426d04f791fd8d1 Mon Sep 17 00:00:00 2001 From: Marius Ciubotariu Date: Sat, 12 Dec 2020 16:08:14 +0000 Subject: [PATCH 12/16] clean up --- tests/examples/demo_duration.rs | 4 +- tests/examples/demo_statistics.rs | 16 +++-- tests/src/lib.rs | 4 -- tests/src/tests_duration.rs | 97 ------------------------------- tests/src/tests_expand.rs | 25 -------- tests/src/tests_tracing.rs | 62 -------------------- timed/src/error.rs | 7 --- timed/src/lib.rs | 14 ++--- timed/src/trace.rs | 11 +--- timed_proc_macros/src/lib.rs | 85 ++++++++++++++++++--------- 10 files changed, 78 insertions(+), 247 deletions(-) delete mode 100644 tests/src/tests_duration.rs delete mode 100644 tests/src/tests_expand.rs delete mode 100644 tests/src/tests_tracing.rs delete mode 100644 timed/src/error.rs diff --git a/tests/examples/demo_duration.rs b/tests/examples/demo_duration.rs index 22428c3..90cc00c 100644 --- a/tests/examples/demo_duration.rs +++ b/tests/examples/demo_duration.rs @@ -12,12 +12,12 @@ fn mul(x: i32, y: i32) -> i32 { x * y } -#[timed(printer = "println!")] +#[timed(duration(printer = "println!"))] fn mul_println(x: i32, y: i32) -> i32 { x * y } -#[timed(printer = "info!")] +#[timed(duration(printer = "info!"))] fn mul_info(x: i32, y: i32) -> i32 { x * y } diff --git a/tests/examples/demo_statistics.rs b/tests/examples/demo_statistics.rs index 591d755..31dcd51 100644 --- a/tests/examples/demo_statistics.rs +++ b/tests/examples/demo_statistics.rs @@ -1,42 +1,40 @@ mod one { pub(crate) mod two { pub(crate) mod three { - #[timed::timed(tracing(enabled = true))] + #[timed::timed(tracing(enabled = true), duration(disabled = true))] pub(crate) fn deep() { - println!("Deep"); + // println!("Deep"); } } } } -#[timed::timed(tracing(enabled = true))] +#[timed::timed(tracing(enabled = true), duration(disabled = true))] fn foo() { bar(); baz(); } -#[timed::timed(tracing(enabled = true))] +#[timed::timed(tracing(enabled = true), duration(disabled = true))] fn baz() { - println!("Hello"); + // println!("Hello"); for _ in 0..3 { one::two::three::deep(); } } -#[timed::timed(tracing(enabled = true))] +#[timed::timed(tracing(enabled = true), duration(disabled = true))] fn bar() { for _ in 0..10 { baz(); } } -#[timed::timed(tracing(enabled = true))] +#[timed::timed(tracing(enabled = true), duration(disabled = true))] fn main() { - let trace = timed::Trace::new("Main"); foo(); println!("{}", trace.statistics()); - } diff --git a/tests/src/lib.rs b/tests/src/lib.rs index 40ffe90..a271b12 100644 --- a/tests/src/lib.rs +++ b/tests/src/lib.rs @@ -1,7 +1,3 @@ extern crate log; -mod tests_duration; -mod tests_tracing; -mod tests_expand; - pub mod tests_utils; diff --git a/tests/src/tests_duration.rs b/tests/src/tests_duration.rs deleted file mode 100644 index f044e46..0000000 --- a/tests/src/tests_duration.rs +++ /dev/null @@ -1,97 +0,0 @@ -// use std::{thread, time}; -// use timed::timed; -// -// use std::sync::Once; -// #[allow(dead_code)] -// static INIT: Once = Once::new(); -// -// /// Setup function that is only run once, even if called multiple times. -// #[allow(dead_code)] -// fn init_logger() { -// INIT.call_once(|| { -// pretty_env_logger::init(); -// }); -// } -// -// #[timed] -// fn foo(x: i32, y: i32) -> i32 { -// thread::sleep(time::Duration::from_millis(100)); -// x + y -// } -// -// #[timed] -// fn bar(x: i32) -> i32 { -// thread::sleep(time::Duration::from_millis(100)); -// x -// } -// -// #[timed] -// fn baz() -> i32 { -// 42 -// } -// -// #[timed] -// fn foobar() { -// thread::sleep(time::Duration::from_millis(100)); -// } -// -// #[timed] -// fn add(x: i32, y: i32) -> i32 { -// x + y -// } -// -// #[timed] -// fn mul(x: i32, y: i32) -> i32 { -// x * y -// } -// -// #[timed(printer = "println!")] -// fn mul_println(x: i32, y: i32) -> i32 { -// x * y -// } -// -// #[timed(printer = "info!")] -// fn mul_info(x: i32, y: i32) -> i32 { -// x * y -// } -// -// #[timed(printer = "warn!")] -// fn mul_error(x: i32, y: i32) -> i32 { -// x * y -// } -// -// #[timed] -// async fn ping_google() { -// reqwest::get("https://google.com").await.unwrap(); -// } -// -// #[test] -// fn simple() { -// foo(1, 2); -// bar(1); -// baz(); -// foobar(); -// -// assert_eq!(add(1, 2), 3); -// assert_eq!(mul(1, 2), 2); -// } -// -// #[test] -// fn with_logging() { -// init_logger(); -// -// mul_info(1, 1); -// mul_info(1, 1); -// mul_error(1, 1); -// } -// -// #[tokio::test] -// async fn with_async() { -// ping_google().await -// } -// -// #[tokio::test] -// async fn test_async_quotes() { -// use crate::tests_utils::get_random_quote; -// get_random_quote().await -// } diff --git a/tests/src/tests_expand.rs b/tests/src/tests_expand.rs deleted file mode 100644 index b9b20ab..0000000 --- a/tests/src/tests_expand.rs +++ /dev/null @@ -1,25 +0,0 @@ -#[timed::timed(tracing(enabled = true))] -fn foo() { - std::thread::sleep(std::time::Duration::from_micros(1000)); - bar(); - baz(); -} - -#[timed::timed(tracing(enabled = true))] -fn baz() { - std::thread::sleep(std::time::Duration::from_micros(1000)); -} - -#[timed::timed(tracing(enabled = true))] -fn bar() { - baz(); - std::thread::sleep(std::time::Duration::from_micros(1000)); -} - -#[timed::timed(tracing(enabled = true))] -fn main() { - let trace = timed::Trace::new("Main"); - - foo(); - -} diff --git a/tests/src/tests_tracing.rs b/tests/src/tests_tracing.rs deleted file mode 100644 index 4e1664c..0000000 --- a/tests/src/tests_tracing.rs +++ /dev/null @@ -1,62 +0,0 @@ -use std::{thread, time}; - -#[macro_use] -use rusty_fork::rusty_fork_test; - -use std::sync::Arc; -use timed; - -#[allow(dead_code)] -fn sleep() { - thread::sleep(time::Duration::from_millis(10)); -} - -#[timed::timed(tracing(enabled = true))] -fn outer_sleep() { - sleep(); - inner_sleep(); -} - -#[timed::timed(tracing(enabled = true))] -fn inner_sleep() { - sleep(); -} - -#[test] -#[timed::timed(tracing(enabled = true))] -fn test_tracing_statistics() { - let mut statistics = RecordBuffer::new(); - - let _ = timed::init_tracing( - timed::TraceCollectorChain::new().chain_output(Arc::clone(&statistics)), - ) - .unwrap(); - - println!("Running main"); - outer_sleep(); - - statistics.lock().unwrap().get_statistics().printstd(); -} - -#[test] -#[timed::timed(tracing(enabled = true))] -fn test_tracing_chrome_trace() { - let mut chrome_trace = RecordBuffer::new(); - - let _ = timed::init_tracing( - timed::TraceCollectorChain::new().chain_output(Arc::clone(&chrome_trace)), - ) - .unwrap(); - - println!("Running main"); - outer_sleep(); - - println!( - "{}", - chrome_trace - .lock() - .unwrap() - .get_chrome_trace() - .to_chrome_trace() - ); -} diff --git a/timed/src/error.rs b/timed/src/error.rs deleted file mode 100644 index 0833628..0000000 --- a/timed/src/error.rs +++ /dev/null @@ -1,7 +0,0 @@ -#[derive(Error, Debug)] -pub enum TimedError { - #[error("Tracing can only be initialized once")] - TracingInitializationFailed, - #[error("Tracing finish failed: {0}")] - TracingFinishFailed(String), -} diff --git a/timed/src/lib.rs b/timed/src/lib.rs index 496dd4e..1778fb9 100644 --- a/timed/src/lib.rs +++ b/timed/src/lib.rs @@ -45,22 +45,22 @@ //! //! ``` -use std::sync::{Arc, Mutex}; use std::collections::HashMap; +use std::sync::Mutex; -#[macro_use] extern crate lazy_static; -#[macro_use] extern crate prettytable; -#[macro_use] extern crate thiserror; +#[macro_use] +extern crate lazy_static; +#[macro_use] +extern crate prettytable; mod chrome_trace; -mod error; mod hop; -mod trace; mod statistics; +mod trace; // export Trace +pub use hop::{Hop, Phase}; pub use trace::Trace; -pub use hop::{Phase, Hop}; // Re-exporting the timed proc macro pub use timed_proc_macros::timed; diff --git a/timed/src/trace.rs b/timed/src/trace.rs index 2cbb3c9..44a7ad7 100644 --- a/timed/src/trace.rs +++ b/timed/src/trace.rs @@ -1,18 +1,13 @@ - -use crate::hop::Hop; use crate::chrome_trace; +use crate::hop::Hop; use crate::statistics; -use thiserror::Error; -use std::collections::HashMap; - pub struct Trace { id: String, start_timestamp: u128, } impl Trace { - fn register(id: &str) { crate::TRACES.lock().unwrap().insert(id.to_string(), vec![]); } @@ -26,7 +21,7 @@ impl Trace { pub fn new(id: &str) -> Self { let trace = Self { id: id.to_string(), - start_timestamp: 0 + start_timestamp: 0, }; Trace::register(id); @@ -44,4 +39,4 @@ impl Trace { let entries = traces.entry(self.id.clone()).or_insert(vec![]); statistics::from(entries) } -} \ No newline at end of file +} diff --git a/timed_proc_macros/src/lib.rs b/timed_proc_macros/src/lib.rs index 8a7577e..4be63e5 100644 --- a/timed_proc_macros/src/lib.rs +++ b/timed_proc_macros/src/lib.rs @@ -1,3 +1,5 @@ +#![allow(unused_imports)] + use darling::FromMeta; use proc_macro::TokenStream; use proc_macro2::Span; @@ -12,14 +14,20 @@ struct TracingArgs { main: Option, } +#[derive(Debug, FromMeta)] +struct DurationArgs { + #[darling(default)] + disabled: bool, + #[darling(default)] + printer: Option, +} + #[derive(Debug, FromMeta)] struct MacroArgs { #[darling(default)] tracing: Option, - // An idea printer could be a 'sink' so it can either println!() each or - // we can collect the data into a vector #[darling(default)] - printer: Option, + duration: Option, } use proc_macro2::TokenStream as Code; @@ -58,17 +66,8 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O } } -fn codegen_duration( - printer: &proc_macro2::TokenStream, - function_name: &String, -) -> proc_macro2::TokenStream { - quote! { - #printer("function={} duration={:?}", #function_name, __timed_elapsed); - } -} - -fn codegen_printer(options: &MacroArgs) -> proc_macro2::TokenStream { - let (printer, needs_bang) = match &options.printer { +fn codegen_printer(options: &Option) -> proc_macro2::TokenStream { + let (printer, needs_bang) = match &options { Some(printer) => { if printer.ends_with('!') { (&printer[..&printer.len() - 1], true) @@ -91,6 +90,42 @@ fn codegen_printer(options: &MacroArgs) -> proc_macro2::TokenStream { } } +fn codegen_duration(options: &MacroArgs, function_name: &String) -> (Code, Code) { + // Generate printer + let printer_options = match &options.duration { + Some(options) => &options.printer, + None => &None, + }; + let printer = codegen_printer(&printer_options); + + // Decide if we generate duration at all + let disabled = match options.duration { + Some(DurationArgs { disabled, .. }) => disabled, + _ => true, + }; + + if let Some(duration_args) = &options.duration { + println!("{:?}", duration_args); + } + + let duration_begin = quote! { + let __timed_start = std::time::Instant::now(); + }; + + let duration_end = if disabled { + quote! { + let __timed_elapsed = __timed_start.elapsed(); + } + } else { + quote! { + let __timed_elapsed = __timed_start.elapsed(); + #printer("function={} duration={:?}", #function_name, __timed_elapsed); + } + }; + + (duration_begin, duration_end) +} + /// Macro that times your function execution. #[proc_macro_attribute] pub fn timed(args: TokenStream, input: TokenStream) -> TokenStream { @@ -102,7 +137,7 @@ pub fn timed(args: TokenStream, input: TokenStream) -> TokenStream { //! ``` //! //! ```ignore - //! #[timed(printer = "println!")] + //! #[timed(duration(printer = "println!"))] //! ``` // debug!("Args {:?}", args); let options = syn::parse_macro_input!(args as AttributeArgs); @@ -124,25 +159,23 @@ pub fn timed(args: TokenStream, input: TokenStream) -> TokenStream { .. } = &function; let name = function.sig.ident.to_string(); - let printer = codegen_printer(&options); - let print_duration = codegen_duration(&printer, &name); + + let (duration_begin, duration_end) = codegen_duration(&options, &name); let (tracing_begin, tracing_end) = codegen_tracing(&options, name.as_str()); let result = quote! { #(#attrs)* #vis #sig { - let __timed_module_path = std::module_path!(); - - #tracing_begin + let __timed_module_path = std::module_path!(); - let __timed_start = std::time::Instant::now(); - let __timed_res = { #body }; - let __timed_elapsed = __timed_start.elapsed(); + #tracing_begin + #duration_begin + let result = { #body }; - #tracing_end - #print_duration + #duration_end + #tracing_end - __timed_res + result } }; From b1355c54055e13473af4d566d763456e58e5f64f Mon Sep 17 00:00:00 2001 From: Marius Ciubotariu Date: Sat, 12 Dec 2020 16:28:10 +0000 Subject: [PATCH 13/16] add current running function as well to stats and tracing --- TODO.md | 8 +++---- tests/examples/demo_statistics.rs | 1 + timed/src/trace.rs | 38 +++++++++++++++++++++++++++++-- timed_proc_macros/src/lib.rs | 2 +- 4 files changed, 42 insertions(+), 7 deletions(-) diff --git a/TODO.md b/TODO.md index a6b8e13..4513eee 100644 --- a/TODO.md +++ b/TODO.md @@ -17,15 +17,15 @@ - [ ] add name override to function, sometimes "new" is not very useful - [ ] remove all unwraps, hardcode the function name, don't put it in format! both in tracing and in duration - [ ] add example repo, add gifs -- [ ] ask for help to write the stats - [ ] ask for help to write a few more idiomatic examples where this would be useful - [ ] add thread and pid and enrich with what else chrome::tracing allows you to - [ ] ask for help for taking a closure as argument to remove the warning and possibly making it cleaner -- [ ] init/main function is not captured during tracing, perhaps try a different type of init -- [ ] allow disable duration to keep tracing only. -- [ ] Add the module path to the name of a function like "foo::bar::baz()" in tracing ## Done +- [x] ask for help to write the stats +- [x] Add the module path to the name of a function like "foo::bar::baz()" in tracing +- [x] allow disable duration to keep tracing only. +- [x] init/main function is not captured during tracing, perhaps try a different type of init - [x] tracing print with "printer" - [x] Keep accumulating in a global state - [no longer] use timed::dump/flush on stdout/file when useful diff --git a/tests/examples/demo_statistics.rs b/tests/examples/demo_statistics.rs index 31dcd51..bb0ff1a 100644 --- a/tests/examples/demo_statistics.rs +++ b/tests/examples/demo_statistics.rs @@ -35,6 +35,7 @@ fn main() { let trace = timed::Trace::new("Main"); foo(); + std::thread::sleep(std::time::Duration::from_millis(1000)); println!("{}", trace.statistics()); } diff --git a/timed/src/trace.rs b/timed/src/trace.rs index 44a7ad7..0e91a96 100644 --- a/timed/src/trace.rs +++ b/timed/src/trace.rs @@ -1,5 +1,5 @@ use crate::chrome_trace; -use crate::hop::Hop; +use crate::hop::{Hop, Phase}; use crate::statistics; pub struct Trace { @@ -19,24 +19,58 @@ impl Trace { } pub fn new(id: &str) -> Self { + let start_timestamp = std::time::SystemTime::now() + .duration_since(std::time::SystemTime::UNIX_EPOCH) + .unwrap() + .as_micros(); + let trace = Self { id: id.to_string(), - start_timestamp: 0, + start_timestamp, }; Trace::register(id); + Trace::record(Hop { + function_name: id.to_string(), + timestamp: start_timestamp, + phase: Phase::Start, + }); + + // record the original too trace } + fn generate_current_end_hop(&self) -> Hop { + let end_timestamp = std::time::SystemTime::now() + .duration_since(std::time::SystemTime::UNIX_EPOCH) + .unwrap() + .as_micros(); + + let duration = + std::time::Duration::from_micros((end_timestamp - self.start_timestamp) as u64); + + Hop { + function_name: self.id.to_string(), + timestamp: end_timestamp, + phase: Phase::Finish(duration), + } + } + pub fn chrome_tracing(&self) -> String { let mut traces = crate::TRACES.lock().unwrap(); let entries = traces.entry(self.id.clone()).or_insert(vec![]); + + entries.push(self.generate_current_end_hop()); + chrome_trace::from(entries) } pub fn statistics(&self) -> String { let mut traces = crate::TRACES.lock().unwrap(); let entries = traces.entry(self.id.clone()).or_insert(vec![]); + + entries.push(self.generate_current_end_hop()); + statistics::from(entries) } } diff --git a/timed_proc_macros/src/lib.rs b/timed_proc_macros/src/lib.rs index 4be63e5..e86cf0e 100644 --- a/timed_proc_macros/src/lib.rs +++ b/timed_proc_macros/src/lib.rs @@ -101,7 +101,7 @@ fn codegen_duration(options: &MacroArgs, function_name: &String) -> (Code, Code) // Decide if we generate duration at all let disabled = match options.duration { Some(DurationArgs { disabled, .. }) => disabled, - _ => true, + _ => false, }; if let Some(duration_args) = &options.duration { From aa0312e94f47c4dc1235027f9d7e4618b91b2eda Mon Sep 17 00:00:00 2001 From: Marius Ciubotariu Date: Sat, 12 Dec 2020 16:34:43 +0000 Subject: [PATCH 14/16] fmt --- docs/tracing_example4.json | 24 ++++++++++++++++++++ tests/Makefile.toml | 3 --- tests/examples/demo_statistics.rs | 2 +- tests/examples/demo_tracing.rs | 22 +++++++++--------- timed/src/chrome_trace.rs | 3 +-- timed/src/hop.rs | 2 +- timed/src/statistics.rs | 37 +++++++++++++------------------ timed_proc_macros/src/lib.rs | 4 ---- 8 files changed, 55 insertions(+), 42 deletions(-) create mode 100644 docs/tracing_example4.json diff --git a/docs/tracing_example4.json b/docs/tracing_example4.json new file mode 100644 index 0000000..4536a5a --- /dev/null +++ b/docs/tracing_example4.json @@ -0,0 +1,24 @@ +[ + { "pid": 0, "ts": 1607790744244301, "ph": "B", "name": "Main" }, + { "pid": 0, "ts": 1607790744244326, "ph": "B", "name": "demo_tracing::foo" }, + { "pid": 0, "ts": 1607790744244327, "ph": "B", "name": "demo_tracing::bar" }, + { "pid": 0, "ts": 1607790744244328, "ph": "B", "name": "demo_tracing::baz" }, + { "pid": 0, "ts": 1607790744244330, "ph": "B", "name": "demo_tracing::one::two::three::deep" }, + { "pid": 0, "ts": 1607790744245618, "ph": "E", "name": "demo_tracing::one::two::three::deep" }, + { "pid": 0, "ts": 1607790744245644, "ph": "B", "name": "demo_tracing::one::two::three::deep" }, + { "pid": 0, "ts": 1607790744247018, "ph": "E", "name": "demo_tracing::one::two::three::deep" }, + { "pid": 0, "ts": 1607790744247055, "ph": "B", "name": "demo_tracing::one::two::three::deep" }, + { "pid": 0, "ts": 1607790744248445, "ph": "E", "name": "demo_tracing::one::two::three::deep" }, + { "pid": 0, "ts": 1607790744248460, "ph": "E", "name": "demo_tracing::baz" }, + { "pid": 0, "ts": 1607790744248462, "ph": "E", "name": "demo_tracing::bar" }, + { "pid": 0, "ts": 1607790744248463, "ph": "B", "name": "demo_tracing::baz" }, + { "pid": 0, "ts": 1607790744248464, "ph": "B", "name": "demo_tracing::one::two::three::deep" }, + { "pid": 0, "ts": 1607790744249861, "ph": "E", "name": "demo_tracing::one::two::three::deep" }, + { "pid": 0, "ts": 1607790744249876, "ph": "B", "name": "demo_tracing::one::two::three::deep" }, + { "pid": 0, "ts": 1607790744251258, "ph": "E", "name": "demo_tracing::one::two::three::deep" }, + { "pid": 0, "ts": 1607790744251276, "ph": "B", "name": "demo_tracing::one::two::three::deep" }, + { "pid": 0, "ts": 1607790744252661, "ph": "E", "name": "demo_tracing::one::two::three::deep" }, + { "pid": 0, "ts": 1607790744252676, "ph": "E", "name": "demo_tracing::baz" }, + { "pid": 0, "ts": 1607790744252678, "ph": "E", "name": "demo_tracing::foo" }, + { "pid": 0, "ts": 1607790744264733, "ph": "E", "name": "Main" } +] \ No newline at end of file diff --git a/tests/Makefile.toml b/tests/Makefile.toml index a5d5fb6..4404703 100644 --- a/tests/Makefile.toml +++ b/tests/Makefile.toml @@ -30,9 +30,6 @@ args = ["run", "--example", "demo_tracing"] command = "cargo" args = ["run", "--example", "demo_statistics"] -[tasks.run_expand] -command = "cargo" -args = ["run", "--bin", "tests_expand"] [tasks.tests] command = "cargo" diff --git a/tests/examples/demo_statistics.rs b/tests/examples/demo_statistics.rs index bb0ff1a..1444f37 100644 --- a/tests/examples/demo_statistics.rs +++ b/tests/examples/demo_statistics.rs @@ -35,7 +35,7 @@ fn main() { let trace = timed::Trace::new("Main"); foo(); - std::thread::sleep(std::time::Duration::from_millis(1000)); + std::thread::sleep(std::time::Duration::from_millis(10)); println!("{}", trace.statistics()); } diff --git a/tests/examples/demo_tracing.rs b/tests/examples/demo_tracing.rs index 1512781..14f244d 100644 --- a/tests/examples/demo_tracing.rs +++ b/tests/examples/demo_tracing.rs @@ -1,38 +1,40 @@ mod one { pub(crate) mod two { pub(crate) mod three { - #[timed::timed(tracing(enabled = true))] + #[timed::timed(tracing(enabled = true), duration(disabled = true))] pub(crate) fn deep() { - println!("Deep"); + // println!("Deep"); + std::thread::sleep(std::time::Duration::from_millis(1)); } } } } -#[timed::timed(tracing(enabled = true))] +#[timed::timed(tracing(enabled = true), duration(disabled = true))] fn foo() { bar(); baz(); } -#[timed::timed(tracing(enabled = true))] +#[timed::timed(tracing(enabled = true), duration(disabled = true))] fn baz() { - println!("Hello"); - one::two::three::deep(); + // println!("Hello"); + for _ in 0..3 { + one::two::three::deep(); + } } -#[timed::timed(tracing(enabled = true))] +#[timed::timed(tracing(enabled = true), duration(disabled = true))] fn bar() { baz(); } -#[timed::timed(tracing(enabled = true))] +#[timed::timed(tracing(enabled = true), duration(disabled = true))] fn main() { - let trace = timed::Trace::new("Main"); foo(); + std::thread::sleep(std::time::Duration::from_millis(10)); println!("{}", trace.chrome_tracing()); - } diff --git a/timed/src/chrome_trace.rs b/timed/src/chrome_trace.rs index 7e0fad7..2550210 100644 --- a/timed/src/chrome_trace.rs +++ b/timed/src/chrome_trace.rs @@ -1,7 +1,6 @@ use crate::hop::Hop; pub fn from(hops: &[Hop]) -> String { - let result = hops .iter() .map(|hop| format!("\t{}", hop.to_chrome_trace())) @@ -9,4 +8,4 @@ pub fn from(hops: &[Hop]) -> String { .join(",\n"); format!("[\n{}\n]", result) -} \ No newline at end of file +} diff --git a/timed/src/hop.rs b/timed/src/hop.rs index b6c8777..e73fc27 100644 --- a/timed/src/hop.rs +++ b/timed/src/hop.rs @@ -32,4 +32,4 @@ impl Hop { self.function_name ) } -} \ No newline at end of file +} diff --git a/timed/src/statistics.rs b/timed/src/statistics.rs index 1a2087c..57fc199 100644 --- a/timed/src/statistics.rs +++ b/timed/src/statistics.rs @@ -1,4 +1,4 @@ -use crate::{Phase}; +use crate::Phase; use prettytable::Table; use std::cmp::Ordering; use std::collections::HashMap; @@ -10,7 +10,7 @@ use crate::hop::Hop; struct StatisticsRecord { name: String, calls: Vec, - overall_time: Duration + overall_time: Duration, } impl StatisticsRecord { @@ -65,9 +65,7 @@ impl Eq for StatisticsRecord {} pub fn from(hops: &[Hop]) -> String { let mut stats = HashMap::new(); - hops - .iter() - .for_each(|record| { + hops.iter().for_each(|record| { if let Phase::Finish(d) = record.phase { let entry = stats .entry(record.function_name.clone()) @@ -94,23 +92,20 @@ pub fn from(hops: &[Hop]) -> String { .map(|(_, sr)| sr.clone()) .collect::>(); - stats - .sort_by(|a, b| b.overall_time.cmp(&a.overall_time)); - - stats - .iter() - .for_each(|sr| { - table.add_row(row![ - sr.name, - sr.calls.len(), - format!("{:?}", sr.overall_time), - format!("{:?}", sr.avg()), - format!("{:?}", sr.nth_percentile_time(1.0).unwrap()), - format!("{:?}", sr.nth_percentile_time(0.9).unwrap()), - format!("{:?}", sr.nth_percentile_time(0.5).unwrap()), - format!("{:?}", sr.nth_percentile_time(0.1).unwrap()) + stats.sort_by(|a, b| b.overall_time.cmp(&a.overall_time)); + + stats.iter().for_each(|sr| { + table.add_row(row![ + sr.name, + sr.calls.len(), + format!("{:?}", sr.overall_time), + format!("{:?}", sr.avg()), + format!("{:?}", sr.nth_percentile_time(1.0).unwrap()), + format!("{:?}", sr.nth_percentile_time(0.9).unwrap()), + format!("{:?}", sr.nth_percentile_time(0.5).unwrap()), + format!("{:?}", sr.nth_percentile_time(0.1).unwrap()) ]); - }); + }); format!("{}", table) } diff --git a/timed_proc_macros/src/lib.rs b/timed_proc_macros/src/lib.rs index e86cf0e..bcd7dc5 100644 --- a/timed_proc_macros/src/lib.rs +++ b/timed_proc_macros/src/lib.rs @@ -104,10 +104,6 @@ fn codegen_duration(options: &MacroArgs, function_name: &String) -> (Code, Code) _ => false, }; - if let Some(duration_args) = &options.duration { - println!("{:?}", duration_args); - } - let duration_begin = quote! { let __timed_start = std::time::Instant::now(); }; From 6d1905e4c85dcde6ae4689e21ac7f658a7eba9a3 Mon Sep 17 00:00:00 2001 From: Marius Ciubotariu Date: Sat, 12 Dec 2020 16:47:14 +0000 Subject: [PATCH 15/16] makefile and instructions --- Cargo.toml | 1 - README.md | 9 +++++---- tests/Makefile.toml | 10 +++++++--- tests/examples/demo_main_info.rs | 2 +- timed/Makefile.toml | 2 +- timed/src/lib.rs | 2 +- timed_proc_macros/Makefile.toml | 8 ++++++++ 7 files changed, 23 insertions(+), 11 deletions(-) create mode 100644 timed_proc_macros/Makefile.toml diff --git a/Cargo.toml b/Cargo.toml index 6c60dda..360e1ab 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,5 +1,4 @@ [workspace] - members = [ "tests", "timed", diff --git a/README.md b/README.md index 912a5c6..74e9ac6 100644 --- a/README.md +++ b/README.md @@ -26,7 +26,7 @@ fn add(x: i32, y: i32) -> i32 { x + y } #[timed] fn mul(x: i32, y: i32) -> i32 { x * y } -#[timed(printer = "println!")] +#[timed(duration(printer = "println!"))] fn mul_println(x: i32, y: i32) -> i32 { x * y} #[timed(printer = "info!")] @@ -73,7 +73,7 @@ Output: ``` Running main Calling https://type.fit/api/quotes -Quote of the day: +Quote of the day: Genius is one percent inspiration and ninety-nine percent perspiration. - Thomas Edison function=get_random_quote duration=455.291753ms function=main duration=456.452412ms @@ -143,6 +143,7 @@ See [TODO](TODO.md) To build specific packages / examples / binaries, follow the usual workflow. To do a full build on everything, run the below: ```shell script -$ cargo make -$ cargo make testing +$ cd tests && cargo make all +$ cd timed && cargo make all +$ cd timed_proc_macros && cargo make all ``` \ No newline at end of file diff --git a/tests/Makefile.toml b/tests/Makefile.toml index 4404703..b36282a 100644 --- a/tests/Makefile.toml +++ b/tests/Makefile.toml @@ -35,10 +35,14 @@ args = ["run", "--example", "demo_statistics"] command = "cargo" args = ["test"] -[tasks.testing] +[tasks.all] dependencies = [ "build", - "run_macros", - "run_expand", "tests", + "example_async", + "example_main", + "example_main_info", + "example_main_nested", + "example_tracing", + "example_statistics", ] \ No newline at end of file diff --git a/tests/examples/demo_main_info.rs b/tests/examples/demo_main_info.rs index ad349e3..6bfc54a 100644 --- a/tests/examples/demo_main_info.rs +++ b/tests/examples/demo_main_info.rs @@ -1,7 +1,7 @@ use log::info; use timed::timed; -#[timed(printer = "info!")] +#[timed(duration(printer = "info!"))] fn main() { pretty_env_logger::init(); println!("Running main"); diff --git a/timed/Makefile.toml b/timed/Makefile.toml index 65ac0f0..94ef12c 100644 --- a/timed/Makefile.toml +++ b/timed/Makefile.toml @@ -2,7 +2,7 @@ command = "cargo" args = ["build"] -[tasks.testing] +[tasks.all] dependencies = [ "build", ] \ No newline at end of file diff --git a/timed/src/lib.rs b/timed/src/lib.rs index 1778fb9..f4647d1 100644 --- a/timed/src/lib.rs +++ b/timed/src/lib.rs @@ -23,7 +23,7 @@ //! x + y //! } //! -//! #[timed(printer = "println!")] +//! #[timed(duration(printer = "println!"))] //! async fn google() { //! // reqwest::get("https://google.com").await; //! } diff --git a/timed_proc_macros/Makefile.toml b/timed_proc_macros/Makefile.toml new file mode 100644 index 0000000..94ef12c --- /dev/null +++ b/timed_proc_macros/Makefile.toml @@ -0,0 +1,8 @@ +[tasks.build] +command = "cargo" +args = ["build"] + +[tasks.all] +dependencies = [ + "build", +] \ No newline at end of file From 7af7411fc5d37435594193b5f56ebd7600d826c0 Mon Sep 17 00:00:00 2001 From: Marius Ciubotariu Date: Sat, 12 Dec 2020 16:54:04 +0000 Subject: [PATCH 16/16] statistics example --- README.md | 48 ++++++++++++++++++++++++++++++++++++++---------- 1 file changed, 38 insertions(+), 10 deletions(-) diff --git a/README.md b/README.md index 74e9ac6..b502100 100644 --- a/README.md +++ b/README.md @@ -6,7 +6,9 @@ ✅ Custom printers, like `println!`, `info!`, or your own function. -✅ New! Profile your program with chrome tracing, build a flamegraph. +✅ Profile your program with chrome tracing, build a flamegraph. + +✅ New! Show timing statistics between your functions ### Usage `duration` @@ -29,7 +31,7 @@ fn mul(x: i32, y: i32) -> i32 { x * y } #[timed(duration(printer = "println!"))] fn mul_println(x: i32, y: i32) -> i32 { x * y} -#[timed(printer = "info!")] +#[timed(duration(printer = "info!"))] fn mul_info(x: i32, y: i32) -> i32 { x * y } @@ -82,23 +84,23 @@ function=main duration=456.452412ms ### Usage chrome::tracing ```rust -#[timed::timed(tracing = true)] +#[timed::timed(tracing(enabled = true), duration(disabled = true))] fn foo() { bar(); baz(); } -#[timed::timed(tracing = true)] +#[timed::timed(tracing(enabled = true), duration(disabled = true))] fn baz() { println!("Hello") } -#[timed::timed(tracing = true)] +#[timed::timed(tracing(enabled = true), duration(disabled = true))] fn bar() { baz(); } -#[timed::timed(tracing = true)] +#[timed::timed(tracing(enabled = true), duration(disabled = true))] fn main() { let trace = timed::TraceOptions::new() .with_chrome_trace(|x: &str| println!("{}", x)) @@ -113,11 +115,7 @@ fn main() { ```shell script Hello -function=baz duration=27.264µs -function=bar duration=45.606µs Hello -function=baz duration=1.625µs -function=foo duration=57.556µs [ { "pid": 0, "ts": 1603026625248670, "ph": "B", "name": "foo" }, { "pid": 0, "ts": 1603026625248676, "ph": "B", "name": "bar" }, @@ -134,6 +132,36 @@ function=foo duration=57.556µs Save the json dump between `[` and `]` to file `tracing.json` then open in Chrome `chrome://tracing` and drag the file: +### Usage statistics + +```rust +#[timed::timed(tracing(enabled = true), duration(disabled = true))] +fn main() { + let trace = timed::Trace::new("Main"); + + foo(); + std::thread::sleep(std::time::Duration::from_millis(10)); + + println!("{}", trace.statistics()); +} +``` + +```shell script ++----------------------------------------+-------+--------------+-----------+-----------+-----------+-----------+-----------+ +| function name | calls | overall time | avg time | max time | p90 time | p50 time | p10 time | ++----------------------------------------+-------+--------------+-----------+-----------+-----------+-----------+-----------+ +| Main | 1 | 10.955ms | 10.955ms | 10.955ms | 10.955ms | 10.955ms | 10.955ms | ++----------------------------------------+-------+--------------+-----------+-----------+-----------+-----------+-----------+ +| demo_statistics::foo | 1 | 112.184µs | 112.184µs | 112.184µs | 112.184µs | 112.184µs | 112.184µs | ++----------------------------------------+-------+--------------+-----------+-----------+-----------+-----------+-----------+ +| demo_statistics::bar | 1 | 99.452µs | 99.452µs | 99.452µs | 99.452µs | 99.452µs | 99.452µs | ++----------------------------------------+-------+--------------+-----------+-----------+-----------+-----------+-----------+ +| demo_statistics::baz | 11 | 85.069µs | 7.733µs | 8.403µs | 5.738µs | 5.895µs | 19.525µs | ++----------------------------------------+-------+--------------+-----------+-----------+-----------+-----------+-----------+ +| demo_statistics::one::two::three::deep | 33 | 691ns | 20ns | 25ns | 23ns | 17ns | 23ns | ++----------------------------------------+-------+--------------+-----------+-----------+-----------+-----------+-----------+ +``` + ## Contribution Contributions are welcome. Please submit PR. See [TODO](TODO.md)