From 0cbf1a5adae81e8ff86ca6d040aeee67cf888262 Mon Sep 17 00:00:00 2001 From: Hayden Stainsby Date: Mon, 29 Jul 2024 12:06:13 +0200 Subject: [PATCH] time,sync: make Sleep and BatchSemaphore instrumentation explicit roots (#6727) 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. --- tokio/src/sync/batch_semaphore.rs | 1 + tokio/src/time/sleep.rs | 1 + .../tracing-instrumentation/tests/sync.rs | 2 +- .../tracing-instrumentation/tests/time.rs | 61 +++++++++++++++++++ 4 files changed, 64 insertions(+), 1 deletion(-) create mode 100644 tokio/tests/tracing-instrumentation/tests/time.rs diff --git a/tokio/src/sync/batch_semaphore.rs b/tokio/src/sync/batch_semaphore.rs index a241f7922..84f88fb39 100644 --- a/tokio/src/sync/batch_semaphore.rs +++ b/tokio/src/sync/batch_semaphore.rs @@ -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", diff --git a/tokio/src/time/sleep.rs b/tokio/src/time/sleep.rs index 9223396fe..d5a68f095 100644 --- a/tokio/src/time/sleep.rs +++ b/tokio/src/time/sleep.rs @@ -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", diff --git a/tokio/tests/tracing-instrumentation/tests/sync.rs b/tokio/tests/tracing-instrumentation/tests/sync.rs index 37d07046a..110928dda 100644 --- a/tokio/tests/tracing-instrumentation/tests/sync.rs +++ b/tokio/tests/tracing-instrumentation/tests/sync.rs @@ -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()) diff --git a/tokio/tests/tracing-instrumentation/tests/time.rs b/tokio/tests/tracing-instrumentation/tests/time.rs new file mode 100644 index 000000000..4d5701598 --- /dev/null +++ b/tokio/tests/tracing-instrumentation/tests/time.rs @@ -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(); +}