Auto merge of #3348 - RalfJung:miri-thread-logging, r=RalfJung

log when we change the active thread, and fix logging for concurrency

Also avoid relying on the incorrect scope exit logging produced by tracing (Cc #2266)

src/bin/miri.rs

@@ -202,16 +202,12 @@ fn rustc_logger_config() -> rustc_log::LoggerConfig {
             // rustc traced, but you can also do `MIRI_LOG=miri=trace,rustc_const_eval::interpret=debug`.
             if tracing::Level::from_str(&var).is_ok() {
                 cfg.filter = Ok(format!(
-                    "rustc_middle::mir::interpret={var},rustc_const_eval::interpret={var}"
+                    "rustc_middle::mir::interpret={var},rustc_const_eval::interpret={var},miri={var}"
                 ));
             } else {
                 cfg.filter = Ok(var);
             }
         }
-        // Enable verbose entry/exit logging by default if MIRI_LOG is set.
-        if matches!(cfg.verbose_entry_exit, Err(VarError::NotPresent)) {
-            cfg.verbose_entry_exit = Ok(format!("1"));
-        }
     }
 
     cfg

src/concurrency/thread.rs

@@ -445,10 +445,13 @@ impl<'mir, 'tcx: 'mir> ThreadManager<'mir, 'tcx> {
 
     /// Set an active thread and return the id of the thread that was active before.
     fn set_active_thread_id(&mut self, id: ThreadId) -> ThreadId {
-        let active_thread_id = self.active_thread;
-        self.active_thread = id;
-        assert!(self.active_thread.index() < self.threads.len());
-        active_thread_id
+        assert!(id.index() < self.threads.len());
+        info!(
+            "---------- Now executing on thread `{}` (previous: `{}`) ----------------------------------------",
+            self.get_thread_display_name(id),
+            self.get_thread_display_name(self.active_thread)
+        );
+        std::mem::replace(&mut self.active_thread, id)
     }
 
     /// Get the id of the currently active thread.
@@ -735,6 +738,11 @@ impl<'mir, 'tcx: 'mir> ThreadManager<'mir, 'tcx> {
         for (id, thread) in threads {
             debug_assert_ne!(self.active_thread, id);
             if thread.state == ThreadState::Enabled {
+                info!(
+                    "---------- Now executing on thread `{}` (previous: `{}`) ----------------------------------------",
+                    self.get_thread_display_name(id),
+                    self.get_thread_display_name(self.active_thread)
+                );
                 self.active_thread = id;
                 break;
             }

src/machine.rs

@@ -1454,13 +1454,17 @@ impl<'mir, 'tcx> Machine<'mir, 'tcx> for MiriMachine<'mir, 'tcx> {
         if ecx.machine.borrow_tracker.is_some() {
             ecx.on_stack_pop(frame)?;
         }
+        // tracing-tree can autoamtically annotate scope changes, but it gets very confused by our
+        // concurrency and what it prints is just plain wrong. So we print our own information
+        // instead. (Cc https://github.com/rust-lang/miri/issues/2266)
+        info!("Leaving {}", ecx.frame().instance);
         Ok(())
     }
 
     #[inline(always)]
     fn after_stack_pop(
         ecx: &mut InterpCx<'mir, 'tcx, Self>,
-        mut frame: Frame<'mir, 'tcx, Provenance, FrameExtra<'tcx>>,
+        frame: Frame<'mir, 'tcx, Provenance, FrameExtra<'tcx>>,
         unwinding: bool,
     ) -> InterpResult<'tcx, StackPopJump> {
         if frame.extra.is_user_relevant {
@@ -1470,10 +1474,20 @@ impl<'mir, 'tcx> Machine<'mir, 'tcx> for MiriMachine<'mir, 'tcx> {
             // user-relevant frame and restore that here.)
             ecx.active_thread_mut().recompute_top_user_relevant_frame();
         }
-        let timing = frame.extra.timing.take();
-        let res = ecx.handle_stack_pop_unwind(frame.extra, unwinding);
-        if let Some(profiler) = ecx.machine.profiler.as_ref() {
-            profiler.finish_recording_interval_event(timing.unwrap());
+        let res = {
+            // Move `frame`` into a sub-scope so we control when it will be dropped.
+            let mut frame = frame;
+            let timing = frame.extra.timing.take();
+            let res = ecx.handle_stack_pop_unwind(frame.extra, unwinding);
+            if let Some(profiler) = ecx.machine.profiler.as_ref() {
+                profiler.finish_recording_interval_event(timing.unwrap());
+            }
+            res
+        };
+        // Needs to be done after dropping frame to show up on the right nesting level.
+        // (Cc https://github.com/rust-lang/miri/issues/2266)
+        if !ecx.active_thread_stack().is_empty() {
+            info!("Continuing in {}", ecx.frame().instance);
         }
         res
     }