diff --git a/.gitignore b/.gitignore index df5c5ef..5f8062c 100644 --- a/.gitignore +++ b/.gitignore @@ -1,3 +1,4 @@ /target Cargo.lock -timed_proc_macros.iml +*.iml +*.xml diff --git a/Cargo.toml b/Cargo.toml index b4dcf41..360e1ab 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,7 +1,6 @@ [workspace] - members = [ + "tests", "timed", - "timed_proc_macros", - "tests" + "timed_proc_macros" ] \ No newline at end of file diff --git a/README.md b/README.md index c54486b..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` @@ -26,10 +28,10 @@ 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!")] +#[timed(duration(printer = "info!"))] fn mul_info(x: i32, y: i32) -> i32 { x * y } @@ -73,7 +75,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 @@ -82,37 +84,38 @@ 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() { - timed::init_tracing!("Main"); + let trace = timed::TraceOptions::new() + .with_chrome_trace(|x: &str| println!("{}", x)) + .build_named("Main"); + foo(); + + trace.finish(); } ``` ```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" }, @@ -129,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) @@ -138,6 +171,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/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/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/Cargo.toml b/tests/Cargo.toml index 5b11951..acffc76 100644 --- a/tests/Cargo.toml +++ b/tests/Cargo.toml @@ -15,13 +15,5 @@ log = "0.4" pretty_env_logger = "0.4" serde_json = "1.0.58" lazy_static = "1.4.0" +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/Makefile.toml b/tests/Makefile.toml index 0720c89..b36282a 100644 --- a/tests/Makefile.toml +++ b/tests/Makefile.toml @@ -2,22 +2,47 @@ command = "cargo" args = ["build"] -[tasks.run_macros] +[tasks.example_async] command = "cargo" -args = ["run", "--bin", "tests_macro"] +args = ["run", "--example", "demo_async"] -[tasks.run_expand] +[tasks.example_duration] command = "cargo" -args = ["run", "--bin", "tests_expand"] +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.tests] 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_duration.rs b/tests/examples/demo_duration.rs index 6b7946f..90cc00c 100644 --- a/tests/examples/demo_duration.rs +++ b/tests/examples/demo_duration.rs @@ -1,26 +1,32 @@ 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} +#[timed(duration(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 } - - -#[test] -fn timing() { +#[timed(duration(printer = "info!"))] +fn mul_info(x: i32, y: i32) -> i32 { + x * y +} +fn main() { 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_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..6bfc54a --- /dev/null +++ b/tests/examples/demo_main_info.rs @@ -0,0 +1,8 @@ +use log::info; +use timed::timed; + +#[timed(duration(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..1444f37 --- /dev/null +++ b/tests/examples/demo_statistics.rs @@ -0,0 +1,41 @@ +mod one { + pub(crate) mod two { + pub(crate) mod three { + #[timed::timed(tracing(enabled = true), duration(disabled = true))] + pub(crate) fn deep() { + // println!("Deep"); + } + } + } +} + +#[timed::timed(tracing(enabled = true), duration(disabled = true))] +fn foo() { + bar(); + baz(); +} + +#[timed::timed(tracing(enabled = true), duration(disabled = true))] +fn baz() { + // println!("Hello"); + for _ in 0..3 { + one::two::three::deep(); + } +} + +#[timed::timed(tracing(enabled = true), duration(disabled = true))] +fn bar() { + for _ in 0..10 { + baz(); + } +} + +#[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()); +} diff --git a/tests/examples/demo_tracing.rs b/tests/examples/demo_tracing.rs index 2b817ac..14f244d 100644 --- a/tests/examples/demo_tracing.rs +++ b/tests/examples/demo_tracing.rs @@ -1,21 +1,40 @@ -#[timed::timed(tracing = true)] +mod one { + pub(crate) mod two { + pub(crate) mod three { + #[timed::timed(tracing(enabled = true), duration(disabled = true))] + pub(crate) fn deep() { + // println!("Deep"); + std::thread::sleep(std::time::Duration::from_millis(1)); + } + } + } +} + +#[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") + // println!("Hello"); + for _ in 0..3 { + one::two::three::deep(); + } } -#[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() { - timed::init_tracing!("Main"); + let trace = timed::Trace::new("Main"); + foo(); + std::thread::sleep(std::time::Duration::from_millis(10)); + + println!("{}", trace.chrome_tracing()); } diff --git a/tests/src/lib.rs b/tests/src/lib.rs index 5a4725f..a271b12 100644 --- a/tests/src/lib.rs +++ b/tests/src/lib.rs @@ -1,8 +1,3 @@ -mod tests_macro; - -#[macro_use] extern crate log; -mod tests_duration; -mod tests_tracing; pub mod tests_utils; diff --git a/tests/src/tests_duration.rs b/tests/src/tests_duration.rs deleted file mode 100644 index e54afc4..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 19c1442..0000000 --- a/tests/src/tests_expand.rs +++ /dev/null @@ -1,23 +0,0 @@ -#[timed::timed(tracing = true)] -fn foo() { - std::thread::sleep(std::time::Duration::from_micros(1000)); - bar(); - baz(); -} - -#[timed::timed(tracing = true)] -fn baz() { - std::thread::sleep(std::time::Duration::from_micros(1000)); -} - -#[timed::timed(tracing = true)] -fn bar() { - baz(); - std::thread::sleep(std::time::Duration::from_micros(1000)); -} - -#[timed::timed(tracing = true)] -fn main() { - timed::init_tracing!("Test", (|x| { println!("{}", x) })); - foo(); -} diff --git a/tests/src/tests_macro.rs b/tests/src/tests_macro.rs deleted file mode 100644 index 4f7bc1c..0000000 --- a/tests/src/tests_macro.rs +++ /dev/null @@ -1,3 +0,0 @@ -fn main() { - timed::init_tracing!("Hei"); -} diff --git a/tests/src/tests_tracing.rs b/tests/src/tests_tracing.rs deleted file mode 100644 index 8f1ce06..0000000 --- a/tests/src/tests_tracing.rs +++ /dev/null @@ -1,49 +0,0 @@ -use std::{thread, time}; -use timed; - -#[allow(dead_code)] -fn sleep() { - thread::sleep(time::Duration::from_millis(10)); -} - -#[timed::timed(tracing = true)] -fn foo() { - bar(); - sleep(); - baz(); -} - -#[timed::timed(tracing = true)] -fn bar() { - sleep(); - baz(); - sleep(); -} - -#[timed::timed(tracing = true)] -fn baz() { - sleep(); - foo::bar::baz::foobar(); -} - -pub mod foo { - pub mod bar { - pub mod baz { - use timed::timed; - #[timed(tracing = true)] - pub fn foobar() { - println!("Foobar"); - } - } - } -} - -#[test] -#[timed::timed(tracing = true)] -fn test_tracing() { - timed::init_tracing!("Test"); - - println!("Running main"); - sleep(); - foo(); -} diff --git a/timed/Cargo.toml b/timed/Cargo.toml index cbed64c..c553095 100644 --- a/timed/Cargo.toml +++ b/timed/Cargo.toml @@ -15,6 +15,8 @@ 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" } -lazy_static = "1.4.0" \ No newline at end of file +#timed_proc_macros = { version = "0.1.1" } +timed_proc_macros = { path = "../timed_proc_macros" } +lazy_static = "1.4.0" +thiserror = "1.0.21" +prettytable-rs = "^0.8" \ No newline at end of file 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/chrome_trace.rs b/timed/src/chrome_trace.rs new file mode 100644 index 0000000..2550210 --- /dev/null +++ b/timed/src/chrome_trace.rs @@ -0,0 +1,11 @@ +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) +} diff --git a/timed/src/hop.rs b/timed/src/hop.rs new file mode 100644 index 0000000..e73fc27 --- /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 + ) + } +} diff --git a/timed/src/lib.rs b/timed/src/lib.rs index 39fec93..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; //! } @@ -45,106 +45,27 @@ //! //! ``` -pub use timed_proc_macros::timed; - -#[macro_use] -extern crate lazy_static; use std::collections::HashMap; use std::sync::Mutex; -lazy_static! { - static ref TRACES: Mutex>> = Mutex::new(HashMap::new()); -} - -pub enum TracingStats { - None, - Percentage, -} - -pub struct Trace { - id: String, - processor: fn(&str), - stats: TracingStats, -} - -#[derive(Debug, Clone)] -pub enum Phase { - B, - E, -} - -#[derive(Clone)] -pub struct Hop { - pub ts: u128, - pub ph: Phase, - pub name: String, -} - -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 fn dump(id: &str, processor: fn(&str), stats: &TracingStats) { - let start = std::time::Instant::now(); - let mut traces = TRACES.lock().unwrap(); - let entry = traces.entry(id.to_string()).or_insert(vec![]); - - processor("["); - for (i, hop) in entry.iter().enumerate() { - let is_last = i == entry.len() - 1; - let trace = format!( - "{{ \"pid\": 0, \"ts\": {}, \"ph\": \"{:?}\", \"name\": \"{}\" }}", - hop.ts, hop.ph, hop.name - ); - processor(&format!(" {}{}", trace, if !is_last { "," } else { "" })); - } - processor("]"); - processor(&format!("Dumping traces took {:?}", start.elapsed())); +#[macro_use] +extern crate lazy_static; +#[macro_use] +extern crate prettytable; - match stats { - TracingStats::None => {} - TracingStats::Percentage => {} - } - } +mod chrome_trace; +mod hop; +mod statistics; +mod trace; - pub fn new(id: &str, processor: Option, stats: Option) -> Trace { - let trace = Trace { - id: id.into(), - processor: processor.unwrap_or(|x: &str| { - println!("{}", x); - }), - stats: stats.unwrap_or(TracingStats::None), - }; - Self::register(&trace.id); - trace - } -} +// export Trace +pub use hop::{Hop, Phase}; +pub use trace::Trace; -impl Drop for Trace { - fn drop(&mut self) { - Trace::dump(&self.id, self.processor, &self.stats); - } -} +// Re-exporting the timed proc macro +pub use timed_proc_macros::timed; -#[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)); - }; +// Keeping track of traces +lazy_static! { + static ref TRACES: Mutex>> = Mutex::new(HashMap::new()); } diff --git a/timed/src/statistics.rs b/timed/src/statistics.rs new file mode 100644 index 0000000..57fc199 --- /dev/null +++ b/timed/src/statistics.rs @@ -0,0 +1,111 @@ +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 new file mode 100644 index 0000000..0e91a96 --- /dev/null +++ b/timed/src/trace.rs @@ -0,0 +1,76 @@ +use crate::chrome_trace; +use crate::hop::{Hop, Phase}; +use crate::statistics; + +pub struct Trace { + id: String, + start_timestamp: u128, +} + +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()); + } + } + + 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, + }; + + 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/Makefile.toml b/timed_proc_macros/Makefile.toml index 36d8ddf..94ef12c 100644 --- a/timed_proc_macros/Makefile.toml +++ b/timed_proc_macros/Makefile.toml @@ -2,21 +2,7 @@ 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] +[tasks.all] 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 c30ab9f..bcd7dc5 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; @@ -5,38 +7,44 @@ use quote::quote; use syn::{AttributeArgs, ItemFn}; #[derive(Debug, FromMeta)] -struct MacroArgs { +struct TracingArgs { #[darling(default)] - printer: Option, + enabled: Option, #[darling(default)] - tracing: Option, + main: 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"); -// } -// } +#[derive(Debug, FromMeta)] +struct DurationArgs { + #[darling(default)] + disabled: bool, + #[darling(default)] + printer: Option, +} + +#[derive(Debug, FromMeta)] +struct MacroArgs { + #[darling(default)] + tracing: Option, + #[darling(default)] + duration: 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::Trace::collect(timed::Hop { ph: timed::Phase::B, name: #function_name.to_string(), ts}); + timed::Trace::record(timed::Hop { + function_name: format!("{}::{}", __timed_module_path, #function_name), + timestamp: ts, + phase: timed::Phase::Start + }); } }; let end = quote! { @@ -45,7 +53,11 @@ 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::record(timed::Hop { + function_name: format!("{}::{}", __timed_module_path, #function_name), + timestamp: ts, + phase: timed::Phase::Finish(__timed_elapsed) + }); } }; (Some(begin), Some(end)) @@ -54,17 +66,8 @@ fn codegen_tracing(options: &MacroArgs, function_name: &str) -> (Option, O } } -fn codegen_duration( - printer: &proc_macro2::TokenStream, - function_name: &syn::Ident, -) -> proc_macro2::TokenStream { - quote! { - #printer("function={} duration={:?}", stringify!(#function_name), start.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) @@ -87,6 +90,38 @@ 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, + _ => false, + }; + + 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 { @@ -98,7 +133,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); @@ -119,21 +154,24 @@ pub fn timed(args: TokenStream, input: TokenStream) -> TokenStream { block: body, .. } = &function; + let name = function.sig.ident.to_string(); - let name = &function.sig.ident; - let printer = codegen_printer(&options); - let print_duration = codegen_duration(&printer, &name); - let (tracing_begin, tracing_end) = codegen_tracing(&options, &name.to_string()); + 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 { - #tracing_begin - let start = std::time::Instant::now(); - let res = { #body }; - #print_duration - #tracing_end - res + let __timed_module_path = std::module_path!(); + + #tracing_begin + #duration_begin + let result = { #body }; + + #duration_end + #tracing_end + + result } };