tracing-tree
tracing-tree copied to clipboard
Print the duration of the span when closing a span
* I'd like to be able to visually distinguish between a span that has _exited_ and a span that has _closed_. That could be done with durations, but that's not the only approach. * As I'm writing this comment, I remembered that tracing-tree isn't really used with asynchronous or non-blocking code. Therefore, I'm not sure how useful this feature is _in the first place_. * One idea I had was to use durations from the _start_ of the span. However, after thinking about it a bit more, I realized that this opens a larger design space that's best discussed in a separate issue. I'd prefer to _not_ block merging this PR on that point.In the latter case we have to store the opening somewhere, any tips?
Sure! Here's the approach I was thinking of:
* `new_span` creates a [`DateTime<Local>`](https://github.com/davidbarsky/tracing-tree/blob/main/src/lib.rs#L23). Nothing needs to change here. * In an `on_exit` or `on_close` method, copy [this approach](https://github.com/davidbarsky/tracing-tree/blob/6a81afb008ac2af974620d06491376c329c04893/src/lib.rs#L269-L282) to calculate the elapsed time of the span.
I did not realize all timings are from the start of the current span. I thought they were from the start of the program :facepalm:
Ok, this seems easy enough to do. Though I'm now also wondering if the start of a span should also have a timing printed, basically giving the time from the start of its parent span.
Thanks for opening this!
I did not realize all timings are from the start of the current span. I thought they were from the start of the program 🤦
No worries! I think this is also doable by borrowing the implementation of tracing_subscriber::fmt::time::Uptime. The "start" can be stored as a field in the layer. I would expect that the time between the the creation of the layer and the first event would be pretty short, thankfully.
Though I'm now also wondering if the start of a span should also have a timing printed, basically giving the time from the start of its parent span.
I think I experimented with this a while ago, but I didn't find it to be particularly useful because I've noticed in the codebases I'm responsible for, there's virtually no delay between creating and entering a span. I'm open to be convinced on this, especially if Chalk/rustc/Miri have different span creation patterns.
I think I experimented with this a while ago, but I didn't find it to be particularly useful because I've noticed in the codebases I'm responsible for, there's virtually no delay between creating and entering a span. I'm open to be convinced on this, especially if Chalk/rustc/Miri have different span creation patterns.
Ah, that's not what I meant. I meant printing the time within the parent span. So if we enter a span, that span entering has currently no time offset to the parent, but every event in the parent would have had one. If there was a long time since the last event in the parent span, the information when the new span was entered relative to it may be of interest to the users.