diff --git a/cranelift/codegen/src/timing.rs b/cranelift/codegen/src/timing.rs index a06c6001ef41..2d10e97a94d7 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;