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

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

Browse source 
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>`
This commit is contained in:
bors 2021-05-30 15:14:23 +00:00
commit 178ae8e44c
6 changed files with 156 additions and 12 deletions
Download patch file Download diff file Expand all files Collapse all files

88
Cargo.lock generated
View file

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

1
Cargo.toml
View file

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

4
README.md
View file

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

4
src/bin/miri.rs
View file

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

6
src/eval.rs
View file

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

65
src/machine.rs
View file

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