Skip to content

Commit a632f76

Browse files
committed
time,sync: make Sleep and BatchSemaphore instrumentation explicit roots
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.
1 parent ee8d4d1 commit a632f76

File tree

4 files changed

+64
-1
lines changed

4 files changed

+64
-1
lines changed

tokio/src/sync/batch_semaphore.rs

+1
Original file line numberDiff line numberDiff line change
@@ -147,6 +147,7 @@ impl Semaphore {
147147
#[cfg(all(tokio_unstable, feature = "tracing"))]
148148
let resource_span = {
149149
let resource_span = tracing::trace_span!(
150+
parent: None,
150151
"runtime.resource",
151152
concrete_type = "Semaphore",
152153
kind = "Sync",

tokio/src/time/sleep.rs

+1
Original file line numberDiff line numberDiff line change
@@ -267,6 +267,7 @@ impl Sleep {
267267

268268
let location = location.expect("should have location if tracing");
269269
let resource_span = tracing::trace_span!(
270+
parent: None,
270271
"runtime.resource",
271272
concrete_type = "Sleep",
272273
kind = "timer",

tokio/tests/tracing-instrumentation/tests/sync.rs

+1-1
Original file line numberDiff line numberDiff line change
@@ -60,7 +60,7 @@ async fn test_mutex_creates_span() {
6060
.new_span(mutex_span.clone().with_explicit_parent(None))
6161
.enter(mutex_span.clone())
6262
.event(locked_event)
63-
.new_span(batch_semaphore_span.clone())
63+
.new_span(batch_semaphore_span.clone().with_explicit_parent(None))
6464
.enter(batch_semaphore_span.clone())
6565
.event(batch_semaphore_permits_event)
6666
.exit(batch_semaphore_span.clone())
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,61 @@
1+
//! Tests for time resource instrumentation.
2+
//!
3+
//! These tests ensure that the instrumentation for tokio
4+
//! synchronization primitives is correct.
5+
use std::time::Duration;
6+
7+
use tracing_mock::{expect, subscriber};
8+
9+
#[tokio::test]
10+
async fn test_sleep_creates_span() {
11+
let sleep_span = expect::span()
12+
.named("runtime.resource")
13+
.with_target("tokio::time::sleep");
14+
15+
let state_update = expect::event()
16+
.with_target("runtime::resource::state_update")
17+
.with_fields(
18+
expect::field("duration")
19+
.with_value(&(7_u64 + 1))
20+
.and(expect::field("duration.op").with_value(&"override")),
21+
);
22+
23+
let async_op_span = expect::span()
24+
.named("runtime.resource.async_op")
25+
.with_target("tokio::time::sleep");
26+
27+
let async_op_poll_span = expect::span()
28+
.named("runtime.resource.async_op.poll")
29+
.with_target("tokio::time::sleep");
30+
31+
let (subscriber, handle) = subscriber::mock()
32+
.new_span(sleep_span.clone().with_explicit_parent(None))
33+
.enter(sleep_span.clone())
34+
.event(state_update)
35+
.new_span(
36+
async_op_span
37+
.clone()
38+
.with_contextual_parent(Some("runtime.resource"))
39+
.with_field(expect::field("source").with_value(&"Sleep::new_timeout")),
40+
)
41+
.exit(sleep_span.clone())
42+
.enter(async_op_span.clone())
43+
.new_span(
44+
async_op_poll_span
45+
.clone()
46+
.with_contextual_parent(Some("runtime.resource.async_op")),
47+
)
48+
.exit(async_op_span.clone())
49+
.drop_span(async_op_span)
50+
.drop_span(async_op_poll_span)
51+
.drop_span(sleep_span)
52+
.run_with_handle();
53+
54+
{
55+
let _guard = tracing::subscriber::set_default(subscriber);
56+
57+
_ = tokio::time::sleep(Duration::from_millis(7));
58+
}
59+
60+
handle.assert_finished();
61+
}

0 commit comments

Comments
 (0)