diff options
| -rw-r--r-- | src/tools/miri/CONTRIBUTING.md | 9 | ||||
| -rw-r--r-- | src/tools/miri/Cargo.lock | 1 | ||||
| -rw-r--r-- | src/tools/miri/Cargo.toml | 2 | ||||
| -rw-r--r-- | src/tools/miri/rustfmt.toml | 5 | ||||
| -rw-r--r-- | src/tools/miri/src/bin/log/mod.rs | 2 | ||||
| -rw-r--r-- | src/tools/miri/src/bin/log/setup.rs | 126 | ||||
| -rw-r--r-- | src/tools/miri/src/bin/log/tracing_chrome.rs | 625 | ||||
| -rw-r--r-- | src/tools/miri/src/bin/miri.rs | 158 | ||||
| -rw-r--r-- | src/tools/miri/src/machine.rs | 2 |
9 files changed, 828 insertions, 102 deletions
diff --git a/src/tools/miri/CONTRIBUTING.md b/src/tools/miri/CONTRIBUTING.md index 739f0702252..fef7f807e93 100644 --- a/src/tools/miri/CONTRIBUTING.md +++ b/src/tools/miri/CONTRIBUTING.md @@ -158,6 +158,15 @@ compiler that has `debug=true` set in `bootstrap.toml`. You can set `MIRI_BACKTRACE=1` to get a backtrace of where an evaluation error was originally raised. +#### Tracing + +You can generate a Chrome trace file from a Miri execution by passing `--features=tracing` during the +build and then setting `MIRI_TRACING=1` when running Miri. This will generate a `.json` file that +you can visualize in [Perfetto](https://ui.perfetto.dev/). For example: + +```sh +MIRI_TRACING=1 ./miri run --features=tracing tests/pass/hello.rs +``` ### UI testing diff --git a/src/tools/miri/Cargo.lock b/src/tools/miri/Cargo.lock index d3123caaa47..aa6f059cec2 100644 --- a/src/tools/miri/Cargo.lock +++ b/src/tools/miri/Cargo.lock @@ -627,6 +627,7 @@ dependencies = [ "regex", "rustc_version", "serde", + "serde_json", "smallvec", "tempfile", "tikv-jemalloc-sys", diff --git a/src/tools/miri/Cargo.toml b/src/tools/miri/Cargo.toml index 9391a6ffee3..75476d7923c 100644 --- a/src/tools/miri/Cargo.toml +++ b/src/tools/miri/Cargo.toml @@ -27,6 +27,7 @@ chrono = { version = "0.4.38", default-features = false } chrono-tz = "0.10" directories = "6" bitflags = "2.6" +serde_json = { version = "1.0", optional = true } # Copied from `compiler/rustc/Cargo.toml`. # But only for some targets, it fails for others. Rustc configures this in its CI, but we can't @@ -67,6 +68,7 @@ default = ["stack-cache"] genmc = [] stack-cache = [] stack-cache-consistency-check = ["stack-cache"] +tracing = ["serde_json"] [lints.rust.unexpected_cfgs] level = "warn" diff --git a/src/tools/miri/rustfmt.toml b/src/tools/miri/rustfmt.toml index 49650d8486c..92fd22b7f55 100644 --- a/src/tools/miri/rustfmt.toml +++ b/src/tools/miri/rustfmt.toml @@ -8,3 +8,8 @@ imports_granularity = "Module" force_multiline_blocks = true match_arm_blocks = false match_arm_leading_pipes = "Preserve" + +ignore = [ + # This file is copy-pasted from the tracing_chrome crate and should remain like the original. + "src/bin/log/tracing_chrome.rs" +] diff --git a/src/tools/miri/src/bin/log/mod.rs b/src/tools/miri/src/bin/log/mod.rs new file mode 100644 index 00000000000..f3b2fdb5348 --- /dev/null +++ b/src/tools/miri/src/bin/log/mod.rs @@ -0,0 +1,2 @@ +pub mod setup; +mod tracing_chrome; diff --git a/src/tools/miri/src/bin/log/setup.rs b/src/tools/miri/src/bin/log/setup.rs new file mode 100644 index 00000000000..da0ba528b2c --- /dev/null +++ b/src/tools/miri/src/bin/log/setup.rs @@ -0,0 +1,126 @@ +use std::env::{self, VarError}; +use std::str::FromStr; +use std::sync::{Mutex, OnceLock}; + +use rustc_middle::ty::TyCtxt; +use rustc_session::{CtfeBacktrace, EarlyDiagCtxt}; + +/// The tracing layer from `tracing-chrome` starts a thread in the background that saves data to +/// file and closes the file when stopped. If the thread is not stopped properly, the file will be +/// missing end terminators (`]` for JSON arrays) and other data may also not be flushed. Therefore +/// we need to keep a guard that, when [Drop]ped, will send a signal to stop the thread. Make sure +/// to manually drop this guard using [deinit_loggers], if you are exiting the program with +/// [std::process::exit]! +#[must_use] +struct TracingGuard { + #[cfg(feature = "tracing")] + _chrome: super::tracing_chrome::FlushGuard, + _no_construct: (), +} + +// This ensures TracingGuard is always a drop-type, even when the `_chrome` field is disabled. +impl Drop for TracingGuard { + fn drop(&mut self) {} +} + +fn rustc_logger_config() -> rustc_log::LoggerConfig { + // Start with the usual env vars. + let mut cfg = rustc_log::LoggerConfig::from_env("RUSTC_LOG"); + + // Overwrite if MIRI_LOG is set. + if let Ok(var) = env::var("MIRI_LOG") { + // MIRI_LOG serves as default for RUSTC_LOG, if that is not set. + if matches!(cfg.filter, Err(VarError::NotPresent)) { + // We try to be a bit clever here: if `MIRI_LOG` is just a single level + // used for everything, we only apply it to the parts of rustc that are + // CTFE-related. Otherwise, we use it verbatim for `RUSTC_LOG`. + // This way, if you set `MIRI_LOG=trace`, you get only the right parts of + // rustc traced, but you can also do `MIRI_LOG=miri=trace,rustc_const_eval::interpret=debug`. + if tracing::Level::from_str(&var).is_ok() { + cfg.filter = Ok(format!( + "rustc_middle::mir::interpret={var},rustc_const_eval::interpret={var},miri={var}" + )); + } else { + cfg.filter = Ok(var); + } + } + } + + cfg +} + +/// The global logger can only be set once per process, so track whether that already happened and +/// keep a [TracingGuard] so it can be [Drop]ped later using [deinit_loggers]. +static LOGGER_INITED: OnceLock<Mutex<Option<TracingGuard>>> = OnceLock::new(); + +fn init_logger_once(early_dcx: &EarlyDiagCtxt) { + // If the logger is not yet initialized, initialize it. + LOGGER_INITED.get_or_init(|| { + let guard = if env::var_os("MIRI_TRACING").is_some() { + #[cfg(not(feature = "tracing"))] + { + crate::fatal_error!( + "fatal error: cannot enable MIRI_TRACING since Miri was not built with the \"tracing\" feature" + ); + } + + #[cfg(feature = "tracing")] + { + let (chrome_layer, chrome_guard) = + super::tracing_chrome::ChromeLayerBuilder::new().include_args(true).build(); + rustc_driver::init_logger_with_additional_layer( + early_dcx, + rustc_logger_config(), + || { + tracing_subscriber::layer::SubscriberExt::with( + tracing_subscriber::Registry::default(), + chrome_layer, + ) + }, + ); + + Some(TracingGuard { _chrome: chrome_guard, _no_construct: () }) + } + } else { + // initialize the logger without any tracing enabled + rustc_driver::init_logger(early_dcx, rustc_logger_config()); + None + }; + Mutex::new(guard) + }); +} + +pub fn init_early_loggers(early_dcx: &EarlyDiagCtxt) { + // We only initialize `rustc` if the env var is set (so the user asked for it). + // If it is not set, we avoid initializing now so that we can initialize later with our custom + // settings, and *not* log anything for what happens before `miri` starts interpreting. + if env::var_os("RUSTC_LOG").is_some() { + init_logger_once(early_dcx); + } +} + +pub fn init_late_loggers(early_dcx: &EarlyDiagCtxt, tcx: TyCtxt<'_>) { + // If the logger is not yet initialized, initialize it. + init_logger_once(early_dcx); + + // If `MIRI_BACKTRACE` is set and `RUSTC_CTFE_BACKTRACE` is not, set `RUSTC_CTFE_BACKTRACE`. + // Do this late, so we ideally only apply this to Miri's errors. + if let Some(val) = env::var_os("MIRI_BACKTRACE") { + let ctfe_backtrace = match &*val.to_string_lossy() { + "immediate" => CtfeBacktrace::Immediate, + "0" => CtfeBacktrace::Disabled, + _ => CtfeBacktrace::Capture, + }; + *tcx.sess.ctfe_backtrace.borrow_mut() = ctfe_backtrace; + } +} + +/// Must be called before the program terminates to ensure the trace file is closed correctly. Not +/// doing so will result in invalid trace files. Also see [TracingGuard]. +pub fn deinit_loggers() { + if let Some(guard) = LOGGER_INITED.get() + && let Ok(mut guard) = guard.lock() + { + std::mem::drop(guard.take()); + } +} diff --git a/src/tools/miri/src/bin/log/tracing_chrome.rs b/src/tools/miri/src/bin/log/tracing_chrome.rs new file mode 100644 index 00000000000..459acea6f0b --- /dev/null +++ b/src/tools/miri/src/bin/log/tracing_chrome.rs @@ -0,0 +1,625 @@ +// SPDX-License-Identifier: MIT +// SPDX-FileCopyrightText: Copyright (c) 2020 Thoren Paulson +//! This file is taken unmodified from the following link, except for file attributes and +//! `extern crate` at the top. +//! https://github.com/thoren-d/tracing-chrome/blob/7e2625ab4aeeef2f0ef9bde9d6258dd181c04472/src/lib.rs +//! Depending on the tracing-chrome crate from crates.io is unfortunately not possible, since it +//! depends on `tracing_core` which conflicts with rustc_private's `tracing_core` (meaning it would +//! not be possible to use the [ChromeLayer] in a context that expects a [Layer] from +//! rustc_private's `tracing_core` version). +#![allow(warnings)] +#![cfg(feature = "tracing")] + +// This is here and not in src/lib.rs since it is a direct dependency of tracing_chrome.rs and +// should not be included if the "tracing" feature is disabled. +extern crate tracing_core; + +use tracing_core::{field::Field, span, Event, Subscriber}; +use tracing_subscriber::{ + layer::Context, + registry::{LookupSpan, SpanRef}, + Layer, +}; + +use serde_json::{json, Value as JsonValue}; +use std::{ + marker::PhantomData, + path::Path, + sync::{ + atomic::{AtomicUsize, Ordering}, + Arc, Mutex, + }, +}; + +use std::io::{BufWriter, Write}; +use std::sync::mpsc; +use std::sync::mpsc::Sender; +use std::{ + cell::{Cell, RefCell}, + thread::JoinHandle, +}; + +thread_local! { + static OUT: RefCell<Option<Sender<Message>>> = const { RefCell::new(None) }; + static TID: RefCell<Option<usize>> = const { RefCell::new(None) }; +} + +type NameFn<S> = Box<dyn Fn(&EventOrSpan<'_, '_, S>) -> String + Send + Sync>; +type Object = serde_json::Map<String, JsonValue>; + +/// A [`Layer`](tracing_subscriber::Layer) that writes a Chrome trace file. +pub struct ChromeLayer<S> +where + S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync, +{ + out: Arc<Mutex<Sender<Message>>>, + start: std::time::Instant, + max_tid: AtomicUsize, + include_args: bool, + include_locations: bool, + trace_style: TraceStyle, + name_fn: Option<NameFn<S>>, + cat_fn: Option<NameFn<S>>, + _inner: PhantomData<S>, +} + +/// A builder for [`ChromeLayer`](crate::ChromeLayer). +#[derive(Default)] +pub struct ChromeLayerBuilder<S> +where + S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync, +{ + out_writer: Option<Box<dyn Write + Send>>, + name_fn: Option<NameFn<S>>, + cat_fn: Option<NameFn<S>>, + include_args: bool, + include_locations: bool, + trace_style: TraceStyle, + _inner: PhantomData<S>, +} + +/// Decides how traces will be recorded. +#[derive(Default)] +pub enum TraceStyle { + /// Traces will be recorded as a group of threads. + /// In this style, spans should be entered and exited on the same thread. + #[default] + Threaded, + + /// Traces will recorded as a group of asynchronous operations. + Async, +} + +impl<S> ChromeLayerBuilder<S> +where + S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync, +{ + pub fn new() -> Self { + ChromeLayerBuilder { + out_writer: None, + name_fn: None, + cat_fn: None, + include_args: false, + include_locations: true, + trace_style: TraceStyle::Threaded, + _inner: PhantomData, + } + } + + /// Set the file to which to output the trace. + /// + /// Defaults to `./trace-{unix epoch in micros}.json`. + /// + /// # Panics + /// + /// If `file` could not be opened/created. To handle errors, + /// open a file and pass it to [`writer`](crate::ChromeLayerBuilder::writer) instead. + pub fn file<P: AsRef<Path>>(self, file: P) -> Self { + self.writer(std::fs::File::create(file).expect("Failed to create trace file.")) + } + + /// Supply an arbitrary writer to which to write trace contents. + /// + /// # Examples + /// + /// ```rust + /// # use tracing_chrome::ChromeLayerBuilder; + /// # use tracing_subscriber::prelude::*; + /// let (layer, guard) = ChromeLayerBuilder::new().writer(std::io::sink()).build(); + /// # tracing_subscriber::registry().with(layer).init(); + /// ``` + pub fn writer<W: Write + Send + 'static>(mut self, writer: W) -> Self { + self.out_writer = Some(Box::new(writer)); + self + } + + /// Include arguments in each trace entry. + /// + /// Defaults to `false`. + /// + /// Includes the arguments used when creating a span/event + /// in the "args" section of the trace entry. + pub fn include_args(mut self, include: bool) -> Self { + self.include_args = include; + self + } + + /// Include file+line with each trace entry. + /// + /// Defaults to `true`. + /// + /// This can add quite a bit of data to the output so turning + /// it off might be helpful when collecting larger traces. + pub fn include_locations(mut self, include: bool) -> Self { + self.include_locations = include; + self + } + + /// Sets the style used when recording trace events. + /// + /// See [`TraceStyle`](crate::TraceStyle) for details. + pub fn trace_style(mut self, style: TraceStyle) -> Self { + self.trace_style = style; + self + } + + /// Allows supplying a function that derives a name from + /// an Event or Span. The result is used as the "name" field + /// on trace entries. + /// + /// # Example + /// ``` + /// use tracing_chrome::{ChromeLayerBuilder, EventOrSpan}; + /// use tracing_subscriber::{registry::Registry, prelude::*}; + /// + /// let (chrome_layer, _guard) = ChromeLayerBuilder::new().name_fn(Box::new(|event_or_span| { + /// match event_or_span { + /// EventOrSpan::Event(ev) => { ev.metadata().name().into() }, + /// EventOrSpan::Span(_s) => { "span".into() }, + /// } + /// })).build(); + /// tracing_subscriber::registry().with(chrome_layer).init() + /// ``` + pub fn name_fn(mut self, name_fn: NameFn<S>) -> Self { + self.name_fn = Some(name_fn); + self + } + + /// Allows supplying a function that derives a category from + /// an Event or Span. The result is used as the "cat" field on + /// trace entries. + /// + /// # Example + /// ``` + /// use tracing_chrome::{ChromeLayerBuilder, EventOrSpan}; + /// use tracing_subscriber::{registry::Registry, prelude::*}; + /// + /// let (chrome_layer, _guard) = ChromeLayerBuilder::new().category_fn(Box::new(|_| { + /// "my_module".into() + /// })).build(); + /// tracing_subscriber::registry().with(chrome_layer).init() + /// ``` + pub fn category_fn(mut self, cat_fn: NameFn<S>) -> Self { + self.cat_fn = Some(cat_fn); + self + } + + /// Creates a [`ChromeLayer`](crate::ChromeLayer) and associated [`FlushGuard`](crate::FlushGuard). + /// + /// # Panics + /// + /// If no file or writer was specified and the default trace file could not be opened/created. + pub fn build(self) -> (ChromeLayer<S>, FlushGuard) { + ChromeLayer::new(self) + } +} + +/// This guard will signal the thread writing the trace file to stop and join it when dropped. +pub struct FlushGuard { + sender: Sender<Message>, + handle: Cell<Option<JoinHandle<()>>>, +} + +impl FlushGuard { + /// Signals the trace writing thread to flush to disk. + pub fn flush(&self) { + if let Some(handle) = self.handle.take() { + let _ignored = self.sender.send(Message::Flush); + self.handle.set(Some(handle)); + } + } + + /// Finishes the current trace and starts a new one. + /// + /// If a [`Write`](std::io::Write) implementation is supplied, + /// the new trace is written to it. Otherwise, the new trace + /// goes to `./trace-{unix epoc in micros}.json`. + pub fn start_new(&self, writer: Option<Box<dyn Write + Send>>) { + if let Some(handle) = self.handle.take() { + let _ignored = self.sender.send(Message::StartNew(writer)); + self.handle.set(Some(handle)); + } + } +} + +impl Drop for FlushGuard { + fn drop(&mut self) { + if let Some(handle) = self.handle.take() { + let _ignored = self.sender.send(Message::Drop); + if handle.join().is_err() { + eprintln!("tracing_chrome: Trace writing thread panicked."); + } + } + } +} + +struct Callsite { + tid: usize, + name: String, + target: String, + file: Option<&'static str>, + line: Option<u32>, + args: Option<Arc<Object>>, +} + +enum Message { + Enter(f64, Callsite, Option<u64>), + Event(f64, Callsite), + Exit(f64, Callsite, Option<u64>), + NewThread(usize, String), + Flush, + Drop, + StartNew(Option<Box<dyn Write + Send>>), +} + +/// Represents either an [`Event`](tracing_core::Event) or [`SpanRef`](tracing_subscriber::registry::SpanRef). +pub enum EventOrSpan<'a, 'b, S> +where + S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync, +{ + Event(&'a Event<'b>), + Span(&'a SpanRef<'b, S>), +} + +fn create_default_writer() -> Box<dyn Write + Send> { + Box::new( + std::fs::File::create(format!( + "./trace-{}.json", + std::time::SystemTime::UNIX_EPOCH + .elapsed() + .unwrap() + .as_micros() + )) + .expect("Failed to create trace file."), + ) +} + +impl<S> ChromeLayer<S> +where + S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync, +{ + fn new(mut builder: ChromeLayerBuilder<S>) -> (ChromeLayer<S>, FlushGuard) { + let (tx, rx) = mpsc::channel(); + OUT.with(|val| val.replace(Some(tx.clone()))); + + let out_writer = builder + .out_writer + .unwrap_or_else(|| create_default_writer()); + + let handle = std::thread::spawn(move || { + let mut write = BufWriter::new(out_writer); + write.write_all(b"[\n").unwrap(); + + let mut has_started = false; + let mut thread_names: Vec<(usize, String)> = Vec::new(); + for msg in rx { + if let Message::Flush = &msg { + write.flush().unwrap(); + continue; + } else if let Message::Drop = &msg { + break; + } else if let Message::StartNew(writer) = msg { + // Finish off current file + write.write_all(b"\n]").unwrap(); + write.flush().unwrap(); + + // Get or create new writer + let out_writer = writer.unwrap_or_else(|| create_default_writer()); + write = BufWriter::new(out_writer); + write.write_all(b"[\n").unwrap(); + has_started = false; + + // Write saved thread names + for (tid, name) in thread_names.iter() { + let entry = json!({ + "ph": "M", + "pid": 1, + "name": "thread_name", + "tid": *tid, + "args": { + "name": name, + }, + }); + + if has_started { + write.write_all(b",\n").unwrap(); + } + serde_json::to_writer(&mut write, &entry).unwrap(); + has_started = true; + } + continue; + } + + let (ph, ts, callsite, id) = match &msg { + Message::Enter(ts, callsite, None) => ("B", Some(ts), Some(callsite), None), + Message::Enter(ts, callsite, Some(root_id)) => { + ("b", Some(ts), Some(callsite), Some(root_id)) + } + Message::Event(ts, callsite) => ("i", Some(ts), Some(callsite), None), + Message::Exit(ts, callsite, None) => ("E", Some(ts), Some(callsite), None), + Message::Exit(ts, callsite, Some(root_id)) => { + ("e", Some(ts), Some(callsite), Some(root_id)) + } + Message::NewThread(_tid, _name) => ("M", None, None, None), + Message::Flush | Message::Drop | Message::StartNew(_) => { + panic!("Was supposed to break by now.") + } + }; + let mut entry = json!({ + "ph": ph, + "pid": 1, + }); + + if let Message::NewThread(tid, name) = msg { + thread_names.push((tid, name.clone())); + entry["name"] = "thread_name".into(); + entry["tid"] = tid.into(); + entry["args"] = json!({ "name": name }); + } else { + let ts = ts.unwrap(); + let callsite = callsite.unwrap(); + entry["ts"] = (*ts).into(); + entry["name"] = callsite.name.clone().into(); + entry["cat"] = callsite.target.clone().into(); + entry["tid"] = callsite.tid.into(); + + if let Some(&id) = id { + entry["id"] = id.into(); + } + + if ph == "i" { + entry["s"] = "t".into(); + } + + if let (Some(file), Some(line)) = (callsite.file, callsite.line) { + entry[".file"] = file.into(); + entry[".line"] = line.into(); + } + + if let Some(call_args) = &callsite.args { + if !call_args.is_empty() { + entry["args"] = (**call_args).clone().into(); + } + } + } + + if has_started { + write.write_all(b",\n").unwrap(); + } + serde_json::to_writer(&mut write, &entry).unwrap(); + has_started = true; + } + + write.write_all(b"\n]").unwrap(); + write.flush().unwrap(); + }); + + let guard = FlushGuard { + sender: tx.clone(), + handle: Cell::new(Some(handle)), + }; + let layer = ChromeLayer { + out: Arc::new(Mutex::new(tx)), + start: std::time::Instant::now(), + max_tid: AtomicUsize::new(0), + name_fn: builder.name_fn.take(), + cat_fn: builder.cat_fn.take(), + include_args: builder.include_args, + include_locations: builder.include_locations, + trace_style: builder.trace_style, + _inner: PhantomData, + }; + + (layer, guard) + } + + fn get_tid(&self) -> (usize, bool) { + TID.with(|value| { + let tid = *value.borrow(); + match tid { + Some(tid) => (tid, false), + None => { + let tid = self.max_tid.fetch_add(1, Ordering::SeqCst); + value.replace(Some(tid)); + (tid, true) + } + } + }) + } + + fn get_callsite(&self, data: EventOrSpan<S>) -> Callsite { + let (tid, new_thread) = self.get_tid(); + let name = self.name_fn.as_ref().map(|name_fn| name_fn(&data)); + let target = self.cat_fn.as_ref().map(|cat_fn| cat_fn(&data)); + let meta = match data { + EventOrSpan::Event(e) => e.metadata(), + EventOrSpan::Span(s) => s.metadata(), + }; + let args = match data { + EventOrSpan::Event(e) => { + if self.include_args { + let mut args = Object::new(); + e.record(&mut JsonVisitor { object: &mut args }); + Some(Arc::new(args)) + } else { + None + } + } + EventOrSpan::Span(s) => s + .extensions() + .get::<ArgsWrapper>() + .map(|e| &e.args) + .cloned(), + }; + let name = name.unwrap_or_else(|| meta.name().into()); + let target = target.unwrap_or_else(|| meta.target().into()); + let (file, line) = if self.include_locations { + (meta.file(), meta.line()) + } else { + (None, None) + }; + + if new_thread { + let name = match std::thread::current().name() { + Some(name) => name.to_owned(), + None => tid.to_string(), + }; + self.send_message(Message::NewThread(tid, name)); + } + + Callsite { + tid, + name, + target, + file, + line, + args, + } + } + + fn get_root_id(span: SpanRef<S>) -> u64 { + span.scope() + .from_root() + .take(1) + .next() + .unwrap_or(span) + .id() + .into_u64() + } + + fn enter_span(&self, span: SpanRef<S>, ts: f64) { + let callsite = self.get_callsite(EventOrSpan::Span(&span)); + let root_id = match self.trace_style { + TraceStyle::Async => Some(ChromeLayer::get_root_id(span)), + _ => None, + }; + self.send_message(Message::Enter(ts, callsite, root_id)); + } + + fn exit_span(&self, span: SpanRef<S>, ts: f64) { + let callsite = self.get_callsite(EventOrSpan::Span(&span)); + let root_id = match self.trace_style { + TraceStyle::Async => Some(ChromeLayer::get_root_id(span)), + _ => None, + }; + self.send_message(Message::Exit(ts, callsite, root_id)); + } + + fn get_ts(&self) -> f64 { + self.start.elapsed().as_nanos() as f64 / 1000.0 + } + + fn send_message(&self, message: Message) { + OUT.with(move |val| { + if val.borrow().is_some() { + let _ignored = val.borrow().as_ref().unwrap().send(message); + } else { + let out = self.out.lock().unwrap().clone(); + let _ignored = out.send(message); + val.replace(Some(out)); + } + }); + } +} + +impl<S> Layer<S> for ChromeLayer<S> +where + S: Subscriber + for<'span> LookupSpan<'span> + Send + Sync, +{ + fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { + if let TraceStyle::Async = self.trace_style { + return; + } + + let ts = self.get_ts(); + self.enter_span(ctx.span(id).expect("Span not found."), ts); + } + + fn on_record(&self, id: &span::Id, values: &span::Record<'_>, ctx: Context<'_, S>) { + if self.include_args { + let span = ctx.span(id).unwrap(); + let mut exts = span.extensions_mut(); + + let args = exts.get_mut::<ArgsWrapper>(); + + if let Some(args) = args { + let args = Arc::make_mut(&mut args.args); + values.record(&mut JsonVisitor { object: args }); + } + } + } + + fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) { + let ts = self.get_ts(); + let callsite = self.get_callsite(EventOrSpan::Event(event)); + self.send_message(Message::Event(ts, callsite)); + } + + fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { + if let TraceStyle::Async = self.trace_style { + return; + } + let ts = self.get_ts(); + self.exit_span(ctx.span(id).expect("Span not found."), ts); + } + + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { + if self.include_args { + let mut args = Object::new(); + attrs.record(&mut JsonVisitor { object: &mut args }); + ctx.span(id).unwrap().extensions_mut().insert(ArgsWrapper { + args: Arc::new(args), + }); + } + if let TraceStyle::Threaded = self.trace_style { + return; + } + + let ts = self.get_ts(); + self.enter_span(ctx.span(id).expect("Span not found."), ts); + } + + fn on_close(&self, id: span::Id, ctx: Context<'_, S>) { + if let TraceStyle::Threaded = self.trace_style { + return; + } + + let ts = self.get_ts(); + self.exit_span(ctx.span(&id).expect("Span not found."), ts); + } +} + +struct JsonVisitor<'a> { + object: &'a mut Object, +} + +impl<'a> tracing_subscriber::field::Visit for JsonVisitor<'a> { + fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { + self.object + .insert(field.name().to_owned(), format!("{value:?}").into()); + } +} + +struct ArgsWrapper { + args: Arc<Object>, +} diff --git a/src/tools/miri/src/bin/miri.rs b/src/tools/miri/src/bin/miri.rs index 56be370d5da..e3b579a4ac6 100644 --- a/src/tools/miri/src/bin/miri.rs +++ b/src/tools/miri/src/bin/miri.rs @@ -10,6 +10,8 @@ // Some "regular" crates we want to share with rustc extern crate tracing; +#[cfg(feature = "tracing")] +extern crate tracing_subscriber; // The rustc crates we need extern crate rustc_abi; @@ -24,14 +26,16 @@ extern crate rustc_middle; extern crate rustc_session; extern crate rustc_span; -use std::env::{self, VarError}; +mod log; + +use std::env; use std::num::NonZero; use std::ops::Range; use std::path::PathBuf; use std::rc::Rc; use std::str::FromStr; +use std::sync::Arc; use std::sync::atomic::{AtomicI32, AtomicU32, Ordering}; -use std::sync::{Arc, Once}; use miri::{ BacktraceStyle, BorrowTrackerMethod, GenmcConfig, GenmcCtx, MiriConfig, MiriEntryFnType, @@ -52,12 +56,14 @@ use rustc_middle::query::LocalCrate; use rustc_middle::traits::{ObligationCause, ObligationCauseCode}; use rustc_middle::ty::{self, Ty, TyCtxt}; use rustc_middle::util::Providers; +use rustc_session::EarlyDiagCtxt; use rustc_session::config::{CrateType, ErrorOutputType, OptLevel}; use rustc_session::search_paths::PathKind; -use rustc_session::{CtfeBacktrace, EarlyDiagCtxt}; use rustc_span::def_id::DefId; use tracing::debug; +use crate::log::setup::{deinit_loggers, init_early_loggers, init_late_loggers}; + struct MiriCompilerCalls { miri_config: Option<MiriConfig>, many_seeds: Option<ManySeedsConfig>, @@ -154,13 +160,13 @@ impl rustc_driver::Callbacks for MiriCompilerCalls { if tcx.sess.dcx().has_errors_or_delayed_bugs().is_some() { tcx.dcx().fatal("miri cannot be run on programs that fail compilation"); } - - let early_dcx = EarlyDiagCtxt::new(tcx.sess.opts.error_format); - init_late_loggers(&early_dcx, tcx); if !tcx.crate_types().contains(&CrateType::Executable) { tcx.dcx().fatal("miri only makes sense on bin crates"); } + let early_dcx = EarlyDiagCtxt::new(tcx.sess.opts.error_format); + init_late_loggers(&early_dcx, tcx); + let (entry_def_id, entry_type) = entry_fn(tcx); let mut config = self.miri_config.take().expect("after_analysis must only be called once"); @@ -213,7 +219,7 @@ impl rustc_driver::Callbacks for MiriCompilerCalls { if !many_seeds.keep_going { // `abort_if_errors` would actually not stop, since `par_for_each` waits for the // rest of the to finish, so we just exit immediately. - std::process::exit(return_code); + exit(return_code); } exit_code.store(return_code, Ordering::Relaxed); num_failed.fetch_add(1, Ordering::Relaxed); @@ -223,7 +229,7 @@ impl rustc_driver::Callbacks for MiriCompilerCalls { if num_failed > 0 { eprintln!("{num_failed}/{total} SEEDS FAILED", total = many_seeds.seeds.count()); } - std::process::exit(exit_code.0.into_inner()); + exit(exit_code.0.into_inner()); } else { let return_code = miri::eval_entry(tcx, entry_def_id, entry_type, &config, None) .unwrap_or_else(|| { @@ -232,7 +238,7 @@ impl rustc_driver::Callbacks for MiriCompilerCalls { tcx.dcx().abort_if_errors(); rustc_driver::EXIT_FAILURE }); - std::process::exit(return_code); + exit(return_code); } // Unreachable. @@ -328,83 +334,31 @@ impl rustc_driver::Callbacks for MiriBeRustCompilerCalls { } } -fn show_error(msg: &impl std::fmt::Display) -> ! { - eprintln!("fatal error: {msg}"); - std::process::exit(1) -} - -macro_rules! show_error { - ($($tt:tt)*) => { show_error(&format_args!($($tt)*)) }; +fn exit(exit_code: i32) -> ! { + // Drop the tracing guard before exiting, so tracing calls are flushed correctly. + deinit_loggers(); + std::process::exit(exit_code); } -fn rustc_logger_config() -> rustc_log::LoggerConfig { - // Start with the usual env vars. - let mut cfg = rustc_log::LoggerConfig::from_env("RUSTC_LOG"); - - // Overwrite if MIRI_LOG is set. - if let Ok(var) = env::var("MIRI_LOG") { - // MIRI_LOG serves as default for RUSTC_LOG, if that is not set. - if matches!(cfg.filter, Err(VarError::NotPresent)) { - // We try to be a bit clever here: if `MIRI_LOG` is just a single level - // used for everything, we only apply it to the parts of rustc that are - // CTFE-related. Otherwise, we use it verbatim for `RUSTC_LOG`. - // This way, if you set `MIRI_LOG=trace`, you get only the right parts of - // rustc traced, but you can also do `MIRI_LOG=miri=trace,rustc_const_eval::interpret=debug`. - if tracing::Level::from_str(&var).is_ok() { - cfg.filter = Ok(format!( - "rustc_middle::mir::interpret={var},rustc_const_eval::interpret={var},miri={var}" - )); - } else { - cfg.filter = Ok(var); - } - } - } - - cfg -} - -/// The global logger can only be set once per process, so track -/// whether that already happened. -static LOGGER_INITED: Once = Once::new(); - -fn init_early_loggers(early_dcx: &EarlyDiagCtxt) { - // We only initialize `rustc` if the env var is set (so the user asked for it). - // If it is not set, we avoid initializing now so that we can initialize later with our custom - // settings, and *not* log anything for what happens before `miri` starts interpreting. - if env::var_os("RUSTC_LOG").is_some() { - LOGGER_INITED.call_once(|| { - rustc_driver::init_logger(early_dcx, rustc_logger_config()); - }); - } +fn fatal_error_(msg: &impl std::fmt::Display) -> ! { + eprintln!("fatal error: {msg}"); + exit(1) } -fn init_late_loggers(early_dcx: &EarlyDiagCtxt, tcx: TyCtxt<'_>) { - // If the logger is not yet initialized, initialize it. - LOGGER_INITED.call_once(|| { - rustc_driver::init_logger(early_dcx, rustc_logger_config()); - }); - - // If `MIRI_BACKTRACE` is set and `RUSTC_CTFE_BACKTRACE` is not, set `RUSTC_CTFE_BACKTRACE`. - // Do this late, so we ideally only apply this to Miri's errors. - if let Some(val) = env::var_os("MIRI_BACKTRACE") { - let ctfe_backtrace = match &*val.to_string_lossy() { - "immediate" => CtfeBacktrace::Immediate, - "0" => CtfeBacktrace::Disabled, - _ => CtfeBacktrace::Capture, - }; - *tcx.sess.ctfe_backtrace.borrow_mut() = ctfe_backtrace; - } +macro_rules! fatal_error { + ($($tt:tt)*) => { $crate::fatal_error_(&format_args!($($tt)*)) }; } +use fatal_error; /// Execute a compiler with the given CLI arguments and callbacks. fn run_compiler_and_exit( args: &[String], callbacks: &mut (dyn rustc_driver::Callbacks + Send), ) -> ! { - // Invoke compiler, and handle return code. + // Invoke compiler, catch any unwinding panics and handle return code. let exit_code = rustc_driver::catch_with_exit_code(move || rustc_driver::run_compiler(args, callbacks)); - std::process::exit(exit_code) + exit(exit_code) } /// Parses a comma separated list of `T` from the given string: @@ -567,7 +521,7 @@ fn main() { params.precise_interior_mut = false; } _ => - show_error!( + fatal_error!( "`-Zmiri-tree-borrows` is required before `-Zmiri-tree-borrows-no-precise-interior-mut`" ), }; @@ -594,7 +548,7 @@ fn main() { "warn-nobacktrace" => miri::IsolatedOp::Reject(miri::RejectOpWith::WarningWithoutBacktrace), _ => - show_error!( + fatal_error!( "-Zmiri-isolation-error must be `abort`, `hide`, `warn`, or `warn-nobacktrace`" ), }; @@ -625,16 +579,16 @@ fn main() { "all" => RetagFields::Yes, "none" => RetagFields::No, "scalar" => RetagFields::OnlyScalar, - _ => show_error!("`-Zmiri-retag-fields` can only be `all`, `none`, or `scalar`"), + _ => fatal_error!("`-Zmiri-retag-fields` can only be `all`, `none`, or `scalar`"), }; } else if let Some(param) = arg.strip_prefix("-Zmiri-seed=") { let seed = param.parse::<u64>().unwrap_or_else(|_| { - show_error!("-Zmiri-seed must be an integer that fits into u64") + fatal_error!("-Zmiri-seed must be an integer that fits into u64") }); miri_config.seed = Some(seed); } else if let Some(param) = arg.strip_prefix("-Zmiri-many-seeds=") { let range = parse_range(param).unwrap_or_else(|err| { - show_error!( + fatal_error!( "-Zmiri-many-seeds requires a range in the form `from..to` or `..to`: {err}" ) }); @@ -651,51 +605,51 @@ fn main() { miri_config.forwarded_env_vars.push(param.to_owned()); } else if let Some(param) = arg.strip_prefix("-Zmiri-env-set=") { let Some((name, value)) = param.split_once('=') else { - show_error!("-Zmiri-env-set requires an argument of the form <name>=<value>"); + fatal_error!("-Zmiri-env-set requires an argument of the form <name>=<value>"); }; miri_config.set_env_vars.insert(name.to_owned(), value.to_owned()); } else if let Some(param) = arg.strip_prefix("-Zmiri-track-pointer-tag=") { let ids: Vec<u64> = parse_comma_list(param).unwrap_or_else(|err| { - show_error!("-Zmiri-track-pointer-tag requires a comma separated list of valid `u64` arguments: {err}") + fatal_error!("-Zmiri-track-pointer-tag requires a comma separated list of valid `u64` arguments: {err}") }); for id in ids.into_iter().map(miri::BorTag::new) { if let Some(id) = id { miri_config.tracked_pointer_tags.insert(id); } else { - show_error!("-Zmiri-track-pointer-tag requires nonzero arguments"); + fatal_error!("-Zmiri-track-pointer-tag requires nonzero arguments"); } } } else if let Some(param) = arg.strip_prefix("-Zmiri-track-alloc-id=") { let ids = parse_comma_list::<NonZero<u64>>(param).unwrap_or_else(|err| { - show_error!("-Zmiri-track-alloc-id requires a comma separated list of valid non-zero `u64` arguments: {err}") + fatal_error!("-Zmiri-track-alloc-id requires a comma separated list of valid non-zero `u64` arguments: {err}") }); miri_config.tracked_alloc_ids.extend(ids.into_iter().map(miri::AllocId)); } else if arg == "-Zmiri-track-alloc-accesses" { miri_config.track_alloc_accesses = true; } else if let Some(param) = arg.strip_prefix("-Zmiri-address-reuse-rate=") { miri_config.address_reuse_rate = parse_rate(param) - .unwrap_or_else(|err| show_error!("-Zmiri-address-reuse-rate {err}")); + .unwrap_or_else(|err| fatal_error!("-Zmiri-address-reuse-rate {err}")); } else if let Some(param) = arg.strip_prefix("-Zmiri-address-reuse-cross-thread-rate=") { miri_config.address_reuse_cross_thread_rate = parse_rate(param) - .unwrap_or_else(|err| show_error!("-Zmiri-address-reuse-cross-thread-rate {err}")); + .unwrap_or_else(|err| fatal_error!("-Zmiri-address-reuse-cross-thread-rate {err}")); } else if let Some(param) = arg.strip_prefix("-Zmiri-compare-exchange-weak-failure-rate=") { miri_config.cmpxchg_weak_failure_rate = parse_rate(param).unwrap_or_else(|err| { - show_error!("-Zmiri-compare-exchange-weak-failure-rate {err}") + fatal_error!("-Zmiri-compare-exchange-weak-failure-rate {err}") }); } else if let Some(param) = arg.strip_prefix("-Zmiri-preemption-rate=") { - miri_config.preemption_rate = - parse_rate(param).unwrap_or_else(|err| show_error!("-Zmiri-preemption-rate {err}")); + miri_config.preemption_rate = parse_rate(param) + .unwrap_or_else(|err| fatal_error!("-Zmiri-preemption-rate {err}")); } else if arg == "-Zmiri-report-progress" { // This makes it take a few seconds between progress reports on my laptop. miri_config.report_progress = Some(1_000_000); } else if let Some(param) = arg.strip_prefix("-Zmiri-report-progress=") { let interval = param.parse::<u32>().unwrap_or_else(|err| { - show_error!("-Zmiri-report-progress requires a `u32`: {}", err) + fatal_error!("-Zmiri-report-progress requires a `u32`: {}", err) }); miri_config.report_progress = Some(interval); } else if let Some(param) = arg.strip_prefix("-Zmiri-provenance-gc=") { let interval = param.parse::<u32>().unwrap_or_else(|err| { - show_error!("-Zmiri-provenance-gc requires a `u32`: {}", err) + fatal_error!("-Zmiri-provenance-gc requires a `u32`: {}", err) }); miri_config.gc_interval = interval; } else if let Some(param) = arg.strip_prefix("-Zmiri-measureme=") { @@ -705,7 +659,7 @@ fn main() { "0" => BacktraceStyle::Off, "1" => BacktraceStyle::Short, "full" => BacktraceStyle::Full, - _ => show_error!("-Zmiri-backtrace may only be 0, 1, or full"), + _ => fatal_error!("-Zmiri-backtrace may only be 0, 1, or full"), }; } else if let Some(param) = arg.strip_prefix("-Zmiri-native-lib=") { let filename = param.to_string(); @@ -722,27 +676,27 @@ fn main() { miri_config.native_lib.push(filename.into()); } } else { - show_error!("-Zmiri-native-lib `{}` does not exist", filename); + fatal_error!("-Zmiri-native-lib `{}` does not exist", filename); } } else if arg == "-Zmiri-native-lib-enable-tracing" { miri_config.native_lib_enable_tracing = true; } else if let Some(param) = arg.strip_prefix("-Zmiri-num-cpus=") { let num_cpus = param .parse::<u32>() - .unwrap_or_else(|err| show_error!("-Zmiri-num-cpus requires a `u32`: {}", err)); + .unwrap_or_else(|err| fatal_error!("-Zmiri-num-cpus requires a `u32`: {}", err)); if !(1..=miri::MAX_CPUS).contains(&usize::try_from(num_cpus).unwrap()) { - show_error!("-Zmiri-num-cpus must be in the range 1..={}", miri::MAX_CPUS); + fatal_error!("-Zmiri-num-cpus must be in the range 1..={}", miri::MAX_CPUS); } miri_config.num_cpus = num_cpus; } else if let Some(param) = arg.strip_prefix("-Zmiri-force-page-size=") { let page_size = param.parse::<u64>().unwrap_or_else(|err| { - show_error!("-Zmiri-force-page-size requires a `u64`: {}", err) + fatal_error!("-Zmiri-force-page-size requires a `u64`: {}", err) }); // Convert from kilobytes to bytes. let page_size = if page_size.is_power_of_two() { page_size * 1024 } else { - show_error!("-Zmiri-force-page-size requires a power of 2: {page_size}"); + fatal_error!("-Zmiri-force-page-size requires a power of 2: {page_size}"); }; miri_config.page_size = Some(page_size); } else { @@ -753,22 +707,22 @@ fn main() { // Tree Borrows implies strict provenance, and is not compatible with native calls. if matches!(miri_config.borrow_tracker, Some(BorrowTrackerMethod::TreeBorrows { .. })) { if miri_config.provenance_mode != ProvenanceMode::Strict { - show_error!( + fatal_error!( "Tree Borrows does not support integer-to-pointer casts, and hence requires strict provenance" ); } if !miri_config.native_lib.is_empty() { - show_error!("Tree Borrows is not compatible with calling native functions"); + fatal_error!("Tree Borrows is not compatible with calling native functions"); } } // Native calls and strict provenance are not compatible. if !miri_config.native_lib.is_empty() && miri_config.provenance_mode == ProvenanceMode::Strict { - show_error!("strict provenance is not compatible with calling native functions"); + fatal_error!("strict provenance is not compatible with calling native functions"); } // You can set either one seed or many. if many_seeds.is_some() && miri_config.seed.is_some() { - show_error!("Only one of `-Zmiri-seed` and `-Zmiri-many-seeds can be set"); + fatal_error!("Only one of `-Zmiri-seed` and `-Zmiri-many-seeds can be set"); } // Ensure we have parallelism for many-seeds mode. @@ -784,12 +738,12 @@ fn main() { assert_eq!(genmc_config.is_some(), miri_config.genmc_mode); if genmc_config.is_some() { if !miri_config.data_race_detector { - show_error!("Cannot disable data race detection in GenMC mode (currently)"); + fatal_error!("Cannot disable data race detection in GenMC mode (currently)"); } else if !miri_config.weak_memory_emulation { - show_error!("Cannot disable weak memory emulation in GenMC mode"); + fatal_error!("Cannot disable weak memory emulation in GenMC mode"); } } else if miri_config.weak_memory_emulation && !miri_config.data_race_detector { - show_error!( + fatal_error!( "Weak memory emulation cannot be enabled when the data race detector is disabled" ); }; diff --git a/src/tools/miri/src/machine.rs b/src/tools/miri/src/machine.rs index 014b83922cc..ebf04c4f049 100644 --- a/src/tools/miri/src/machine.rs +++ b/src/tools/miri/src/machine.rs @@ -1014,6 +1014,8 @@ impl<'tcx> Machine<'tcx> for MiriMachine<'tcx> { const PANIC_ON_ALLOC_FAIL: bool = false; + const TRACING_ENABLED: bool = cfg!(feature = "tracing"); + #[inline(always)] fn enforce_alignment(ecx: &MiriInterpCx<'tcx>) -> bool { ecx.machine.check_alignment != AlignmentCheck::None |