Skip to content

Commit c60dfa8

Browse files
matkladhawkw
andcommitted
tracing: simplify common case of immediately entering the span (#1252)
* 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 <[email protected]> Signed-off-by: Eliza Weisman <[email protected]>
1 parent 4538d74 commit c60dfa8

File tree

2 files changed

+261
-14
lines changed

2 files changed

+261
-14
lines changed

tracing/src/span.rs

Lines changed: 223 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -318,6 +318,9 @@ pub use tracing_core::span::{Attributes, Id, Record};
318318
use crate::stdlib::{
319319
cmp, fmt,
320320
hash::{Hash, Hasher},
321+
marker::PhantomData,
322+
mem,
323+
ops::Deref,
321324
};
322325
use crate::{
323326
dispatcher::{self, Dispatch},
@@ -381,6 +384,28 @@ pub struct Entered<'a> {
381384
span: &'a Span,
382385
}
383386

387+
/// An owned version of [`Entered`], a guard representing a span which has been
388+
/// entered and is currently executing.
389+
///
390+
/// When the guard is dropped, the span will be exited.
391+
///
392+
/// This is returned by the [`Span::entered`] function.
393+
///
394+
/// [`Span::entered`]: super::Span::entered()
395+
#[derive(Debug)]
396+
#[must_use = "once a span has been entered, it should be exited"]
397+
pub struct EnteredSpan {
398+
span: Span,
399+
400+
/// ```compile_fail
401+
/// use tracing::span::*;
402+
/// trait AssertSend: Send {}
403+
///
404+
/// impl AssertSend for EnteredSpan {}
405+
/// ```
406+
_not_send: PhantomNotSend,
407+
}
408+
384409
/// `log` target for all span lifecycle (creation/enter/exit/close) records.
385410
#[cfg(feature = "log")]
386411
const LIFECYCLE_LOG_TARGET: &str = "tracing::span";
@@ -745,8 +770,134 @@ impl Span {
745770
/// [`Subscriber::enter`]: ../subscriber/trait.Subscriber.html#method.enter
746771
/// [`Subscriber::exit`]: ../subscriber/trait.Subscriber.html#method.exit
747772
/// [`Id`]: ../struct.Id.html
773+
#[inline]
748774
pub fn enter(&self) -> Entered<'_> {
749-
if let Some(ref inner) = self.inner.as_ref() {
775+
self.do_enter();
776+
Entered {
777+
span: self,
778+
}
779+
}
780+
781+
/// Enters this span, consuming it and returning a [guard][`EnteredSpan`]
782+
/// that will exit the span when dropped.
783+
///
784+
/// If this span is enabled by the current subscriber, then this function will
785+
/// call [`Subscriber::enter`] with the span's [`Id`], and dropping the guard
786+
/// will call [`Subscriber::exit`]. If the span is disabled, this does
787+
/// nothing.
788+
///
789+
/// This is similar to the [`Span::enter`] method, except that it moves the
790+
/// span by value into the returned guard, rather than borrowing it.
791+
/// Therefore, this method can be used to create and enter a span in a
792+
/// single expression, without requiring a `let`-binding. For example:
793+
///
794+
/// ```
795+
/// # use tracing::info_span;
796+
/// let _span = info_span!("something_interesting").entered();
797+
/// ```
798+
/// rather than:
799+
/// ```
800+
/// # use tracing::info_span;
801+
/// let span = info_span!("something_interesting");
802+
/// let _e = span.enter();
803+
/// ```
804+
///
805+
/// Furthermore, `entered` may be used when the span must be stored in some
806+
/// other struct or be passed to a function while remaining entered.
807+
///
808+
/// <div class="information">
809+
/// <div class="tooltip ignore" style="">ⓘ<span class="tooltiptext">Note</span></div>
810+
/// </div>
811+
/// <div class="example-wrap" style="display:inline-block">
812+
/// <pre class="ignore" style="white-space:normal;font:inherit;">
813+
///
814+
/// **Note**: The returned [`EnteredSpan`] guard does not
815+
/// implement `Send`. Dropping the guard will exit *this* span,
816+
/// and if the guard is sent to another thread and dropped there, that thread may
817+
/// never have entered this span. Thus, `EnteredSpan`s should not be sent
818+
/// between threads.
819+
///
820+
/// </pre></div>
821+
///
822+
/// **Warning**: in asynchronous code that uses [async/await syntax][syntax],
823+
/// [`Span::entered`] should be used very carefully or avoided entirely. Holding
824+
/// the drop guard returned by `Span::entered` across `.await` points will
825+
/// result in incorrect traces. See the documentation for the
826+
/// [`Span::enter`] method for details.
827+
///
828+
/// [syntax]: https://rust-lang.github.io/async-book/01_getting_started/04_async_await_primer.html
829+
///
830+
/// # Examples
831+
///
832+
/// The returned guard can be [explicitly exited][EnteredSpan::exit],
833+
/// returning the un-entered span:
834+
///
835+
/// ```
836+
/// # use tracing::{Level, span};
837+
/// let span = span!(Level::INFO, "doing_something").entered();
838+
///
839+
/// // code here is within the span
840+
///
841+
/// // explicitly exit the span, returning it
842+
/// let span = span.exit();
843+
///
844+
/// // code here is no longer within the span
845+
///
846+
/// // enter the span again
847+
/// let span = span.entered();
848+
///
849+
/// // now we are inside the span once again
850+
/// ```
851+
///
852+
/// Guards need not be explicitly dropped:
853+
///
854+
/// ```
855+
/// # use tracing::trace_span;
856+
/// fn my_function() -> String {
857+
/// // enter a span for the duration of this function.
858+
/// let span = trace_span!("my_function").entered();
859+
///
860+
/// // anything happening in functions we call is still inside the span...
861+
/// my_other_function();
862+
///
863+
/// // returning from the function drops the guard, exiting the span.
864+
/// return "Hello world".to_owned();
865+
/// }
866+
///
867+
/// fn my_other_function() {
868+
/// // ...
869+
/// }
870+
/// ```
871+
///
872+
/// Since the [`EnteredSpan`] guard can dereference to the [`Span`] itself,
873+
/// the span may still be accessed while entered. For example:
874+
///
875+
/// ```rust
876+
/// # use tracing::info_span;
877+
/// use tracing::field;
878+
///
879+
/// // create the span with an empty field, and enter it.
880+
/// let span = info_span!("my_span", some_field = field::Empty).entered();
881+
///
882+
/// // we can still record a value for the field while the span is entered.
883+
/// span.record("some_field", &"hello world!");
884+
/// ```
885+
///
886+
/// [`Subscriber::enter`]: ../subscriber/trait.Subscriber.html#method.enter
887+
/// [`Subscriber::exit`]: ../subscriber/trait.Subscriber.html#method.exit
888+
/// [`Id`]: ../struct.Id.html
889+
#[inline]
890+
pub fn entered(self) -> EnteredSpan {
891+
self.do_enter();
892+
EnteredSpan {
893+
span: self,
894+
_not_send: PhantomNotSend,
895+
}
896+
}
897+
898+
#[inline]
899+
fn do_enter(&self) {
900+
if let Some(inner) = self.inner.as_ref() {
750901
inner.subscriber.enter(&inner.id);
751902
}
752903

@@ -755,8 +906,23 @@ impl Span {
755906
self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("-> {}", meta.name()));
756907
}
757908
}}
909+
}
758910

759-
Entered { span: self }
911+
// Called from [`Entered`] and [`EnteredSpan`] drops.
912+
//
913+
// Running this behaviour on drop rather than with an explicit function
914+
// call means that spans may still be exited when unwinding.
915+
#[inline]
916+
fn do_exit(&self) {
917+
if let Some(inner) = self.inner.as_ref() {
918+
inner.subscriber.exit(&inner.id);
919+
}
920+
921+
if_log_enabled! { crate::Level::TRACE, {
922+
if let Some(ref _meta) = self.meta {
923+
self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {}", _meta.name()));
924+
}
925+
}}
760926
}
761927

762928
/// Executes the given function in the context of this span.
@@ -1221,25 +1387,66 @@ impl Clone for Inner {
12211387

12221388
// ===== impl Entered =====
12231389

1390+
impl EnteredSpan {
1391+
/// Exits this span, returning the underlying [`Span`].
1392+
#[inline]
1393+
pub fn exit(mut self) -> Span {
1394+
// One does not simply move out of a struct with `Drop`.
1395+
let span = mem::replace(&mut self.span, Span::none());
1396+
span.do_exit();
1397+
span
1398+
}
1399+
}
1400+
1401+
impl Deref for EnteredSpan {
1402+
type Target = Span;
1403+
1404+
#[inline]
1405+
fn deref(&self) -> &Span {
1406+
&self.span
1407+
}
1408+
}
1409+
12241410
impl<'a> Drop for Entered<'a> {
12251411
#[inline]
12261412
fn drop(&mut self) {
1227-
// Dropping the guard exits the span.
1228-
//
1229-
// Running this behaviour on drop rather than with an explicit function
1230-
// call means that spans may still be exited when unwinding.
1231-
if let Some(inner) = self.span.inner.as_ref() {
1232-
inner.subscriber.exit(&inner.id);
1233-
}
1413+
self.span.do_exit()
1414+
}
1415+
}
12341416

1235-
if let Some(ref _meta) = self.span.meta {
1236-
if_log_enabled! { crate::Level::TRACE, {
1237-
self.span.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {}", _meta.name()));
1238-
}}
1239-
}
1417+
impl Drop for EnteredSpan {
1418+
#[inline]
1419+
fn drop(&mut self) {
1420+
self.span.do_exit()
12401421
}
12411422
}
12421423

1424+
/// Technically, `EnteredSpan` _can_ implement both `Send` *and*
1425+
/// `Sync` safely. It doesn't, because it has a `PhantomNotSend` field,
1426+
/// specifically added in order to make it `!Send`.
1427+
///
1428+
/// Sending an `EnteredSpan` guard between threads cannot cause memory unsafety.
1429+
/// However, it *would* result in incorrect behavior, so we add a
1430+
/// `PhantomNotSend` to prevent it from being sent between threads. This is
1431+
/// because it must be *dropped* on the same thread that it was created;
1432+
/// otherwise, the span will never be exited on the thread where it was entered,
1433+
/// and it will attempt to exit the span on a thread that may never have entered
1434+
/// it. However, we still want them to be `Sync` so that a struct holding an
1435+
/// `Entered` guard can be `Sync`.
1436+
///
1437+
/// Thus, this is totally safe.
1438+
#[derive(Debug)]
1439+
struct PhantomNotSend {
1440+
ghost: PhantomData<*mut ()>,
1441+
}
1442+
#[allow(non_upper_case_globals)]
1443+
const PhantomNotSend: PhantomNotSend = PhantomNotSend { ghost: PhantomData };
1444+
1445+
/// # Safety
1446+
///
1447+
/// Trivially safe, as `PhantomNotSend` doesn't have any API.
1448+
unsafe impl Sync for PhantomNotSend {}
1449+
12431450
#[cfg(feature = "log")]
12441451
struct FmtValues<'a>(&'a Record<'a>);
12451452

@@ -1281,4 +1488,6 @@ mod test {
12811488

12821489
trait AssertSync: Sync {}
12831490
impl AssertSync for Span {}
1491+
impl AssertSync for Entered<'_> {}
1492+
impl AssertSync for EnteredSpan {}
12841493
}

tracing/tests/span.rs

Lines changed: 38 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -297,6 +297,44 @@ fn enter() {
297297
handle.assert_finished();
298298
}
299299

300+
#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
301+
#[test]
302+
fn entered() {
303+
let (subscriber, handle) = subscriber::mock()
304+
.enter(span::mock().named("foo"))
305+
.event(event::mock())
306+
.exit(span::mock().named("foo"))
307+
.drop_span(span::mock().named("foo"))
308+
.done()
309+
.run_with_handle();
310+
with_default(subscriber, || {
311+
let _span = span!(Level::TRACE, "foo").entered();
312+
debug!("dropping guard...");
313+
});
314+
315+
handle.assert_finished();
316+
}
317+
318+
#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
319+
#[test]
320+
fn entered_api() {
321+
let (subscriber, handle) = subscriber::mock()
322+
.enter(span::mock().named("foo"))
323+
.event(event::mock())
324+
.exit(span::mock().named("foo"))
325+
.drop_span(span::mock().named("foo"))
326+
.done()
327+
.run_with_handle();
328+
with_default(subscriber, || {
329+
let span = span!(Level::TRACE, "foo").entered();
330+
let _derefs_to_span = span.id();
331+
debug!("exiting span...");
332+
let _: Span = span.exit();
333+
});
334+
335+
handle.assert_finished();
336+
}
337+
300338
#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
301339
#[test]
302340
fn moved_field() {

0 commit comments

Comments
 (0)