Partially revert some tracing changes and make a few more (#31)

In ba014d6 we changed our tracing spans to use Level::ERROR, but that
had an unexpected side effect: tracing's default env filter includes the
ERROR level, so these spans are always constructed even when we don't
actually want/see any log output. That has a massive performance impact
on large tests, so we need to fix that.

This change instead sets a new hierarchy where all Shuttle's internal
tracing events are at Level::TRACE, and its spans and metrics outputs
are at Level::DEBUG. This means clients can still see our spans without
seeing our tracing output, and also avoids constructing any spans in the
common case where no tracing output is desired.

src/runtime/execution.rs

@@ -12,7 +12,7 @@ use std::panic;
 use std::rc::Rc;
 use std::task::{Context, Poll};
 use tracing::span::Entered;
-use tracing::{debug, span, Level, Span};
+use tracing::{span, trace, Level, Span};
 
 // We use this scoped TLS to smuggle the ExecutionState, which is not 'static, across tasks that
 // need access to it (to spawn new tasks, interrogate task status, etc).
@@ -401,7 +401,7 @@ impl ExecutionState {
             .map(ScheduledTask::Some)
             .unwrap_or(ScheduledTask::Stopped);
 
-        debug!(?runnable, next_task=?self.next_task);
+        trace!(?runnable, next_task=?self.next_task);
     }
 
     /// Set the next task as the current task, and update our tracing span
@@ -419,7 +419,7 @@ impl ExecutionState {
         // `self.current_span_entered` before dropping the `self.current_span` it points to.
         self.current_span_entered.take();
         if let ScheduledTask::Some(tid) = self.current_task {
-            self.current_span = span!(Level::ERROR, "step", i = self.current_schedule.len() - 1, task = tid.0);
+            self.current_span = span!(Level::INFO, "step", i = self.current_schedule.len() - 1, task = tid.0);
             self.current_span_entered = Some(unsafe { extend_span_entered_lt(self.current_span.enter()) });
         }
     }

src/runtime/runner.rs

@@ -63,7 +63,7 @@ impl<S: Scheduler + 'static> Runner<S> {
 
                 let execution = Execution::new(self.scheduler.clone(), schedule);
                 let f = Arc::clone(&f);
-                span!(Level::ERROR, "execution", i).in_scope(|| execution.run(&self.config, move || f()));
+                span!(Level::INFO, "execution", i).in_scope(|| execution.run(&self.config, move || f()));
 
                 i += 1;
             }
@@ -130,7 +130,7 @@ impl PortfolioRunner {
 
                     let runner = Runner::new(scheduler, config);
 
-                    span!(Level::ERROR, "job", i).in_scope(|| {
+                    span!(Level::INFO, "job", i).in_scope(|| {
                         let ret = panic::catch_unwind(panic::AssertUnwindSafe(|| runner.run(f)));
 
                         match ret {

tests/basic/mutex.rs

@@ -3,7 +3,6 @@ use shuttle::sync::Mutex;
 use shuttle::{check, check_random, thread, Runner};
 use std::sync::Arc;
 use test_env_log::test;
-use tracing::info;
 
 #[test]
 fn basic_lock_test() {
@@ -87,7 +86,6 @@ fn concurrent_increment_buggy() {
         }
 
         let counter = *lock.lock().unwrap();
-        info!(counter);
         assert_eq!(counter, 2, "racing increments");
     });
 }