Skip to content

Commit

Permalink
Address comments by @jorajeev
Browse files Browse the repository at this point in the history
  • Loading branch information
sarsko committed Jan 27, 2024
1 parent 3fc910d commit 8274c09
Show file tree
Hide file tree
Showing 5 changed files with 34 additions and 14 deletions.
8 changes: 8 additions & 0 deletions src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
15 changes: 12 additions & 3 deletions src/runtime/execution.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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));

Expand Down
6 changes: 3 additions & 3 deletions src/runtime/runner.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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(),
Expand Down Expand Up @@ -101,7 +101,7 @@ impl<S: Scheduler + 'static> Runner<S> {
// 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()));

Expand Down
14 changes: 10 additions & 4 deletions src/runtime/task/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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<Span>,

// Arbitrarily settable tag which is inherited from the parent.
Expand Down
5 changes: 1 addition & 4 deletions tests/basic/tracing.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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};

Expand Down Expand Up @@ -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;
Expand Down

0 comments on commit 8274c09

Please sign in to comment.