user0/rust
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

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

Browse source 
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 https://github.com/rust-lang/miri/issues/2266)
This commit is contained in:
bors 2024-03-03 12:38:10 +00:00
commit f51f9236f9
3 changed files with 32 additions and 14 deletions
Download patch file Download diff file Expand all files Collapse all files

6
src/tools/miri/src/bin/miri.rs
View file

@ -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

16
src/tools/miri/src/concurrency/thread.rs
View file

@ -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;
}

24
src/tools/miri/src/machine.rs
View file

@ -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
}