diff --git a/src/tools/miri/src/bin/miri.rs b/src/tools/miri/src/bin/miri.rs index 2f37a64576e4e..dd08a376e7fc9 100644 --- a/src/tools/miri/src/bin/miri.rs +++ b/src/tools/miri/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 diff --git a/src/tools/miri/src/concurrency/thread.rs b/src/tools/miri/src/concurrency/thread.rs index 83ca27a467c8d..8341fd7648b29 100644 --- a/src/tools/miri/src/concurrency/thread.rs +++ b/src/tools/miri/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; } diff --git a/src/tools/miri/src/machine.rs b/src/tools/miri/src/machine.rs index d40f1c4525fc2..f0e851c132f7f 100644 --- a/src/tools/miri/src/machine.rs +++ b/src/tools/miri/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 }