Cranelift: robustify timing infrastructure against mis-use and/or system clock bugs. (#12709)

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.

Author: cfallin

cranelift/codegen/src/timing.rs

@@ -220,21 +220,51 @@ 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<Pass> = const { Cell::new(Pass::None) };
+        static LAST_INSTANT: Cell<Option<Instant>> = 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 {
         fn start_pass(&self, pass: Pass) -> Box<dyn Any> {
             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;