From 34c16e72cf8ac0108b8ba3d9ae8312f962c3956a Mon Sep 17 00:00:00 2001 From: Ralf Jung Date: Sun, 3 Mar 2024 12:50:55 +0100 Subject: [PATCH 1/3] fix MIRI_LOG=info not setting the level for miri itself --- src/bin/miri.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/bin/miri.rs b/src/bin/miri.rs index 2f37a64576..6f82c1876e 100644 --- a/src/bin/miri.rs +++ b/src/bin/miri.rs @@ -202,7 +202,7 @@ 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); From f94eb1ba3598b3a542a46b99ddbdc8330bfcdde1 Mon Sep 17 00:00:00 2001 From: Ralf Jung Date: Sun, 3 Mar 2024 12:53:32 +0100 Subject: [PATCH 2/3] log when we change the active thread --- src/concurrency/thread.rs | 16 ++++++++++++---- 1 file changed, 12 insertions(+), 4 deletions(-) diff --git a/src/concurrency/thread.rs b/src/concurrency/thread.rs index 83ca27a467..8341fd7648 100644 --- a/src/concurrency/thread.rs +++ b/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; } From 5bef572cefec6cfd0249ec0219478d9e7312b8f4 Mon Sep 17 00:00:00 2001 From: Ralf Jung Date: Sun, 3 Mar 2024 13:29:14 +0100 Subject: [PATCH 3/3] do not rely on tracing's scope exit logging, it is wrong --- src/bin/miri.rs | 4 ---- src/machine.rs | 24 +++++++++++++++++++----- 2 files changed, 19 insertions(+), 9 deletions(-) diff --git a/src/bin/miri.rs b/src/bin/miri.rs index 6f82c1876e..dd08a376e7 100644 --- a/src/bin/miri.rs +++ b/src/bin/miri.rs @@ -208,10 +208,6 @@ fn rustc_logger_config() -> rustc_log::LoggerConfig { 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/machine.rs b/src/machine.rs index d40f1c4525..f0e851c132 100644 --- a/src/machine.rs +++ b/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 }