perf(cli): use new deno_core timers (#22569)

Improves #19100 

Fixes #20356

Replaces #20428



Changes made in deno_core to support this:

 - [x] Errors must be handled in setTimeout callbacks
 - [x] Microtask ordering is not-quite-right
 - [x] Timer cancellation must be checked right before dispatch
 - [x] Timer sanitizer
 - [x] Move high-res timer to deno_core
 - [x] Timers need opcall tracing

2 files changed, 60 insertions, 47 deletions

diff --git a/cli/tools/test/fmt.rs b/cli/tools/test/fmt.rs
index 7dc9ceabf..1c1c09e1d 100644
--- a/cli/tools/test/fmt.rs
+++ b/cli/tools/test/fmt.rs
@@ -147,14 +147,46 @@ fn format_sanitizer_accum(
         String::new()
       };
       output.push(value);
+    } else if item_type == RuntimeActivityType::Timer {
+      let (count_str, plural, tense) = if count == 1 {
+        (Cow::Borrowed("A"), "", "was")
+      } else {
+        (Cow::Owned(count.to_string()), "s", "were")
+      };
+      let phrase = if appeared {
+        "started in this test, but never completed"
+      } else {
+        "started before the test, but completed during the test. Intervals and timers should not complete in a test if they were not started in that test"
+      };
+      let mut value = format!("{count_str} timer{plural} {tense} {phrase}. This is often caused by not calling `clearTimeout`.");
+      value += &if let Some(trace) = trace {
+        format!(" The operation {tense} started here:\n{trace}")
+      } else {
+        needs_trace_leaks = true;
+        String::new()
+      };
+      output.push(value);
+    } else if item_type == RuntimeActivityType::Interval {
+      let (count_str, plural, tense) = if count == 1 {
+        (Cow::Borrowed("An"), "", "was")
+      } else {
+        (Cow::Owned(count.to_string()), "s", "were")
+      };
+      let phrase = if appeared {
+        "started in this test, but never completed"
+      } else {
+        "started before the test, but completed during the test. Intervals and timers should not complete in a test if they were not started in that test"
+      };
+      let mut value = format!("{count_str} interval{plural} {tense} {phrase}. This is often caused by not calling `clearInterval`.");
+      value += &if let Some(trace) = trace {
+        format!(" The operation {tense} started here:\n{trace}")
+      } else {
+        needs_trace_leaks = true;
+        String::new()
+      };
+      output.push(value);
     } else {
-      // TODO(mmastrac): this will be done in a later PR
-      unimplemented!(
-        "Unhandled diff: {appeared} {} {:?} {}",
-        count,
-        item_type,
-        item_name
-      );
+      unreachable!()
     }
   }
   if needs_trace_leaks {
@@ -176,9 +208,9 @@ fn format_sanitizer_accum_item(
     RuntimeActivity::AsyncOp(_, trace, name) => {
       (activity_type, name.into(), trace)
     }
-    RuntimeActivity::Interval(..) => (activity_type, "".into(), None),
-    RuntimeActivity::Resource(.., name) => (activity_type, name.into(), None),
-    RuntimeActivity::Timer(..) => (activity_type, "".into(), None),
+    RuntimeActivity::Resource(_, _, name) => (activity_type, name.into(), None),
+    RuntimeActivity::Interval(_, trace) => (activity_type, "".into(), trace),
+    RuntimeActivity::Timer(_, trace) => (activity_type, "".into(), trace),
   }
 }
 
@@ -310,8 +342,6 @@ pub const OP_DETAILS: phf::Map<&'static str, [&'static str; 2]> = phf_map! {
   "op_run_status" => ["get the status of a subprocess", "awaiting the result of a `Deno.Process#status` call"],
   "op_seek_async" => ["seek in a file", "awaiting the result of a `Deno.File#seek` call"],
   "op_signal_poll" => ["get the next signal", "un-registering a OS signal handler"],
-  "op_sleep_interval" => ["sleep for a duration", "cancelling a `setTimeout` or `setInterval` call"],
-  "op_sleep" => ["sleep for a duration", "cancelling a `setTimeout` or `setInterval` call"],
   "op_stat_async" => ["get file metadata", "awaiting the result of a `Deno.stat` call"],
   "op_symlink_async" => ["create a symlink", "awaiting the result of a `Deno.symlink` call"],
   "op_net_accept_tls" => ["accept a TLS stream", "closing a `Deno.TlsListener`"],
diff --git a/cli/tools/test/mod.rs b/cli/tools/test/mod.rs
index 4ec90050e..0f10188bc 100644
--- a/cli/tools/test/mod.rs
+++ b/cli/tools/test/mod.rs
@@ -728,6 +728,7 @@ async fn run_tests_for_worker_inner(
   let mut filter = RuntimeActivityStatsFilter::default();
   filter = filter.with_resources();
   filter = filter.with_ops();
+  filter = filter.with_timers();
   filter = filter.omit_op(op_id_host_recv_ctrl as _);
   filter = filter.omit_op(op_id_host_recv_message as _);
 
@@ -825,37 +826,6 @@ async fn run_tests_for_worker_inner(
   Ok(())
 }
 
-/// Removes timer resources and op_sleep_interval calls. When an interval is started before a test
-/// and resolves during a test, there's a false alarm.
-fn preprocess_timer_activity(activities: &mut Vec<RuntimeActivity>) {
-  // TODO(mmastrac): Once we get to the new timer implementation, all of this
-  // code can go away and be replaced by a proper timer sanitizer.
-  let mut timer_resource_leaked = false;
-
-  // First, search for any timer resources which will indicate that we have an interval leak
-  activities.retain(|activity| {
-    if let RuntimeActivity::Resource(.., name) = activity {
-      if name == "timer" {
-        timer_resource_leaked = true;
-        return false;
-      }
-    }
-    true
-  });
-
-  // If we've leaked a timer resource, we un-mute op_sleep_interval calls. Otherwise, we remove
-  // them.
-  if !timer_resource_leaked {
-    activities.retain(|activity| {
-      if let RuntimeActivity::AsyncOp(.., op) = activity {
-        *op != "op_sleep_interval"
-      } else {
-        true
-      }
-    })
-  }
-}
-
 async fn wait_for_activity_to_stabilize(
   worker: &mut MainWorker,
   stats: &RuntimeActivityStatsFactory,
@@ -867,8 +837,6 @@ async fn wait_for_activity_to_stabilize(
   // First, check to see if there's any diff at all. If not, just continue.
   let after = stats.clone().capture(filter);
   let mut diff = RuntimeActivityStats::diff(&before, &after);
-  preprocess_timer_activity(&mut diff.appeared);
-  preprocess_timer_activity(&mut diff.disappeared);
   if diff.is_empty() {
     // No activity, so we return early
     return Ok(None);
@@ -884,8 +852,6 @@ async fn wait_for_activity_to_stabilize(
 
     let after = stats.clone().capture(filter);
     diff = RuntimeActivityStats::diff(&before, &after);
-    preprocess_timer_activity(&mut diff.appeared);
-    preprocess_timer_activity(&mut diff.disappeared);
     if diff.is_empty() {
       return Ok(None);
     }
@@ -908,6 +874,23 @@ async fn wait_for_activity_to_stabilize(
       .retain(|activity| !matches!(activity, RuntimeActivity::Resource(..)));
   }
 
+  // Since we don't have an option to disable timer sanitization, we use sanitize_ops == false &&
+  // sanitize_resources == false to disable those.
+  if !sanitize_ops && !sanitize_resources {
+    diff.appeared.retain(|activity| {
+      !matches!(
+        activity,
+        RuntimeActivity::Timer(..) | RuntimeActivity::Interval(..)
+      )
+    });
+    diff.disappeared.retain(|activity| {
+      !matches!(
+        activity,
+        RuntimeActivity::Timer(..) | RuntimeActivity::Interval(..)
+      )
+    });
+  }
+
   Ok(if diff.is_empty() { None } else { Some(diff) })
 }