add statistics to dump #11

yonip23 · 2020-10-22T21:00:46Z

This PR addresses (some of) the next issues:
#9
#10
Now when calling timed::init_tracing!("Test", TracingStats::Statistics); something like this will be added to your dump:

========================
      Statistics
========================
- timed_proc_macros::baz
	> calls:      2
	> total time: 20.207063ms (19.99726%)
- timed_proc_macros::bar
	> calls:      1
	> total time: 30.320106ms (30.00530%)
- timed_proc_macros::foobar
	> calls:      2
	> total time: 6.263µs     (0.00620%)
- timed_proc_macros::foo
	> calls:      1
	> total time: 50.515721ms (49.99124%)
========================
all functions total time: 101.049153ms

y2kappa · 2020-10-23T18:46:33Z

timed/src/lib.rs

+    Finish(Duration),
+}
+
+impl Phase {


This needs to print to "B" and "E" as these are the only two phases that chrome://tracing takes into account for this event type:

See the specs here: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview

I'll change it for now, but please keep in mind that the console output shouldn't be less readable on behalf of another feature (a.k.a chrome tracing)

I agree. The main purpose of these structs was originally for chrome tracing, however if it grows to enable another use case, we can parametrize how it prints out. For tracing it can print like "B" and "E". I don't know what other use case you have in mind for printing out these structs, but if there is another we can discuss. As far as it goes for now, they are only useful for chrome tracing.

y2kappa · 2020-10-23T19:00:01Z

timed_proc_macros/src/lib.rs

@@ -119,18 +119,19 @@ 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);


Just tested this out, the output of:

cargo run --package tests --example demo_tracing

is:

[ { "pid": 0, "ts": 1603479130104696, "ph": "Start", "name": "timed_proc_macros::foo" }, { "pid": 0, "ts": 1603479130104699, "ph": "Start", "name": "timed_proc_macros::bar" }, { "pid": 0, "ts": 1603479130104700, "ph": "Start", "name": "timed_proc_macros::baz" }, { "pid": 0, "ts": 1603479130104752, "ph": "Finish", "name": "timed_proc_macros::baz" }, { "pid": 0, "ts": 1603479130104756, "ph": "Finish", "name": "timed_proc_macros::bar" }, { "pid": 0, "ts": 1603479130104760, "ph": "Start", "name": "timed_proc_macros::baz" }, { "pid": 0, "ts": 1603479130104765, "ph": "Finish", "name": "timed_proc_macros::baz" }, { "pid": 0, "ts": 1603479130104768, "ph": "Finish", "name": "timed_proc_macros::foo" } ]

It should in fact be demo_tracing::foo, not timed_proc_macros::foo

You should add this inside: quote!, I just tried:

let result = quote! { #(#attrs)* #vis #sig { #tracing_begin let start = std::time::Instant::now(); let res = { #body }; let elapsed = start.elapsed(); let path = std::module_path!(); println!("Module path {:?}", path); #print_duration #tracing_end res } };

prints:

Module path "demo_tracing"

y2kappa · 2020-10-23T19:03:11Z

timed/src/lib.rs


        match stats {
            TracingStats::None => {}
-            TracingStats::Percentage => {}
+            TracingStats::Statistics => {


Can you please sort it descending by total time? I think the most useful out of this is to know which function took longest so you know what you need to optimize.

y2kappa · 2020-10-23T19:06:37Z

tests/src/tests_tracing.rs

@@ -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);


Can you please add a separate test for this? I would like to keep this one for a single feature.

y2kappa · 2020-10-23T19:08:23Z

Thanks for this. I realise this was not fully spec'd out, sorry for the back and forth.

- moved module_path call to inside quote! - changed phase to B and E - separated statistics test

yonip23 · 2020-10-23T19:51:08Z

Thanks for this. I realise this was not fully spec'd out, sorry for the back and forth.

It's cool man, happy to help :)

… `tests_tracing.rs`

y2kappa

It looks good overall, I am happy with the decisions you took. I think removing the macro and using a builder pattern is a better pattern to use.

Also, can you please run cargo fmt and cargo clippy?

Last thing is testing: can you think of a way we could test this? Can we somehow use the closures to tracing and statistics to write into a static variable which we can inspect afterwards? I guess it would also be enough to just test the TRACES static and ensure it contains the Hops, just unit test the statistics processing based on simple inputs rather than a whole program.

Writing just a two three skeleton tests that check your newly implemented utilities is enough.

y2kappa · 2020-10-24T11:26:00Z

timed/src/lib.rs

+    Finish(Duration),
+}
+
+impl Phase {


I agree. The main purpose of these structs was originally for chrome tracing, however if it grows to enable another use case, we can parametrize how it prints out. For tracing it can print like "B" and "E". I don't know what other use case you have in mind for printing out these structs, but if there is another we can discuss. As far as it goes for now, they are only useful for chrome tracing.

y2kappa · 2020-10-24T22:00:06Z

timed/src/lib.rs

@@ -91,60 +127,99 @@ 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) {


I guess you can make it take &self and stop sending these params. Just a recommendation, not compulsory. Not sure if there is a performance impact.

y2kappa · 2020-10-24T22:01:21Z

timed/src/lib.rs

+
+impl TraceOptions {
+    pub fn new() -> TraceOptions {
+        TraceOptions {


I like this. I think this fits the builder pattern, I think you can straight away go ahead and use this https://docs.rs/derive_builder/0.9.0/derive_builder/

Also, that makes the trace_init() not necessary anymore.

I'll change it, wasn't sure that you'll like it haha

Last thing is testing: can you think of a way we could test this? Can we somehow use the closures to tracing and statistics to write into a static variable which we can inspect afterwards? I guess it would also be enough to just test the TRACES static and ensure it contains the Hops, just unit test the statistics processing based on simple inputs rather than a whole program.

Definitely, and tbh I think the closures should receive a ChromeTrace / Statistics structs instead of &strs. This will cause the whole design to 'smell' more event driven, in the sense that the closures will get notified on each new ChromeTrace entry and will act upon it as they wish.
This will also make it far more testable, asserting each ChromeTrace in the closure.

I usually work on side projects on the weekends, so feel free to checkout this branch and implement it if you find some time.

y2kappa · 2020-10-24T22:08:21Z

timed/src/lib.rs

-    fn drop(&mut self) {
-        Trace::dump(&self.id, self.processor, &self.stats);
+    fn print_statistics(processor: &fn(&str), stats_map: &HashMap<String, Vec<Duration>>, total_time_nanos: u128) {
+        struct FnStats {


I am not familiar with this idiom. Does this type definition get instantiated at every function invocation? Any reason you do not declare it above without the pub qualifier?

It's a nice feature that lets you define a struct (or any type) within a scope. I use it when the struct is only meaningful for the current scope and nowhere else, like here: FnStats only exists so I can sort the statistics later on, and nothing else. It's definition is done at compile time, just like any other struct.

- cargo fmt - removed init_tracing macro and used builder design - replace traces drop behavior with explicit call (finish)

yonip23 · 2020-10-24T23:34:21Z

timed/src/lib.rs

+    pub fn finish(self) {
+        self.dump();
+    }


When I removed the init_tracing! macro, I replaced it with let _ = Trace::new(...) in the build_named function of TracingOptions and got empty tracings, this was due to the drop that was called before it should have been called (due to my changes).

This made me think that the drop behaviour was too implicit, that's why I replaced it. Please let me know if you disagree

yep, _ has a special treatment that it drops immediately. that's why maybe it helps when it's hidden behind a macro. However, calling it _trace will make it drop at the end of the block, so that should work.

I have mixed feelings, I want a clean api and I think that combining a macro with a pseudo builder pattern is unidiomatic, a bit clunky. By any means, this is not bad feedback, I am just unsure. If we can keep macros simple and clean, all good, but if not, i'd rather keep it simple.

I do think that if you make users init the variables the normal way, most of them will use _ as a name so that makes the api not intuitive, users won't know they can rely on Drop.

I think finish is a good choice, I don't have a better idea. Forcing users to call finish will ensure they name their variables properly and therefore it doesn't drop prematurely.

Good job with this, really good stuff, thanks a lot.

yonip23 · 2020-11-11T16:46:13Z

I got drifted into a major refactor and i dont really have the time to pull this one through with all the tests etc.
So @y2kappa please, if you can take it from here that'd be great, Im happy with my results so far. I made it much more agile and generic.
To see what i intended to provide to the users, check out tests_tracing.rs, as well as the default_exts package.

If you want to discuss it further we can talk on reddit or something.

y2kappa · 2020-12-02T00:27:44Z

Will pick this up tomorrow. Sorry, has a busy period. Thanks for your work so far!

y2kappa · 2020-12-12T16:55:11Z

@yonip23 thanks for your help on this!

y2kappa · 2020-12-12T16:57:25Z

@yonip23 put a PR to add your name as author to the timed crate please

yonip23 added 3 commits October 22, 2020 23:57

added statistics to dump

7a71d92

prettyfied statistics printing + added full path to function names

aab70f3

minor changes

c6c96f5

y2kappa requested changes Oct 23, 2020

View reviewed changes

- sorted statistics print by time (desc)

fcb3c70

- moved module_path call to inside quote! - changed phase to B and E - separated statistics test

yonip23 requested a review from y2kappa October 23, 2020 19:59

changed tracing api plz dont kill me (to see the usage take a look at…

bfdfa75

… `tests_tracing.rs`

y2kappa reviewed Oct 24, 2020

View reviewed changes

changes:

a0b43ea

- cargo fmt - removed init_tracing macro and used builder design - replace traces drop behavior with explicit call (finish)

yonip23 commented Oct 24, 2020

View reviewed changes

yonip23 added 4 commits October 31, 2020 02:03

midway

b877483

temp - after statistics table

b6a9166

default exts

c07a700

i dont know what im doing...

e635f72

y2kappa added 6 commits December 7, 2020 00:37

wip

e32fc9d

clean up

ce35f9a

add current running function as well to stats and tracing

b1355c5

fmt

aa0312e

makefile and instructions

6d1905e

statistics example

7af7411

y2kappa merged commit ca1edd4 into y2kappa:master Dec 12, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

add statistics to dump #11

add statistics to dump #11

yonip23 commented Oct 22, 2020 •

edited

Loading

y2kappa Oct 23, 2020

yonip23 Oct 23, 2020

y2kappa Oct 24, 2020

y2kappa Oct 23, 2020

y2kappa Oct 23, 2020

y2kappa Oct 23, 2020

y2kappa commented Oct 23, 2020

yonip23 commented Oct 23, 2020

y2kappa left a comment

y2kappa Oct 24, 2020

y2kappa Oct 24, 2020

y2kappa Oct 24, 2020

yonip23 Oct 24, 2020

yonip23 Oct 24, 2020

y2kappa Oct 24, 2020

yonip23 Oct 24, 2020 •

edited

Loading

yonip23 Oct 24, 2020 •

edited

Loading

y2kappa Oct 25, 2020

yonip23 commented Nov 11, 2020

y2kappa commented Dec 2, 2020

y2kappa commented Dec 12, 2020

y2kappa commented Dec 12, 2020

add statistics to dump #11

add statistics to dump #11

Conversation

yonip23 commented Oct 22, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

y2kappa commented Oct 23, 2020

yonip23 commented Oct 23, 2020

y2kappa left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

yonip23 Oct 24, 2020 • edited Loading

Choose a reason for hiding this comment

yonip23 Oct 24, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

yonip23 commented Nov 11, 2020

y2kappa commented Dec 2, 2020

y2kappa commented Dec 12, 2020

y2kappa commented Dec 12, 2020

yonip23 commented Oct 22, 2020 •

edited

Loading

yonip23 Oct 24, 2020 •

edited

Loading

yonip23 Oct 24, 2020 •

edited

Loading