jonhoo / tracing-timing

Inter-event timing metrics on top of tracing.
112 stars 11 forks source link

The current starting experience is not user friendly #17

Open Stargateur opened 2 years ago

Stargateur commented 2 years ago

The crate does not implement a mechanism for recording the resulting histograms. Instead, you can implement this as you see fit using TimingSubscriber::with_histograms.

From my point of view of total noob of this crate, this is very harsh for new user to say "do it yourself", specially:

It gives you access to the histograms for all groups. Note that you must call refresh() on each histogram to see its latest values (see hdrhistogram::SyncHistogram). Note that calling refresh() will block until the next event is posted, so you may want TimingSubscriber::force_synchronize instead.

Look like it's easy to mess up. While I understand the point of not implement any form of output I think have a "Q&D" way build-in would be a big plus. I think having a simple Debug alternative implementation would be nice to have, something that is not guarantee to not change but still allow to not deal with https://github.com/jonhoo/tracing-timing/blob/main/examples/pretty.rs code, you ask user to downcast and manipulate very low level api here.

denosaurtrain commented 1 year ago

When I first used this library a few months ago, I somehow managed to deadlock on both refresh() and refresh_timeout(). There is a bug there for sure, but when I went to fix it, I realized that I completely failed to grok the purpose of this library: I expected a histogram of span timings, rather than a histogram of time between events. (Completely my fault for failing to read the docs closely.)

Is there a downside to creating nested spans that I'm not seeing? Is there another crate that already supports this?

That is, why this...

trace_span!("request").in_scope(|| {
    std::thread::sleep(fast);
    trace!("fast");
    std::thread::sleep(slow);
    trace!("slow");
});

...instead of this...

trace_span!("request").in_scope(|| {
    trace_span!("fast").in_scope(|| std::thread::sleep(fast));
    trace_span!("slow").in_scope(|| std::thread::sleep(slow));
});

For trace/debug-level functions instrumented with tracing-attributes, I often want a subscriber/layer that exposes a histogram of the functions' execution time rather than logging each execution. When I need more granular timings, I create more spans or instrument more functions. I have my own subscriber/layer mechanism that kinda/sorta works, but I'm curious how others are doing it, and whether that fits into this crate or something else.

akshayknarayan commented 1 year ago

@denosaurtrain you may find the following two configuration options useful:

jonhoo commented 1 year ago

Sorry for the silence here — tracing-timing is a bit on the backburner at the moment. I would love for the starting experience to be better, though have limited time at the moment to make that happen myself (sadly). If any of you want to take a stab at adding a impl Debug, extending the examples, and maybe even making the interface harder to get wrong (especially with regards to deadlocks, which are a pain), I would be happy to take a look at some PRs!