Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Print the duration of the span when closing a span #17

Open
oli-obk opened this issue Aug 17, 2020 · 2 comments
Open

Print the duration of the span when closing a span #17

oli-obk opened this issue Aug 17, 2020 · 2 comments

Comments

@oli-obk
Copy link
Collaborator

oli-obk commented Aug 17, 2020

* 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 🤦

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.

@davidbarsky
Copy link
Owner

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.

@oli-obk
Copy link
Collaborator Author

oli-obk commented Aug 18, 2020

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants