Auto merge of #1791 - Aaron1011:measureme, r=RalfJung

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, the timing 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: bors

Cargo.lock

@@ -30,6 +30,7 @@ smallvec = "1.4.2"
 # See the `src/tools/rustc-workspace-hack/README.md` file in `rust-lang/rust`
 # for more information.
 rustc-workspace-hack = "1.0.0"
+measureme = "9.1.2"
 
 # Enable some feature flags that dev-dependencies need but dependencies
 # do not.  This makes `./miri install` after `./miri build` faster.

Cargo.toml

@@ -222,6 +222,10 @@ environment variable:
   times to exclude several variables.  On Windows, the `TERM` environment
   variable is excluded by default.
 * `-Zmiri-ignore-leaks` disables the memory leak checker.
+* `-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.
 * `-Zmiri-seed=<hex>` configures the seed of the RNG that Miri uses to resolve
   non-determinism.  This RNG is used to pick base addresses for allocations.
   When isolation is enabled (the default), this is also used to emulate system

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 a file
+    /// with the specified prefix.
+    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

@@ -34,7 +34,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 +42,21 @@ 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>>,
+
+    /// If `measureme` profiling is enabled, holds timing information
+    /// for the start of this frame. When we finish executing this frame,
+    /// we use this to register a completed event with `measureme`.
+    pub timing: Option<measureme::DetachedTiming>,
+}
+
+impl<'tcx> std::fmt::Debug for FrameData<'tcx> {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        // Omitting `timing`, it does not support `Debug`.
+        f.debug_struct("FrameData")
+            .field("call_id", &self.call_id)
+            .field("catch_unwind", &self.catch_unwind)
+            .finish()
+    }
 }
 
 /// Extra memory kinds
@@ -270,16 +284,22 @@ pub struct Evaluator<'mir, 'tcx> {
 
     /// Allocations that are considered roots of static memory (that may leak).
     pub(crate) static_roots: Vec<AllocId>,
+
+    /// The `measureme` profiler used to record timing information about
+    /// the emulated program.
+    profiler: Option<measureme::Profiler>,
+    /// Used with `profiler` to cache the `StringId`s for event names
+    /// uesd with `measureme`.
+    string_cache: FxHashMap<String, measureme::StringId>,
 }
 
 impl<'mir, 'tcx> Evaluator<'mir, 'tcx> {
-    pub(crate) fn new(
-        communicate: bool,
-        validate: bool,
-        layout_cx: LayoutCx<'tcx, TyCtxt<'tcx>>,
-    ) -> Self {
+    pub(crate) fn new(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| {
+            measureme::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 +308,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(),
         }
     }
 }
@@ -597,11 +619,27 @@ impl<'mir, 'tcx> Machine<'mir, 'tcx> for Evaluator<'mir, 'tcx> {
         ecx: &mut InterpCx<'mir, 'tcx, Self>,
         frame: Frame<'mir, 'tcx, Tag>,
     ) -> InterpResult<'tcx, Frame<'mir, 'tcx, Tag, FrameData<'tcx>>> {
+        // Start recording our event before doing anything else
+        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 = entry.or_insert_with(|| profiler.alloc_string(&*fn_name));
+
+            Some(profiler.start_recording_interval_event_detached(
+                *name,
+                measureme::EventId::from_label(*name),
+                ecx.get_active_thread().to_u32(),
+            ))
+        } else {
+            None
+        };
+
         let stacked_borrows = ecx.memory.extra.stacked_borrows.as_ref();
         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 extra = FrameData { call_id, catch_unwind: None, timing };
         Ok(frame.with_extra(extra))
     }
 
@@ -625,10 +663,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)]