Skip to content

Commit

Permalink
tracing: simplify common case of immediately entering the span (#1252)
Browse files Browse the repository at this point in the history
* Simplify common case of immediately entering the span

This PR allows the following API:

```
let _guard = tracing::span!("foo").entered();
```

See #1246 for an extended
discussion.

* Add missing inlines

This fns are monomorphic, so an `#[inline]` is necessary to alow
cross-crate inlining at all.

* improve method documentation

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
  • Loading branch information
matklad and hawkw committed Feb 23, 2021
1 parent 4538d74 commit a358728
Show file tree
Hide file tree
Showing 2 changed files with 259 additions and 14 deletions.
235 changes: 221 additions & 14 deletions tracing/src/span.rs
Original file line number Diff line number Diff line change
Expand Up @@ -318,6 +318,9 @@ pub use tracing_core::span::{Attributes, Id, Record};
use crate::stdlib::{
cmp, fmt,
hash::{Hash, Hasher},
marker::PhantomData,
mem,
ops::Deref,
};
use crate::{
dispatcher::{self, Dispatch},
Expand Down Expand Up @@ -381,6 +384,28 @@ pub struct Entered<'a> {
span: &'a Span,
}

/// An owned version of [`Entered`], a guard representing a span which has been
/// entered and is currently executing.
///
/// When the guard is dropped, the span will be exited.
///
/// This is returned by the [`Span::entered`] function.
///
/// [`Span::entered`]: super::Span::entered()
#[derive(Debug)]
#[must_use = "once a span has been entered, it should be exited"]
pub struct EnteredSpan {
span: Span,

/// ```compile_fail
/// use tracing::span::*;
/// trait AssertSend: Send {}
///
/// impl AssertSend for EnteredSpan {}
/// ```
_not_send: PhantomNotSend,
}

/// `log` target for all span lifecycle (creation/enter/exit/close) records.
#[cfg(feature = "log")]
const LIFECYCLE_LOG_TARGET: &str = "tracing::span";
Expand Down Expand Up @@ -745,8 +770,132 @@ impl Span {
/// [`Subscriber::enter`]: ../subscriber/trait.Subscriber.html#method.enter
/// [`Subscriber::exit`]: ../subscriber/trait.Subscriber.html#method.exit
/// [`Id`]: ../struct.Id.html
#[inline]
pub fn enter(&self) -> Entered<'_> {
if let Some(ref inner) = self.inner.as_ref() {
self.do_enter();
Entered { span: self }
}

/// Enters this span, consuming it and returning a [guard][`EnteredSpan`]
/// that will exit the span when dropped.
///
/// If this span is enabled by the current subscriber, then this function will
/// call [`Subscriber::enter`] with the span's [`Id`], and dropping the guard
/// will call [`Subscriber::exit`]. If the span is disabled, this does
/// nothing.
///
/// This is similar to the [`Span::enter`] method, except that it moves the
/// span by value into the returned guard, rather than borrowing it.
/// Therefore, this method can be used to create and enter a span in a
/// single expression, without requiring a `let`-binding. For example:
///
/// ```
/// # use tracing::info_span;
/// let _span = info_span!("something_interesting").entered();
/// ```
/// rather than:
/// ```
/// # use tracing::info_span;
/// let span = info_span!("something_interesting");
/// let _e = span.enter();
/// ```
///
/// Furthermore, `entered` may be used when the span must be stored in some
/// other struct or be passed to a function while remaining entered.
///
/// <div class="information">
/// <div class="tooltip ignore" style="">ⓘ<span class="tooltiptext">Note</span></div>
/// </div>
/// <div class="example-wrap" style="display:inline-block">
/// <pre class="ignore" style="white-space:normal;font:inherit;">
///
/// **Note**: The returned [`EnteredSpan`] guard does not
/// implement `Send`. Dropping the guard will exit *this* span,
/// and if the guard is sent to another thread and dropped there, that thread may
/// never have entered this span. Thus, `EnteredSpan`s should not be sent
/// between threads.
///
/// </pre></div>
///
/// **Warning**: in asynchronous code that uses [async/await syntax][syntax],
/// [`Span::entered`] should be used very carefully or avoided entirely. Holding
/// the drop guard returned by `Span::entered` across `.await` points will
/// result in incorrect traces. See the documentation for the
/// [`Span::enter`] method for details.
///
/// [syntax]: https://rust-lang.github.io/async-book/01_getting_started/04_async_await_primer.html
///
/// # Examples
///
/// The returned guard can be [explicitly exited][EnteredSpan::exit],
/// returning the un-entered span:
///
/// ```
/// # use tracing::{Level, span};
/// let span = span!(Level::INFO, "doing_something").entered();
///
/// // code here is within the span
///
/// // explicitly exit the span, returning it
/// let span = span.exit();
///
/// // code here is no longer within the span
///
/// // enter the span again
/// let span = span.entered();
///
/// // now we are inside the span once again
/// ```
///
/// Guards need not be explicitly dropped:
///
/// ```
/// # use tracing::trace_span;
/// fn my_function() -> String {
/// // enter a span for the duration of this function.
/// let span = trace_span!("my_function").entered();
///
/// // anything happening in functions we call is still inside the span...
/// my_other_function();
///
/// // returning from the function drops the guard, exiting the span.
/// return "Hello world".to_owned();
/// }
///
/// fn my_other_function() {
/// // ...
/// }
/// ```
///
/// Since the [`EnteredSpan`] guard can dereference to the [`Span`] itself,
/// the span may still be accessed while entered. For example:
///
/// ```rust
/// # use tracing::info_span;
/// use tracing::field;
///
/// // create the span with an empty field, and enter it.
/// let span = info_span!("my_span", some_field = field::Empty).entered();
///
/// // we can still record a value for the field while the span is entered.
/// span.record("some_field", &"hello world!");
/// ```
///
/// [`Subscriber::enter`]: ../subscriber/trait.Subscriber.html#method.enter
/// [`Subscriber::exit`]: ../subscriber/trait.Subscriber.html#method.exit
/// [`Id`]: ../struct.Id.html
#[inline]
pub fn entered(self) -> EnteredSpan {
self.do_enter();
EnteredSpan {
span: self,
_not_send: PhantomNotSend,
}
}

#[inline]
fn do_enter(&self) {
if let Some(inner) = self.inner.as_ref() {
inner.subscriber.enter(&inner.id);
}

Expand All @@ -755,8 +904,23 @@ impl Span {
self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("-> {}", meta.name()));
}
}}
}

Entered { span: self }
// Called from [`Entered`] and [`EnteredSpan`] drops.
//
// Running this behaviour on drop rather than with an explicit function
// call means that spans may still be exited when unwinding.
#[inline]
fn do_exit(&self) {
if let Some(inner) = self.inner.as_ref() {
inner.subscriber.exit(&inner.id);
}

if_log_enabled! { crate::Level::TRACE, {
if let Some(ref _meta) = self.meta {
self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {}", _meta.name()));
}
}}
}

/// Executes the given function in the context of this span.
Expand Down Expand Up @@ -1221,25 +1385,66 @@ impl Clone for Inner {

// ===== impl Entered =====

impl EnteredSpan {
/// Exits this span, returning the underlying [`Span`].
#[inline]
pub fn exit(mut self) -> Span {
// One does not simply move out of a struct with `Drop`.
let span = mem::replace(&mut self.span, Span::none());
span.do_exit();
span
}
}

impl Deref for EnteredSpan {
type Target = Span;

#[inline]
fn deref(&self) -> &Span {
&self.span
}
}

impl<'a> Drop for Entered<'a> {
#[inline]
fn drop(&mut self) {
// Dropping the guard exits the span.
//
// Running this behaviour on drop rather than with an explicit function
// call means that spans may still be exited when unwinding.
if let Some(inner) = self.span.inner.as_ref() {
inner.subscriber.exit(&inner.id);
}
self.span.do_exit()
}
}

if let Some(ref _meta) = self.span.meta {
if_log_enabled! { crate::Level::TRACE, {
self.span.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {}", _meta.name()));
}}
}
impl Drop for EnteredSpan {
#[inline]
fn drop(&mut self) {
self.span.do_exit()
}
}

/// Technically, `EnteredSpan` _can_ implement both `Send` *and*
/// `Sync` safely. It doesn't, because it has a `PhantomNotSend` field,
/// specifically added in order to make it `!Send`.
///
/// Sending an `EnteredSpan` guard between threads cannot cause memory unsafety.
/// However, it *would* result in incorrect behavior, so we add a
/// `PhantomNotSend` to prevent it from being sent between threads. This is
/// because it must be *dropped* on the same thread that it was created;
/// otherwise, the span will never be exited on the thread where it was entered,
/// and it will attempt to exit the span on a thread that may never have entered
/// it. However, we still want them to be `Sync` so that a struct holding an
/// `Entered` guard can be `Sync`.
///
/// Thus, this is totally safe.
#[derive(Debug)]
struct PhantomNotSend {
ghost: PhantomData<*mut ()>,
}
#[allow(non_upper_case_globals)]
const PhantomNotSend: PhantomNotSend = PhantomNotSend { ghost: PhantomData };

/// # Safety
///
/// Trivially safe, as `PhantomNotSend` doesn't have any API.
unsafe impl Sync for PhantomNotSend {}

#[cfg(feature = "log")]
struct FmtValues<'a>(&'a Record<'a>);

Expand Down Expand Up @@ -1281,4 +1486,6 @@ mod test {

trait AssertSync: Sync {}
impl AssertSync for Span {}
impl AssertSync for Entered<'_> {}
impl AssertSync for EnteredSpan {}
}
38 changes: 38 additions & 0 deletions tracing/tests/span.rs
Original file line number Diff line number Diff line change
Expand Up @@ -297,6 +297,44 @@ fn enter() {
handle.assert_finished();
}

#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
#[test]
fn entered() {
let (subscriber, handle) = subscriber::mock()
.enter(span::mock().named("foo"))
.event(event::mock())
.exit(span::mock().named("foo"))
.drop_span(span::mock().named("foo"))
.done()
.run_with_handle();
with_default(subscriber, || {
let _span = span!(Level::TRACE, "foo").entered();
debug!("dropping guard...");
});

handle.assert_finished();
}

#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
#[test]
fn entered_api() {
let (subscriber, handle) = subscriber::mock()
.enter(span::mock().named("foo"))
.event(event::mock())
.exit(span::mock().named("foo"))
.drop_span(span::mock().named("foo"))
.done()
.run_with_handle();
with_default(subscriber, || {
let span = span!(Level::TRACE, "foo").entered();
let _derefs_to_span = span.id();
debug!("exiting span...");
let _: Span = span.exit();
});

handle.assert_finished();
}

#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
#[test]
fn moved_field() {
Expand Down

0 comments on commit a358728

Please sign in to comment.