From 8274c0977a1cd7285b77b79783ab9b4b4cc54893 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Sarek=20H=C3=B8verstad=20Skot=C3=A5m?= Date: Fri, 26 Jan 2024 19:23:09 -0800 Subject: [PATCH] Address comments by @jorajeev --- src/lib.rs | 8 ++++++++ src/runtime/execution.rs | 15 ++++++++++++--- src/runtime/runner.rs | 6 +++--- src/runtime/task/mod.rs | 14 ++++++++++---- tests/basic/tracing.rs | 5 +---- 5 files changed, 34 insertions(+), 14 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index d1b637e..04905dc 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -223,6 +223,14 @@ pub struct Config { /// Whether to call the `Span::record()` method to update the step count (`i`) of the `Span` /// containing the `TaskId` and the current step count for the given `TaskId`. + /// If `false`, this `Span` will look like this: `step{task=1}`, and if `true`, this `Span` + /// will look something like this: `step{task=1 i=3 i=9 i=12}`, or, if a `Subscriber` which + /// overwrites on calls to `span.record()` is used, something like this: + /// ```no_run + /// step{task=1 i=3} + /// step{task=1 i=9} + /// step{task=1 i=12} + /// ``` /// The reason this is a config option is that the most popular tracing `Subscriber`s, ie /// `tracing_subscriber::fmt`, appends to the span on calls to `record()` (instead of /// overwriting), which results in traces which are hard to read if the task is scheduled more diff --git a/src/runtime/execution.rs b/src/runtime/execution.rs index 89614cf..ed6af50 100644 --- a/src/runtime/execution.rs +++ b/src/runtime/execution.rs @@ -145,15 +145,19 @@ impl Execution { let ret = match next_step { NextStep::Task(continuation) => { // Enter the Task's span - // Note that if any issues arises with spans and tracing, then calling `exit` until `None`, - // storing the entirety of the `span_stack` when creating the `Task` and storing - // `top_level_span` as a stack should be tried. + // (Note that if any issues arise with spans and tracing, then + // 1) calling `exit` until `None` before entering the `Task`s `Span`, + // 2) storing the entirety of the `span_stack` when creating the `Task`, and + // 3) storing `top_level_span` as a stack + // should be tried.) ExecutionState::with(|state| { tracing::dispatcher::get_default(|subscriber| { if let Some(span_id) = tracing::Span::current().id().as_ref() { subscriber.exit(span_id); } + // The `span_stack` stores `Span`s such that the top of the stack is the outermost `Span`, + // meaning that parents (left-most when printed) are entered first. while let Some(span) = state.current_mut().span_stack.pop() { if let Some(span_id) = span.id().as_ref() { subscriber.enter(span_id) @@ -642,6 +646,11 @@ impl ExecutionState { } } + // Tracing this `in_scope` is purely a matter of taste. We do it because + // 1) It is an action taken by the scheduler, and should thus be traced under the scheduler's span + // 2) It creates a visual separation of scheduling decisions and `Task`-induced tracing. + // Note that there is a case to be made for not `in_scope`-ing it, as that makes seeing the context + // of the context switch clearer. self.top_level_span .in_scope(|| trace!(?runnable, next_task=?self.next_task)); diff --git a/src/runtime/runner.rs b/src/runtime/runner.rs index d61b1ca..fdcf5c1 100644 --- a/src/runtime/runner.rs +++ b/src/runtime/runner.rs @@ -16,15 +16,15 @@ use std::time::Instant; use tracing::{span, Level}; // A helper struct which on `drop` exits all current spans, then enters the span which was entered when it was constructed. -// The reason this exist is to solve the "span-stacking" issue which occurs when there is a panic inside `run` which is +// The reason this exists is to solve the "span-stacking" issue which occurs when there is a panic inside `run` which is // then caught by `panic::catch_unwind()` (such as when Shuttle is run inside proptest). // In other words: it enables correct spans when doing proptest minimization. +#[must_use] struct ResetSpanOnDrop { span: tracing::Span, } impl ResetSpanOnDrop { - #[must_use] fn new() -> Self { Self { span: tracing::Span::current().clone(), @@ -101,7 +101,7 @@ impl Runner { // This is a slightly lazy way to ensure that everything outside of the "execution" span gets // established correctly between executions. Fully `exit`ing and fully `enter`ing (explicitly // `enter`/`exit` all `Span`s) would most likely obviate the need for this. - let _rsod = ResetSpanOnDrop::new(); + let _span_drop_guard2 = ResetSpanOnDrop::new(); span!(Level::ERROR, "execution", i).in_scope(|| execution.run(&self.config, move || f())); diff --git a/src/runtime/task/mod.rs b/src/runtime/task/mod.rs index efc12a9..7a385a6 100644 --- a/src/runtime/task/mod.rs +++ b/src/runtime/task/mod.rs @@ -91,14 +91,20 @@ pub(crate) struct Task { local_storage: StorageMap, - // The `Span` containing the `Task`s `id` and the current step count (if step count recording is enabled) + // The `Span` which looks like this: step{task=task_id}, or, if step count recording is enabled, like this: + // step{task=task_id i=step_count}. Becomes the parent of the spans created by the `Task`. pub(super) step_span: Span, - // The current `Span` "stack" of the `Task`. There are two things to note: + + // The current `Span` "stack" of the `Task`. + // `Span`s are stored such that the `Task`s current `Span` is at `span_stack[0]`, that `Span`s parent (if it exists) + // is at `span_stack[1]`, and so on, until `span_stack[span_stack.len()-1]`, which is the "outermost" (left-most when printed) + // `Span`. This means that `span_stack[span_stack.len()-1]` will usually be the `Span` saying `execution{i=X}`. + // We `pop` it empty when resuming a `Task`, and `push` + `exit` `tracing::Span::current()` + // until there is no entered `Span` when we switch out of the `Task`. + // There are two things to note: // 1: We have to own the `Span`s (versus storing `Id`s) for the `Span` to not get dropped while the task is switched out. // 2: We have to store the stack of `Span`s in order to return to the correct `Span` once the `Entered<'_>` from an // `instrument`ed future is dropped. - // `span_stack` is (as the name suggests) a stack. We `pop` it empty when resuming a `Task`, and `push` + `exit` - // `tracing::Span::current()` until there is no entered `Span` when we switch out of the `Task`. pub(super) span_stack: Vec, // Arbitrarily settable tag which is inherited from the parent. diff --git a/tests/basic/tracing.rs b/tests/basic/tracing.rs index 1fdeb64..8f24603 100644 --- a/tests/basic/tracing.rs +++ b/tests/basic/tracing.rs @@ -3,7 +3,6 @@ use proptest::test_runner::Config; use shuttle::future::spawn; use shuttle::sync::{Arc, Mutex}; use shuttle::{check_random, thread}; -use std::time::Duration; use test_log::test; use tracing::{instrument::Instrument, warn, warn_span}; @@ -95,9 +94,7 @@ async fn spawn_instrumented_futures() { spawn(async { let span_id = tracing::Span::current().id(); async { - // NOTE: Just a way to get a `thread::switch` call. - // Consider `pub`ing `thread::switch` ? - thread::sleep(Duration::from_millis(0)); + thread::yield_now(); } .instrument(warn_span!("Span")) .await;