Skip to content

Commit 13cdc41

Browse files
matkladhawkw
andcommitted
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 a0201ba commit 13cdc41

File tree

2 files changed

+268
-22
lines changed

2 files changed

+268
-22
lines changed

tracing/src/span.rs

Lines changed: 230 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -314,15 +314,17 @@
314314
//! [guard]: struct.Entered.html
315315
//! [parent]: #span-relationships
316316
pub use tracing_core::span::{Attributes, Id, Record};
317-
318-
use crate::stdlib::{
319-
cmp, fmt,
320-
hash::{Hash, Hasher},
321-
};
322317
use crate::{
323318
dispatcher::{self, Dispatch},
324319
field, Metadata,
325320
};
321+
use crate::stdlib::{
322+
cmp, fmt,
323+
hash::{Hash, Hasher},
324+
marker::PhantomData,
325+
mem,
326+
ops::Deref,
327+
};
326328

327329
/// Trait implemented by types which have a span `Id`.
328330
pub trait AsId: crate::sealed::Sealed {
@@ -381,6 +383,28 @@ pub struct Entered<'a> {
381383
span: &'a Span,
382384
}
383385

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

@@ -755,8 +905,23 @@ impl Span {
755905
self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("-> {}", meta.name()));
756906
}
757907
}}
908+
}
758909

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

762927
/// Executes the given function in the context of this span.
@@ -1221,25 +1386,66 @@ impl Clone for Inner {
12211386

12221387
// ===== impl Entered =====
12231388

1389+
impl EnteredSpan {
1390+
/// Exits this span, returning the underlying [`Span`].
1391+
#[inline]
1392+
pub fn exit(mut self) -> Span {
1393+
// One does not simply move out of a struct with `Drop`.
1394+
let span = mem::replace(&mut self.span, Span::none());
1395+
span.do_exit();
1396+
span
1397+
}
1398+
}
1399+
1400+
impl Deref for EnteredSpan {
1401+
type Target = Span;
1402+
1403+
#[inline]
1404+
fn deref(&self) -> &Span {
1405+
&self.span
1406+
}
1407+
}
1408+
12241409
impl<'a> Drop for Entered<'a> {
12251410
#[inline]
12261411
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-
}
1412+
self.span.do_exit()
1413+
}
1414+
}
12341415

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-
}
1416+
impl Drop for EnteredSpan {
1417+
#[inline]
1418+
fn drop(&mut self) {
1419+
self.span.do_exit()
12401420
}
12411421
}
12421422

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

@@ -1281,4 +1487,6 @@ mod test {
12811487

12821488
trait AssertSync: Sync {}
12831489
impl AssertSync for Span {}
1490+
impl AssertSync for Entered<'_> {}
1491+
impl AssertSync for EnteredSpan {}
12841492
}

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)