Auto merge of #153402 - RalfJung:miri, r=RalfJung

miri subtree update

Subtree update of `miri` to rust-lang/miri@c37cbf8.

Created using https://github.com/rust-lang/josh-sync.

r? @ghost

Author: bors

src/tools/miri/CONTRIBUTING.md

@@ -189,6 +189,8 @@ you can visualize in [Perfetto](https://ui.perfetto.dev/). For example:
 MIRI_TRACING=1 ./miri run --features=tracing tests/pass/hello.rs
 ```
 
+See [doc/tracing.md](./doc/tracing.md) for more information.
+
 ### UI testing
 
 We use ui-testing in Miri, meaning we generate `.stderr` and `.stdout` files for the output

src/tools/miri/doc/tracing.md

@@ -2,6 +2,9 @@
 
 Miri can be traced to understand how much time is spent in its various components (e.g. borrow tracker, data race checker, etc.). When tracing is enabled, running Miri will create a `.json` trace file that can be opened and analyzed in [Perfetto](https://ui.perfetto.dev/). For any questions regarding this documentation you may contact [Stypox](https://rust-lang.zulipchat.com/#narrow/dm/627563-Stypox) on Zulip.
 
+> [!WARNING]
+> Tracing in Miri at the moment is broken due to two bugs in tracing libraries: https://github.com/tokio-rs/tracing/pull/3392 and https://github.com/davidbarsky/tracing-tree/issues/93. Also see https://github.com/rust-lang/miri/issues/4752.
+
 ## Obtaining a trace file
 
 ### From the Miri codebase
@@ -240,7 +243,7 @@ let _trace = enter_trace_span!(M, "borrow_tracker", borrow_tracker = "on_stack_p
 
 ### `tracing_separate_thread` parameter
 
-Miri saves traces using the the `tracing_chrome` `tracing::Layer` so that they can be visualized in Perfetto. To instruct `tracing_chrome` to put some spans on a separate trace thread/line than other spans when viewed in Perfetto, you can pass `tracing_separate_thread = tracing::field::Empty` to the tracing macros. This is useful to separate out spans which just indicate the current step or program frame being processed by the interpreter. As explained in [The timeline](#the-timeline), those spans end up under the "Global Legacy Events" track. You should use a value of `tracing::field::Empty` so that other tracing layers (e.g. the logger) will ignore the `tracing_separate_thread` field. For example:
+Miri saves traces using the `tracing_chrome` `tracing::Layer` so that they can be visualized in Perfetto. To instruct `tracing_chrome` to put some spans on a separate trace thread/line than other spans when viewed in Perfetto, you can pass `tracing_separate_thread = tracing::field::Empty` to the tracing macros. This is useful to separate out spans which just indicate the current step or program frame being processed by the interpreter. As explained in [The timeline](#the-timeline), those spans end up under the "Global Legacy Events" track. You should use a value of `tracing::field::Empty` so that other tracing layers (e.g. the logger) will ignore the `tracing_separate_thread` field. For example:
 ```rust
 let _trace = enter_trace_span!(M, step::eval_statement, tracing_separate_thread = tracing::field::Empty);
 ```
@@ -277,9 +280,12 @@ So the solution was to copy-paste [the only file](https://github.com/thoren-d/tr
 
 ### Time measurements
 
-tracing-chrome originally used `std::time::Instant` to measure time, however on some x86/x86_64 Linux systems it might be unbearably slow since the underlying system call (`clock_gettime`) would take ≈1.3µs. Read more [here](https://btorpey.github.io/blog/2014/02/18/clock-sources-in-linux/) about how the Linux kernel chooses the clock source.
+tracing-chrome uses `std::time::Instant` to measure time. On most modern systems this is ok, since the underlying system call (`clock_gettime`) uses very fast hardware counters (e.g. `tsc`) and has a latency of ≈16ns.
+
+On some x86/x86_64 Linux systems, however, `tsc` is not "reliable" and the system thus relies on other timers, e.g. `hpet` which takes ≈1.3µs. Read [here](https://btorpey.github.io/blog/2014/02/18/clock-sources-in-linux/) how the Linux kernel chooses the clock source, and how to check if your system is using `tsc`. If it doesn't use `tsc`, then expect most of the trace time being spent in time measurements, which degrades traces' usefulness... See [here](https://github.com/rust-lang/miri/issues/4563) for some discussion.
 
-Therefore, on x86/x86_64 Linux systems with a CPU that has an invariant TSC counter, we read from that instead to measure time, which takes only ≈13ns. There are unfortunately a lot of caveats to this approach though, as explained [in the code](https://github.com/rust-lang/miri/blob/master/src/bin/log/tracing_chrome_instant.rs) and [in the PR](https://github.com/rust-lang/miri/pull/4524). The most impactful one is that: every thread spawned in Miri that wants to trace something (which requires measuring time) needs to pin itself to a single CPU core (using `sched_setaffinity`).
+> [!WARNING]
+> A (somewhat risky) workaround is to add `tsc=reliable clocksource=tsc hpet=disable` to the kernel boot parameters, which forces it to use `tsc` even if it is unreliable. But this may render the system unstable, so try it at your own risk!
 
 ## Other useful stuff
 

src/tools/miri/rust-version

@@ -1 +1 @@
-7bee525095c0872e87c038c412c781b9bbb3f5dc
+d933cf483edf1605142ac6899ff32536c0ad8b22

src/tools/miri/src/alloc_addresses/mod.rs

@@ -168,7 +168,11 @@ trait EvalContextExtPriv<'tcx>: crate::MiriInterpCxExt<'tcx> {
                     if let Some(GlobalAlloc::Function { instance, .. }) =
                         this.tcx.try_get_global_alloc(alloc_id)
                     {
-                        let fn_sig = this.tcx.fn_sig(instance.def_id()).skip_binder().skip_binder();
+                        let fn_sig = this.tcx.instantiate_bound_regions_with_erased(
+                            this.tcx
+                                .fn_sig(instance.def_id())
+                                .instantiate(*this.tcx, instance.args),
+                        );
                         let fn_ptr = crate::shims::native_lib::build_libffi_closure(this, fn_sig)?;
 
                         #[expect(

src/tools/miri/src/bin/log/mod.rs

@@ -1,3 +1,2 @@
 pub mod setup;
 mod tracing_chrome;
-mod tracing_chrome_instant;

src/tools/miri/src/bin/log/tracing_chrome.rs

@@ -50,9 +50,8 @@ use std::{
     thread::JoinHandle,
 };
 
-use crate::log::tracing_chrome_instant::TracingChromeInstant;
-
 /// Contains thread-local data for threads that send tracing spans or events.
+#[derive(Clone)]
 struct ThreadData {
     /// A unique ID for this thread, will populate "tid" field in the output trace file.
     tid: usize,
@@ -61,7 +60,7 @@ struct ThreadData {
     out: Sender<Message>,
     /// The instant in time this thread was started. All events happening on this thread will be
     /// saved to the trace file with a timestamp (the "ts" field) measured relative to this instant.
-    start: TracingChromeInstant,
+    start: std::time::Instant,
 }
 
 thread_local! {
@@ -562,28 +561,46 @@ where
     #[inline(always)]
     fn with_elapsed_micros_subtracting_tracing(&self, f: impl Fn(f64, usize, &Sender<Message>)) {
         THREAD_DATA.with(|value| {
-            let mut thread_data = value.borrow_mut();
-            let (ThreadData { tid, out, start }, new_thread) = match thread_data.as_mut() {
-                Some(thread_data) => (thread_data, false),
-                None => {
-                    let tid = self.max_tid.fetch_add(1, Ordering::SeqCst);
-                    let out = self.out.lock().unwrap().clone();
-                    let start = TracingChromeInstant::setup_for_thread_and_start(tid);
-                    *thread_data = Some(ThreadData { tid, out, start });
-                    (thread_data.as_mut().unwrap(), true)
+            // Make sure not to keep `value` borrowed when calling `f` below, since the user tracing
+            // code that `f` might invoke (e.g. fmt::Debug argument formatting) may contain nested
+            // tracing calls that would cause `value` to be doubly-borrowed mutably.
+            let (ThreadData { tid, out, start }, new_thread) = {
+                let mut thread_data = value.borrow_mut();
+                match thread_data.as_mut() {
+                    Some(thread_data) => (thread_data.clone(), false),
+                    None => {
+                        let tid = self.max_tid.fetch_add(1, Ordering::SeqCst);
+                        let out = self.out.lock().unwrap().clone();
+                        let start = std::time::Instant::now();
+                        *thread_data = Some(ThreadData { tid, out: out.clone(), start });
+                        (ThreadData { tid, out, start }, true)
+                    }
                 }
             };
 
-            start.with_elapsed_micros_subtracting_tracing(|ts| {
-                if new_thread {
-                    let name = match std::thread::current().name() {
-                        Some(name) => name.to_owned(),
-                        None => tid.to_string(),
-                    };
-                    let _ignored = out.send(Message::NewThread(*tid, name));
-                }
-                f(ts, *tid, out);
-            });
+            // Obtain the current time (before executing `f`).
+            let instant_before_f = std::time::Instant::now();
+
+            // Using the current time (`instant_before_f`), calculate the elapsed time (in
+            // microseconds) since `start` was instantiated, accounting for any time that was
+            // previously spent executing `f`. The "accounting" part is not computed in this
+            // line, but is rather done by shifting forward the `start` down below.
+            let ts = (instant_before_f - start).as_nanos() as f64 / 1000.0;
+
+            // Run the function (supposedly a function internal to the tracing infrastructure).
+            if new_thread {
+                let name = match std::thread::current().name() {
+                    Some(name) => name.to_owned(),
+                    None => tid.to_string(),
+                };
+                let _ignored = out.send(Message::NewThread(tid, name));
+            }
+            f(ts, tid, &out);
+
+            // Measure how much time was spent executing `f` and shift `start` forward
+            // by that amount. This "removes" that time from the trace.
+            // See comment at the top of this function for why we have to re-borrow here.
+            value.borrow_mut().as_mut().unwrap().start += std::time::Instant::now() - instant_before_f;
         });
     }
 }