From 9e407ce37b582e330425244b73ea0b0471f3bfb3 Mon Sep 17 00:00:00 2001 From: Chris Fallin Date: Tue, 3 Mar 2026 10:35:20 -0800 Subject: [PATCH 1/4] Cranelift: robustify timing infrastructure against mis-use and/or system clock bugs. In #12692, it was observed that the computation of time spent in nested timing spans, minus child time, was underflowing. Correct operation of the handling of nested spans depends on the invariant that the accumulated time for child spans is less than or equal to a parent span once timing is completed. This property should hold as long as the system clock is monotonic, and as long as timing tokens are dropped in-order, so that the elapsed time of a parent truly is computed after the elapsed time of a child ends. The timing state may also temporarily violate this invariant whenever a token is pending (still on stack and timing): the child time of any completed child spans will be counted, but the parent has not yet been. Hence, taking a snapshot of the state and computing "parent minus children" on that snapshot may observe cases that yield underflow. This PR makes the infrastructure more robust along a few different dimensions: - It hardens the clock source we use to have a locally-ensured guarantee of monotonicity, since we rely on this for logical correctness. In particular, for each thread (since timing spans never move between threads), we track the last `Instant` that was used by the timing infrastructure, and use that value (zero time passed) if the system clock moves backward. - It hardens the assert about pass-timing token drop order from a `debug_assert` to an `assert`. If this invariant is being violated, we want to know about it noisily, rather than observing a subtraction underflow or other inconsistency later. - It adds an assert in `take_current()` to ensure that a snapshot is never taken when any pass timing is in progress. This should address any theoretically possible sources of #12692, as far as I can tell. (cherry picked from commit 2f8644f1507739cfe3866bad9fd905730fe3bd66) --- cranelift/codegen/src/timing.rs | 37 ++++++++++++++++++++++++++++++--- 1 file changed, 34 insertions(+), 3 deletions(-) diff --git a/cranelift/codegen/src/timing.rs b/cranelift/codegen/src/timing.rs index a61dd21f7956..2be2a5981e1d 100644 --- a/cranelift/codegen/src/timing.rs +++ b/cranelift/codegen/src/timing.rs @@ -220,13 +220,43 @@ mod enabled { /// Take the current accumulated pass timings and reset the timings for the current thread. /// /// Only applies when [`DefaultProfiler`] is used. + /// + /// # Panics + /// + /// Panics when any pass timing token is currently active. pub fn take_current() -> PassTimes { + assert_eq!( + CURRENT_PASS.with(|p| p.get()), + Pass::None, + "Cannot take_current() on profiler while a pass is active" + ); PASS_TIME.with(|rc| mem::take(&mut *rc.borrow_mut())) } // Information about passes in a single thread. thread_local! { static CURRENT_PASS: Cell = const { Cell::new(Pass::None) }; + static LAST_INSTANT: Cell> = Cell::new(None); + } + + /// Provides a guaranteed-never-decreasing `Instant`. This is + /// supposed to be guaranteed by the operating system APIs that + /// are used to implement `Instant::now()`, but apparently + /// sometimes kernel bugs may result in this moving backward, and + /// if it does, our invariants here are violated, possibly + /// resulting in panics when we process nested time spans. So we + /// backstop against any bugs by tracking the last-returned + /// `Instant` and never regressing before it. + fn monotonic_instant() -> Instant { + let now = match LAST_INSTANT.get() { + None => Instant::now(), + Some(prev) => { + let system_now = Instant::now(); + core::cmp::max(prev, system_now) + } + }; + LAST_INSTANT.set(Some(now)); + now } impl Profiler for DefaultProfiler { @@ -234,7 +264,7 @@ mod enabled { let prev = CURRENT_PASS.with(|p| p.replace(pass)); log::debug!("timing: Starting {pass}, (during {prev})"); Box::new(DefaultTimingToken { - start: Instant::now(), + start: monotonic_instant(), pass, prev, }) @@ -260,10 +290,11 @@ mod enabled { /// Dropping a timing token indicated the end of the pass. impl Drop for DefaultTimingToken { fn drop(&mut self) { - let duration = self.start.elapsed(); + let now = monotonic_instant(); + let duration = self.start.duration_since(now); log::debug!("timing: Ending {}: {}ms", self.pass, duration.as_millis()); let old_cur = CURRENT_PASS.with(|p| p.replace(self.prev)); - debug_assert_eq!(self.pass, old_cur, "Timing tokens dropped out of order"); + assert_eq!(self.pass, old_cur, "Timing tokens dropped out of order"); PASS_TIME.with(|rc| { let mut table = rc.borrow_mut(); table.pass[self.pass.idx()].total += duration; From 7750d148f5ff7d56de8ab8cf35805b4f9fb1e561 Mon Sep 17 00:00:00 2001 From: Ben Brandt Date: Tue, 5 May 2026 16:38:00 +0200 Subject: [PATCH 2/4] Update releases.md --- RELEASES.md | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/RELEASES.md b/RELEASES.md index 4bc21d76d177..acc230540256 100644 --- a/RELEASES.md +++ b/RELEASES.md @@ -1,3 +1,13 @@ +## 36.0.9 + +Released 2026-04-30. + +### Fixed + +* Cranelift's timing infrastructure is now more robust in the face of buggy system clocks. #13273 + +-------------------------------------------------------------------------------- + ## 36.0.8 Released 2026-04-30. From 16bfeeee1c48e17803846caae06b8380bec13f1d Mon Sep 17 00:00:00 2001 From: Alex Crichton Date: Fri, 1 May 2026 16:54:20 -0700 Subject: [PATCH 3/4] Fix timing information in cranelift A typo in #12709 accidentally led to all passes clocking in at 0ns. Swap the order of arguments to get true timing information. (cherry picked from commit 8b664c34e974d8d31552d5e452489f1ace9a123e) --- cranelift/codegen/src/timing.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cranelift/codegen/src/timing.rs b/cranelift/codegen/src/timing.rs index 2be2a5981e1d..feaf142e7243 100644 --- a/cranelift/codegen/src/timing.rs +++ b/cranelift/codegen/src/timing.rs @@ -291,7 +291,7 @@ mod enabled { impl Drop for DefaultTimingToken { fn drop(&mut self) { let now = monotonic_instant(); - let duration = self.start.duration_since(now); + let duration = now.duration_since(self.start); log::debug!("timing: Ending {}: {}ms", self.pass, duration.as_millis()); let old_cur = CURRENT_PASS.with(|p| p.replace(self.prev)); assert_eq!(self.pass, old_cur, "Timing tokens dropped out of order"); From c88bab54be111cc9c08dd005b354cb214e62eeb4 Mon Sep 17 00:00:00 2001 From: Ben Brandt Date: Tue, 5 May 2026 16:58:17 +0200 Subject: [PATCH 4/4] Fix releases update --- RELEASES.md | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/RELEASES.md b/RELEASES.md index acc230540256..d70670862ade 100644 --- a/RELEASES.md +++ b/RELEASES.md @@ -1,10 +1,12 @@ ## 36.0.9 -Released 2026-04-30. +Released 2026-05-05. ### Fixed -* Cranelift's timing infrastructure is now more robust in the face of buggy system clocks. #13273 +* Cranelift's timing infrastructure is now more robust in the face of buggy system clocks. + [#12709](https://github.com/bytecodealliance/wasmtime/pull/12709) + [#13253](https://github.com/bytecodealliance/wasmtime/pull/13253) --------------------------------------------------------------------------------