Skip to content

Commit

Permalink
time,sync: make Sleep and BatchSemaphore instrumentation explicit roots
Browse files Browse the repository at this point in the history
When instrumenting resources in Tokio, a span is created for each
resource. Previously, all resources inherited the currently active span
as their parent (tracing default). However, this would keep that parent
span alive until the resource (and its span) were dropped. This is often
not correct, as a resource may be created in a task and then sent
elsewhere, while the originating task ends.

This artificial extension of the parent span's lifetime would make it
look like that task was still alive (but idle) in any system reading the
tracing instrumentation in Tokio, for example Tokio Console as reported
in tokio-rs/console#345.

In #6107, most of the existing resource spans were updated to
make them explicit roots, so they have no contextual parent. However,
2. were missed:
- `Sleep`
- `BatchSemaphore`

This change alters the resource spans for those 2 resources to also make
them explicit roots.

(so that the span doesn't have a parent). This
is necessary, because otherwise a resource that is created inside a task
(or some other span) and then sent elsewhere will keep that contextual
parent span open (but not necessarily active) for the lifetime of the
resource itself.
  • Loading branch information
hds committed Jul 26, 2024
1 parent ee8d4d1 commit cac89fe
Show file tree
Hide file tree
Showing 4 changed files with 64 additions and 1 deletion.
1 change: 1 addition & 0 deletions tokio/src/sync/batch_semaphore.rs
Original file line number Diff line number Diff line change
Expand Up @@ -147,6 +147,7 @@ impl Semaphore {
#[cfg(all(tokio_unstable, feature = "tracing"))]
let resource_span = {
let resource_span = tracing::trace_span!(
parent: None,
"runtime.resource",
concrete_type = "Semaphore",
kind = "Sync",
Expand Down
1 change: 1 addition & 0 deletions tokio/src/time/sleep.rs
Original file line number Diff line number Diff line change
Expand Up @@ -267,6 +267,7 @@ impl Sleep {

let location = location.expect("should have location if tracing");
let resource_span = tracing::trace_span!(
parent: None,
"runtime.resource",
concrete_type = "Sleep",
kind = "timer",
Expand Down
2 changes: 1 addition & 1 deletion tokio/tests/tracing-instrumentation/tests/sync.rs
Original file line number Diff line number Diff line change
Expand Up @@ -60,7 +60,7 @@ async fn test_mutex_creates_span() {
.new_span(mutex_span.clone().with_explicit_parent(None))
.enter(mutex_span.clone())
.event(locked_event)
.new_span(batch_semaphore_span.clone())
.new_span(batch_semaphore_span.clone().with_explicit_parent(None))
.enter(batch_semaphore_span.clone())
.event(batch_semaphore_permits_event)
.exit(batch_semaphore_span.clone())
Expand Down
61 changes: 61 additions & 0 deletions tokio/tests/tracing-instrumentation/tests/time.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,61 @@
//! Tests for time resource instrumentation.
//!
//! These tests ensure that the instrumentation for tokio
//! synchronization primitives is correct.
use std::time::Duration;

use tracing_mock::{expect, subscriber};

#[tokio::test]
async fn test_sleep_creates_span() {
let sleep_span = expect::span()
.named("runtime.resource")
.with_target("tokio::time::sleep");

let state_update = expect::event()
.with_target("runtime::resource::state_update")
.with_fields(
expect::field("duration")
.with_value(&(7_u64 + 1))
.and(expect::field("duration.op").with_value(&"override")),
);

let async_op_span = expect::span()
.named("runtime.resource.async_op")
.with_target("tokio::time::sleep");

let async_op_poll_span = expect::span()
.named("runtime.resource.async_op.poll")
.with_target("tokio::time::sleep");

let (subscriber, handle) = subscriber::mock()
.new_span(sleep_span.clone().with_explicit_parent(None))
.enter(sleep_span.clone())
.event(state_update)
.new_span(
async_op_span
.clone()
.with_contextual_parent(Some("runtime.resource"))
.with_field(expect::field("source").with_value(&"Sleep::new_timeout")),
)
.exit(sleep_span.clone())
.enter(async_op_span.clone())
.new_span(
async_op_poll_span
.clone()
.with_contextual_parent(Some("runtime.resource.async_op")),
)
.exit(async_op_span.clone())
.drop_span(async_op_span)
.drop_span(async_op_poll_span)
.drop_span(sleep_span)
.run_with_handle();

{
let _guard = tracing::subscriber::set_default(subscriber);

_ = tokio::time::sleep(Duration::from_millis(7));
}

handle.assert_finished();
}

0 comments on commit cac89fe

Please sign in to comment.