diff --git a/Cargo.lock b/Cargo.lock index 69cc1966a6f8..e728dc07b928 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -167,6 +167,15 @@ version = "2.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4" +[[package]] +name = "instant" +version = "0.1.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "61124eeebbd69b8190558df225adf7e4caafce0d743919e5d6b19652314ec5ec" +dependencies = [ + "cfg-if", +] + [[package]] name = "itoa" version = "0.4.7" @@ -185,6 +194,15 @@ version = "0.2.92" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "56d855069fafbb9b344c0f962150cd2c1187975cb1c22c1522c240d8c4986714" +[[package]] +name = "lock_api" +version = "0.4.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5a3c91c24eae6777794bb1997ad98bbb87daf92890acab859f7eaa4320333176" +dependencies = [ + "scopeguard", +] + [[package]] name = "log" version = "0.4.14" @@ -194,12 +212,35 @@ dependencies = [ "cfg-if", ] +[[package]] +name = "measureme" +version = "9.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "78f7a41bc6f856a2cf0e95094ad5121f82500e2d9a0f3c0171d98f6566d8117d" +dependencies = [ + "log", + "memmap2", + "parking_lot", + "perf-event-open-sys", + "rustc-hash", + "smallvec", +] + [[package]] name = "memchr" version = "2.3.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0ee1c47aaa256ecabcaea351eae4a9b01ef39ed810004e298d2511ed284b1525" +[[package]] +name = "memmap2" +version = "0.2.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "397d1a6d6d0563c0f5462bbdae662cf6c784edf5e828e40c7257f85d82bf56dd" +dependencies = [ + "libc", +] + [[package]] name = "miow" version = "0.3.7" @@ -220,6 +261,7 @@ dependencies = [ "hex", "libc", "log", + "measureme", "rand", "rustc-workspace-hack", "rustc_version", @@ -237,6 +279,40 @@ dependencies = [ "libc", ] +[[package]] +name = "parking_lot" +version = "0.11.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6d7744ac029df22dca6284efe4e898991d28e3085c706c972bcd7da4a27a15eb" +dependencies = [ + "instant", + "lock_api", + "parking_lot_core", +] + +[[package]] +name = "parking_lot_core" +version = "0.8.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "fa7a782938e745763fe6907fc6ba86946d72f49fe7e21de074e08128a99fb018" +dependencies = [ + "cfg-if", + "instant", + "libc", + "redox_syscall", + "smallvec", + "winapi", +] + +[[package]] +name = "perf-event-open-sys" +version = "1.0.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ce9bedf5da2c234fdf2391ede2b90fabf585355f33100689bc364a3ea558561a" +dependencies = [ + "libc", +] + [[package]] name = "pest" version = "2.1.3" @@ -355,6 +431,12 @@ dependencies = [ "winapi", ] +[[package]] +name = "rustc-hash" +version = "1.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "08d43f7aa6b08d49f382cde6a7982047c3426db949b1424bc4b7ec9ae12c6ce2" + [[package]] name = "rustc-workspace-hack" version = "1.0.0" @@ -394,6 +476,12 @@ version = "1.0.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "71d301d4193d031abdd79ff7e3dd721168a9572ef3fe51a1517aba235bd8f86e" +[[package]] +name = "scopeguard" +version = "1.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d29ab0c6d3fc0ee92fe66e2d99f700eab17a8d57d1c1d3b748380fb20baa78cd" + [[package]] name = "semver" version = "0.11.0" diff --git a/Cargo.toml b/Cargo.toml index ab7d88e66934..7ee96f7e99e6 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -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. diff --git a/README.md b/README.md index 469263115dd7..b214ab6d09c1 100644 --- a/README.md +++ b/README.md @@ -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=` 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 ``, and can be processed + using the tools in the repository https://github.com/rust-lang/measureme. * `-Zmiri-seed=` 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 diff --git a/src/bin/miri.rs b/src/bin/miri.rs index 4a1ea3a54286..47cde5c353e1 100644 --- a/src/bin/miri.rs +++ b/src/bin/miri.rs @@ -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); diff --git a/src/eval.rs b/src/eval.rs index 1e46015f87a8..52e554f57d7e 100644 --- a/src/eval.rs +++ b/src/eval.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, } 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. diff --git a/src/machine.rs b/src/machine.rs index 467696e83976..4f643e7f5091 100644 --- a/src/machine.rs +++ b/src/machine.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>, + + /// 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, +} + +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, + + /// The `measureme` profiler used to record timing information about + /// the emulated program. + profiler: Option, + /// Used with `profiler` to cache the `StringId`s for event names + /// uesd with `measureme`. + string_cache: FxHashMap, } 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)]