tokio: Enable trace subscriber propagation in the runtime

[hawkw]

Motivation

One of the biggest pain points in the current tokio-trace API is that
the subscriber context must be propagated manually. For example, if a
user tokio::spawns a future, the spawning thread's subscriber will not
be propagated to the worker thread the spawned future actually executes
on.

Users can currently get around this one of two ways:

• Instrument the future with a span:

   use tokio_trace_futures::Instrument;
  
   let fut = do_stuff()
       .instrument(span!("do stuff"));
   tokio::spawn(Box::new(fut));

  Since entering a span sets the dispatcher to that span's dispatcher
  while inside the span, this will both propagate the dispatcher
  context and create a span for the future. However, if the span is
  disabled, then the dispatcher will not be set, which can lead to
  surprising and unexpected behavior.
• Explicitly attach a subscriber context to the future:

  use tokio_trace_futures::WithSubscriber;
  let dispatch = tokio_trace::dispatcher::with(|current| current.clone());
  
  let fut = do_stuff()
      .instrument(span!("do stuff")) // optionally
      .with_subscriber(dispatch);
  tokio::spawn(Box::new(fut));

  This will work regardless of whether or not the future is
  instrumented with a span, and regardless of whether or not any spans
  are enabled. However, it requires some extra noise and is perhaps
  non-obvious.

Additionally, the following issues apply to both of these approaches:

• They both require the tokio-trace-futures crate, which is in the
  nursery and thus less stable than the core tokio-trace crates.
• If library code also uses tokio::spawn or similar functions (a
  reasonably common pattern!) there is nothing that user code can do
  to ensure that futures spawned by libraries also propagate the
  subscriber context correctly.

Solution

This branch modifies runtime::Builder::build so that the current
trace subscriber context is captured, and adds a call to
tokio_trace_core::dispatcher::with_default in the closure passed
to around_worker in the runtime builder's threadpool builder. This
results in the dispatcher context being propagated to all of the worker
threads in the runtime.

Notes

• This branch requires tokio to depend on tokio-trace-core.
  Therefore, we should not merge this branch until a 0.1 release of
  tokio-trace-core is published to crates.io.
• Currently, the user cannot explicitly configure the runtime to use a
  provided dispatcher. Adding a function to allow this would require a
  dependency on tokio-trace-core in tokio's public API surface,
  and I believe that we haven't yet decided that tokio-trace-core is
  stable enough for that. This can be added later.

Fixes: #947

Signed-off-by: Eliza Weisman eliza@buoyant.io

[LucioFranco]

I'm +1 on this, though would we want to put it behind a trace feature flag?

[carllerche]

@LucioFranco The thinking re: feature flag is adding a feature flag includes it permanently in the public dependency (feature flags are public).

[carllerche]

This is fine w/ me. I would like to get reviews from @seanmonstar and @stjepang.

[seanmonstar]

Is this clone required? It seems like most of the other with_default things are fine with a reference.

[hawkw]

@seanmonstar A Dispatch is internally just an Arc --- we could potentially make with_default take an &Dispatch and perform the clone itself. I thought it was better to take it by value since the dispatcher might not always need to be cloned when with_default is used in other cases`...

[carllerche]

That’s a good point. with_dispatch should probably take a ref to follow the pattern.

The fn can clone internally.

[hawkw]

I've opened #971 to make this change. As I had suspected, it has the downside of requiring the arc to be cloned twice when entering a span using the tokio-trace::Span type. If we decide this is acceptable, I can rebase onto that branch.

[carllerche]

Setting the dispatcher every time a span is entered is unexpected to me. Can you expand on that decision?

[hawkw]

@carllerche

Setting the dispatcher every time a span is entered is unexpected to me. Can you expand on that decision?

Setting the default dispatcher on span entry is a relic of when spans tracked their parent's ID. At that time, it was necessary to ensure that any spans created inside a span were observed by the same subscriber that originally provided the entered span with an ID, as otherwise, new spans would be created with parent IDs that did not originate from that subscriber.

Now that spans don't track their parent ID, this is no longer necessary. However, removing this behavior does mean that if a span is entered outside of the subscriber context it was created in, any subsequent spans will be observed by the current default subscriber and thus will not be part of the original span's trace tree. Since subscribers are not expected to change frequently, and spans are not expected to move between them, this is likely acceptable.

I've removed this on my branch for #971 in commit 345567d.

Not setting the dispatcher on entry does make span entry/exit significantly faster. Here are the results of running a benchmark that enters a span, does nothing, and immediately exits it, before this change:

test enter_span              ... bench:          93 ns/iter (+/- 14)

...and after:

test enter_span              ... bench:          51 ns/iter (+/- 9)

[hawkw]

I'm +1 on this, though would we want to put it behind a trace feature flag?

@LucioFranco The thinking re: feature flag is adding a feature flag includes it permanently in the public dependency (feature flags are public).

To expand just a little bit on Carl's comment, I just wanted to point out that since the dispatcher propagation is (currently) only done implicitly, this branch doesn't actually expose anything from tokio-trace-core in the public API surface. If Runtime users aren't using tokio-trace themselves, the added code will just silently do nothing; and since types and functions from tokio-trace-core aren't exposed publicly by tokio, any API changes in tokio-trace-core won't break code that doesn't depend on it explicitly.

In this case, the main reason users might want to disable a trace feature flag is to reduce the number of dependencies. This is valid but it's probably fine to wait until we have a public dependency on tokio-trace-core to introduce a feature flag.

[hawkw]

I've rebased this branch onto master and marked it as "ready for review", but I think we'll want to actually get a tokio-trace-core 0.1 release on crates.io prior to merging this PR (and update the dependency to use that).

[seanmonstar]

Just noting, out of context, "dispatcher" sounds like a task dispatcher, not something about traces...

[hawkw]

@seanmonstar in f409c12, I changed the way the Dispatch type and the dispatcher module are imported so that they're all namespaced as trace::dispatcher --- hopefully that's clearer!

[carllerche]

I do agree w/ sean... trace::dispatcher helps some. IMO it would be better if it was trace::subscriber, but I also know why it isn't subscriber (Dispatcher::new(subscriber)).

I'm not going to make a request either way. I just wanted to provide these thoughts to @seanmonstar and @hawkw