Add measureme integration for profiling the interpreted program

This PR uses the `measureme` crate to profile the call stack of the
program being interpreted by Miri. This is accomplished by starting a
measureme 'event' when we enter a function call, and ending the event
when we exit the call. The `measureme` tooling can be used to produce a
call stack from the generated profile data.

Limitations:
* We currently record every single entry/exit. This might generate very
  large profile outputs for programs with a large number of function
  calls. In follow-up work, we might want to explore sampling (e.g. only
  recording every N function calls).
* This does not integrate very well with Miri's concurrency support.
  Each event we record starts when we push a frame, and ends when we pop
  a frame. As a result, switching between virtual threads will cause
  events from different threads to be interleaved. Additionally, the
  recorded for a particular frame will include all of the work Miri does
  before that frame completes, including executing another thread.

The `measureme` integration is off by default, and must be enabled via
`-Zmiri-measureme=<output_name>`

Author: Aaron1011

Cargo.lock

@@ -18,6 +18,7 @@ test = false # we have no unit tests
 doctest = false # and no doc tests
 
 [dependencies]
+measureme = { git = "https://github.com/rust-lang/measureme", rev = "501d6a3c192beee5e633a6c5f79130bedfdadcb5" }
 getrandom = { version = "0.2", features = ["std"] }
 env_logger = "0.8"
 log = "0.4"

Cargo.toml

@@ -258,6 +258,10 @@ environment variable:
   this pointer. Note that it is not currently guaranteed that code that works
   with `-Zmiri-track-raw-pointers` also works without
   `-Zmiri-track-raw-pointers`, but for the vast majority of code, this will be the case.
+* `-Zmiri-measureme=<name>` enables `measureme` profiling for the interpreted program.
+   This can be used to find which parts of your program are executing slowly under Miri.
+   The profile is written out to a file with the prefix `<name>`, and can be processed
+   using the tools in the repository https://github.com/rust-lang/measureme
 
 Some native rustc `-Z` flags are also very relevant for Miri:
 

README.md

@@ -318,6 +318,10 @@ fn main() {
                     };
                     miri_config.cmpxchg_weak_failure_rate = rate;
                 }
+                arg if arg.starts_with("-Zmiri-measureme=") => {
+                    let measureme_out = arg.strip_prefix("-Zmiri-measureme=").unwrap();
+                    miri_config.measureme_out = Some(measureme_out.to_string());
+                }
                 _ => {
                     // Forward to rustc.
                     rustc_args.push(arg);

src/bin/miri.rs

@@ -54,6 +54,9 @@ pub struct MiriConfig {
     /// Rate of spurious failures for compare_exchange_weak atomic operations,
     /// between 0.0 and 1.0, defaulting to 0.8 (80% chance of failure).
     pub cmpxchg_weak_failure_rate: f64,
+    /// If `Some`, enable the `measureme` profiler, writing results to the specified
+    /// directory.
+    pub measureme_out: Option<String>,
 }
 
 impl Default for MiriConfig {
@@ -73,6 +76,7 @@ impl Default for MiriConfig {
             track_raw: false,
             data_race_detector: true,
             cmpxchg_weak_failure_rate: 0.8,
+            measureme_out: None,
         }
     }
 }
@@ -92,7 +96,7 @@ pub fn create_ecx<'mir, 'tcx: 'mir>(
         tcx,
         rustc_span::source_map::DUMMY_SP,
         param_env,
-        Evaluator::new(config.communicate, config.validate, layout_cx),
+        Evaluator::new(&config, layout_cx),
         MemoryExtra::new(&config),
     );
     // Complete initialization.

src/eval.rs

@@ -10,6 +10,8 @@ use std::time::Instant;
 use log::trace;
 use rand::rngs::StdRng;
 use rand::SeedableRng;
+use std::collections::hash_map::Entry;
+use measureme::{Profiler, StringId, EventId, DetachedTiming};
 
 use rustc_data_structures::fx::FxHashMap;
 use rustc_middle::{
@@ -34,7 +36,6 @@ pub const STACK_SIZE: u64 = 16 * PAGE_SIZE; // whatever
 pub const NUM_CPUS: u64 = 1;
 
 /// Extra data stored with each stack frame
-#[derive(Debug)]
 pub struct FrameData<'tcx> {
     /// Extra data for Stacked Borrows.
     pub call_id: stacked_borrows::CallId,
@@ -43,6 +44,8 @@ pub struct FrameData<'tcx> {
     /// called by `try`). When this frame is popped during unwinding a panic,
     /// we stop unwinding, use the `CatchUnwindData` to handle catching.
     pub catch_unwind: Option<CatchUnwindData<'tcx>>,
+
+    pub timing: Option<DetachedTiming>,
 }
 
 /// Extra memory kinds
@@ -270,16 +273,21 @@ pub struct Evaluator<'mir, 'tcx> {
 
     /// Allocations that are considered roots of static memory (that may leak).
     pub(crate) static_roots: Vec<AllocId>,
+
+    profiler: Option<Profiler>,
+    string_cache: FxHashMap<String, StringId>,
 }
 
 impl<'mir, 'tcx> Evaluator<'mir, 'tcx> {
     pub(crate) fn new(
-        communicate: bool,
-        validate: bool,
+        config: &MiriConfig,
         layout_cx: LayoutCx<'tcx, TyCtxt<'tcx>>,
     ) -> Self {
         let layouts =
             PrimitiveLayouts::new(layout_cx).expect("Couldn't get layouts of primitive types");
+        let profiler = config.measureme_out.as_ref().map(|out| {
+            Profiler::new(out).expect("Couldn't create `measureme` profiler")
+        });
         Evaluator {
             // `env_vars` could be initialized properly here if `Memory` were available before
             // calling this method.
@@ -288,14 +296,16 @@ impl<'mir, 'tcx> Evaluator<'mir, 'tcx> {
             argv: None,
             cmd_line: None,
             tls: TlsData::default(),
-            communicate,
-            validate,
+            communicate: config.communicate,
+            validate: config.validate,
             file_handler: Default::default(),
             dir_handler: Default::default(),
             time_anchor: Instant::now(),
             layouts,
             threads: ThreadManager::default(),
             static_roots: Vec::new(),
+            profiler,
+            string_cache: Default::default(),
         }
     }
 }
@@ -601,7 +611,26 @@ impl<'mir, 'tcx> Machine<'mir, 'tcx> for Evaluator<'mir, 'tcx> {
         let call_id = stacked_borrows.map_or(NonZeroU64::new(1).unwrap(), |stacked_borrows| {
             stacked_borrows.borrow_mut().new_call()
         });
-        let extra = FrameData { call_id, catch_unwind: None };
+        let timing = if let Some(profiler) = ecx.machine.profiler.as_ref() {
+            let fn_name = frame.instance.to_string();
+            let entry = ecx.machine.string_cache.entry(fn_name.clone());
+            let name = match entry {
+                Entry::Occupied(e) => *e.get(),
+                Entry::Vacant(e) => {
+                    *e.insert(profiler.alloc_string(&*fn_name))
+                }
+            };
+
+            Some(profiler.start_recording_interval_event_detached(
+                name,
+                EventId::from_label(name),
+                0
+            ))
+        } else {
+            None
+        };
+
+        let extra = FrameData { call_id, catch_unwind: None, timing };
         Ok(frame.with_extra(extra))
     }
 
@@ -625,10 +654,15 @@ impl<'mir, 'tcx> Machine<'mir, 'tcx> for Evaluator<'mir, 'tcx> {
     #[inline(always)]
     fn after_stack_pop(
         ecx: &mut InterpCx<'mir, 'tcx, Self>,
-        frame: Frame<'mir, 'tcx, Tag, FrameData<'tcx>>,
+        mut frame: Frame<'mir, 'tcx, Tag, FrameData<'tcx>>,
         unwinding: bool,
     ) -> InterpResult<'tcx, StackPopJump> {
-        ecx.handle_stack_pop(frame.extra, unwinding)
+        let timing = frame.extra.timing.take();
+        let res = ecx.handle_stack_pop(frame.extra, unwinding);
+        if let Some(profiler) = ecx.machine.profiler.as_ref() {
+            profiler.finish_recording_interval_event(timing.unwrap());
+        }
+        res
     }
 
     #[inline(always)]

src/machine.rs

@@ -119,7 +119,6 @@ pub trait EvalContextExt<'mir, 'tcx: 'mir>: crate::MiriEvalContextExt<'mir, 'tcx
     ) -> InterpResult<'tcx, StackPopJump> {
         let this = self.eval_context_mut();
 
-        trace!("handle_stack_pop(extra = {:?}, unwinding = {})", extra, unwinding);
         if let Some(stacked_borrows) = &this.memory.extra.stacked_borrows {
             stacked_borrows.borrow_mut().end_call(extra.call_id);
         }