From 7e9da8d30eb07093c09fd90276aeca4a469a0432 Mon Sep 17 00:00:00 2001 From: Aaron Hill Date: Sat, 8 May 2021 12:20:51 -0400 Subject: [PATCH] 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=` --- Cargo.lock | 87 ++++++++++++++++++++++++++++++++++++++++++++++ Cargo.toml | 1 + README.md | 4 +++ src/bin/miri.rs | 4 +++ src/eval.rs | 6 +++- src/machine.rs | 50 +++++++++++++++++++++----- src/shims/panic.rs | 1 - 7 files changed, 143 insertions(+), 10 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 69cc1966a6f..3ae27003218 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,34 @@ dependencies = [ "cfg-if", ] +[[package]] +name = "measureme" +version = "9.1.1" +source = "git+https://github.com/rust-lang/measureme?rev=501d6a3c192beee5e633a6c5f79130bedfdadcb5#501d6a3c192beee5e633a6c5f79130bedfdadcb5" +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 +260,7 @@ dependencies = [ "hex", "libc", "log", + "measureme", "rand", "rustc-workspace-hack", "rustc_version", @@ -237,6 +278,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 +430,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 +475,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 ab7d88e6693..fd212e43047 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -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" diff --git a/README.md b/README.md index 469263115dd..87f6b87c662 100644 --- a/README.md +++ b/README.md @@ -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=` 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 Some native rustc `-Z` flags are also very relevant for Miri: diff --git a/src/bin/miri.rs b/src/bin/miri.rs index 4a1ea3a5428..47cde5c353e 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 1e46015f87a..a5268b58a2d 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 the specified + /// directory. + 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 467696e8397..77c606a83f4 100644 --- a/src/machine.rs +++ b/src/machine.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>, + + pub timing: Option, } /// 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, + + profiler: Option, + string_cache: FxHashMap, } 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)] diff --git a/src/shims/panic.rs b/src/shims/panic.rs index b1da7f340fc..6b08ee8e184 100644 --- a/src/shims/panic.rs +++ b/src/shims/panic.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); }