Consider adding atomic `new_span_and_enter` and `exit_and_close` span events?

[matklad]

In near/nearcore#4033 (comment), I've noticed that tracing reports spurious idle time. That is, my code looks like this:

{
  let _s = tracing::info_span("blurb").entered();
  do_important_blockchain_stuff()
}

and the logs look like this:

blurb: close time.busy=18.2ms time.idle=1.15µs

Note how the idle time is non-zero.

The reason for that is that tracing emits separate events for span exiting and span closing (and for span creation and exiting). In both callbacs, tracing calls Instant::now and the diff between the two (which is overhead of the tracing itself) gets counted as idle time.

I think the fix here is to allow atomically exit and close span, so that only one time measurement can be taken. Not sure what's the appropriate abstraction to add this API.

[hawkw]

I've also been thinking about adding a way to create and enter a span --- it would also let us avoid a tiny bit of overhead from returning from one Subscriber callback and then immediately calling into another one.

I'm not really sure what the correct API for adding this is, though.

As far as exposing it to the subscriber, maybe the Subscriber trait could have new methods with default impls, like

fn new_entered(&self, attrs: span::Attributes) -> span::Id {
   let id = self.new_span(attrs);
   self.enter(id);
   id
}

or similar? Alternatively, we could have a flag on the Attributes struct indicating that the span should be immediately entered, but that seems easier for subscriber implementations to accidentally ignore.

Alternatively to adding new methods to the subscriber trait, we could have new inherent methods on the Dispatch struct that always just call self.new_span followed by self.enter. That keeps the trait a little simpler and avoids adding new methods with default impls...but then, the question is whether or not we want user subscriber implementations to be able to have totally separate behavior for "create and enter" that isn't just immediately running the enter callback after constructing the span. I'm not sure whether or not there's a use-case for something like that.

As for the user-facing instrumentation-side API, I'm not really sure how we would want to expose this to the user. I'm not a big fan of adding a totally new set of macros that have this behavior. But, we also definitely don't want to change the behavior of the existing macros --- there are definitely cases where we want to create a span and not enter it immediately, such as when attaching it to a future using Future::instrument.

[matklad]

Having slept on this, I think there's a simpler solution for my specific problem: just define the span's total time as the interval between first enter and the last exit. So, we slice lifetime of the span into the following chunks

pre-start
busy
idle
busy
idle
busy
post-stop

ie, we just single out the two idle periods at the edges. That might be interesing: long pre-start means that executor takes a lot of time to schedule a fresh future, log post-stop might indicate that something blocks in Drop.