perf: make deno test 10x faster (#20550)

Cargo.lock

@@ -1217,9 +1217,9 @@ dependencies = [
 
 [[package]]
 name = "deno_core"
-version = "0.213.0"
+version = "0.214.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "d1799de49977a9b73cd8f931ff429b452f3adfb2d5e9648098905923381a374f"
+checksum = "be0af76effe9a766f7c9a253171ab10b9adfaf4b10c6eb0b9f005f9dd0ba2948"
 dependencies = [
  "anyhow",
  "bytes",

Cargo.toml

@@ -40,7 +40,7 @@ repository = "https://github.com/denoland/deno"
 [workspace.dependencies]
 deno_ast = { version = "0.29.3", features = ["transpiling"] }
 
-deno_core = { version = "0.213.0" }
+deno_core = { version = "0.214.0" }
 
 deno_runtime = { version = "0.126.0", path = "./runtime" }
 napi_sym = { version = "0.48.0", path = "./cli/napi/sym" }

cli/js/40_testing.js

@@ -22,7 +22,6 @@ const {
   MapPrototypeSet,
   MathCeil,
   ObjectKeys,
-  ObjectHasOwn,
   ObjectPrototypeIsPrototypeOf,
   Promise,
   SafeArrayIterator,
@@ -151,26 +150,14 @@ const OP_DETAILS = {
   "op_ws_send_pong": ["send a message on a WebSocket", "closing a `WebSocket` or `WebSocketStream`"],
 };
 
-function collectReliableOpMetrics() {
-  let metrics = core.metrics();
-  if (metrics.opsDispatched > metrics.opsCompleted) {
-    // If there are still async ops pending, we drain the event loop to the
-    // point where all ops that can return `Poll::Ready` have done so, to ensure
-    // that any ops are ready because of user cleanup code are completed.
-    const hasPendingWorkerOps = metrics.ops.op_host_recv_message && (
-      metrics.ops.op_host_recv_message.opsDispatched >
-        metrics.ops.op_host_recv_message.opsCompleted ||
-      metrics.ops.op_host_recv_ctrl.opsDispatched >
-        metrics.ops.op_host_recv_ctrl.opsCompleted
-    );
-    return opSanitizerDelay(hasPendingWorkerOps).then(() => {
-      metrics = core.metrics();
-      const traces = new Map(core.opCallTraces);
-      return { metrics, traces };
-    });
-  }
-  const traces = new Map(core.opCallTraces);
-  return { metrics, traces };
+let opIdHostRecvMessage = -1;
+let opIdHostRecvCtrl = -1;
+let opNames = null;
+
+function populateOpNames() {
+  opNames = core.ops.op_op_names();
+  opIdHostRecvMessage = opNames.indexOf("op_host_recv_message");
+  opIdHostRecvCtrl = opNames.indexOf("op_host_recv_ctrl");
 }
 
 // Wrap test function in additional assertion that makes sure
@@ -181,50 +168,61 @@ function collectReliableOpMetrics() {
 function assertOps(fn) {
   /** @param desc {TestDescription | TestStepDescription} */
   return async function asyncOpSanitizer(desc) {
-    let metrics = collectReliableOpMetrics();
-    if (metrics.then) {
-      // We're delaying so await to get the result asynchronously.
-      metrics = await metrics;
+    if (opNames === null) populateOpNames();
+    const res = core.ops.op_test_op_sanitizer_collect(
+      desc.id,
+      false,
+      opIdHostRecvMessage,
+      opIdHostRecvCtrl,
+    );
+    if (res !== 0) {
+      await opSanitizerDelay(res === 2);
+      core.ops.op_test_op_sanitizer_collect(
+        desc.id,
+        true,
+        opIdHostRecvMessage,
+        opIdHostRecvCtrl,
+      );
     }
-    const { metrics: pre, traces: preTraces } = metrics;
-    let post;
+    const preTraces = new Map(core.opCallTraces);
     let postTraces;
+    let report = null;
 
     try {
       const innerResult = await fn(desc);
       if (innerResult) return innerResult;
     } finally {
-      let metrics = collectReliableOpMetrics();
-      if (metrics.then) {
-        // We're delaying so await to get the result asynchronously.
-        metrics = await metrics;
+      let res = core.ops.op_test_op_sanitizer_finish(
+        desc.id,
+        false,
+        opIdHostRecvMessage,
+        opIdHostRecvCtrl,
+      );
+      if (res === 1 || res === 2) {
+        await opSanitizerDelay(res === 2);
+        res = core.ops.op_test_op_sanitizer_finish(
+          desc.id,
+          true,
+          opIdHostRecvMessage,
+          opIdHostRecvCtrl,
+        );
+      }
+      postTraces = new Map(core.opCallTraces);
+      if (res === 3) {
+        report = core.ops.op_test_op_sanitizer_report(desc.id);
       }
-      ({ metrics: post, traces: postTraces } = metrics);
     }
 
-    // We're checking diff because one might spawn HTTP server in the background
-    // that will be a pending async op before test starts.
-    const dispatchedDiff = post.opsDispatchedAsync - pre.opsDispatchedAsync;
-    const completedDiff = post.opsCompletedAsync - pre.opsCompletedAsync;
-
-    if (dispatchedDiff === completedDiff) return null;
+    if (report === null) return null;
 
     const details = [];
-    for (const key in post.ops) {
-      if (!ObjectHasOwn(post.ops, key)) {
-        continue;
-      }
-      const preOp = pre.ops[key] ??
-        { opsDispatchedAsync: 0, opsCompletedAsync: 0 };
-      const postOp = post.ops[key];
-      const dispatchedDiff = postOp.opsDispatchedAsync -
-        preOp.opsDispatchedAsync;
-      const completedDiff = postOp.opsCompletedAsync -
-        preOp.opsCompletedAsync;
+    for (const opReport of report) {
+      const opName = opNames[opReport.id];
+      const diff = opReport.diff;
 
-      if (dispatchedDiff > completedDiff) {
-        const [name, hint] = OP_DETAILS[key] || [key, null];
-        const count = dispatchedDiff - completedDiff;
+      if (diff > 0) {
+        const [name, hint] = OP_DETAILS[opName] || [opName, null];
+        const count = diff;
         let message = `${count} async operation${
           count === 1 ? "" : "s"
         } to ${name} ${
@@ -234,8 +232,8 @@ function assertOps(fn) {
           message += ` This is often caused by not ${hint}.`;
         }
         const traces = [];
-        for (const [id, { opName, stack }] of postTraces) {
-          if (opName !== key) continue;
+        for (const [id, { opName: traceOpName, stack }] of postTraces) {
+          if (traceOpName !== opName) continue;
           if (MapPrototypeHas(preTraces, id)) continue;
           ArrayPrototypePush(traces, stack);
         }
@@ -247,9 +245,9 @@ function assertOps(fn) {
           message += ArrayPrototypeJoin(traces, "\n\n");
         }
         ArrayPrototypePush(details, message);
-      } else if (dispatchedDiff < completedDiff) {
-        const [name, hint] = OP_DETAILS[key] || [key, null];
-        const count = completedDiff - dispatchedDiff;
+      } else if (diff < 0) {
+        const [name, hint] = OP_DETAILS[opName] || [opName, null];
+        const count = -diff;
         let message = `${count} async operation${
           count === 1 ? "" : "s"
         } to ${name} ${
@@ -261,8 +259,8 @@ function assertOps(fn) {
           message += ` This is often caused by not ${hint}.`;
         }
         const traces = [];
-        for (const [id, { opName, stack }] of preTraces) {
-          if (opName !== key) continue;
+        for (const [id, { opName: traceOpName, stack }] of preTraces) {
+          if (opName !== traceOpName) continue;
           if (MapPrototypeHas(postTraces, id)) continue;
           ArrayPrototypePush(traces, stack);
         }
@@ -274,6 +272,8 @@ function assertOps(fn) {
           message += ArrayPrototypeJoin(traces, "\n\n");
         }
         ArrayPrototypePush(details, message);
+      } else {
+        throw new Error("unreachable");
       }
     }
 

cli/ops/testing.rs

@@ -12,6 +12,7 @@ use deno_core::op2;
 use deno_core::serde_v8;
 use deno_core::v8;
 use deno_core::ModuleSpecifier;
+use deno_core::OpMetrics;
 use deno_core::OpState;
 use deno_runtime::permissions::create_child_permissions;
 use deno_runtime::permissions::ChildPermissionsArg;
@@ -19,6 +20,9 @@ use deno_runtime::permissions::PermissionsContainer;
 use serde::Deserialize;
 use serde::Deserializer;
 use serde::Serialize;
+use std::cell::Ref;
+use std::collections::hash_map::Entry;
+use std::collections::HashMap;
 use std::sync::atomic::AtomicUsize;
 use std::sync::atomic::Ordering;
 use uuid::Uuid;
@@ -35,6 +39,9 @@ deno_core::extension!(deno_test,
     op_register_test,
     op_register_test_step,
     op_dispatch_test_event,
+    op_test_op_sanitizer_collect,
+    op_test_op_sanitizer_finish,
+    op_test_op_sanitizer_report,
   ],
   options = {
     sender: TestEventSender,
@@ -42,6 +49,7 @@ deno_core::extension!(deno_test,
   state = |state, options| {
     state.put(options.sender);
     state.put(TestContainer::default());
+    state.put(TestOpSanitizers::default());
   },
 );
 
@@ -202,3 +210,189 @@ fn op_dispatch_test_event(
   sender.send(event).ok();
   Ok(())
 }
+
+#[derive(Default)]
+struct TestOpSanitizers(HashMap<u32, TestOpSanitizerState>);
+
+enum TestOpSanitizerState {
+  Collecting { metrics: Vec<OpMetrics> },
+  Finished { report: Vec<TestOpSanitizerReport> },
+}
+
+fn try_collect_metrics(
+  state: &OpState,
+  force: bool,
+  op_id_host_recv_msg: usize,
+  op_id_host_recv_ctrl: usize,
+) -> Result<Ref<Vec<OpMetrics>>, bool> {
+  let metrics = state.tracker.per_op();
+  for op_metric in &*metrics {
+    let has_pending_ops = op_metric.ops_dispatched_async
+      + op_metric.ops_dispatched_async_unref
+      > op_metric.ops_completed_async + op_metric.ops_completed_async_unref;
+    if has_pending_ops && !force {
+      let host_recv_msg = metrics
+        .get(op_id_host_recv_msg)
+        .map(|op_metric| {
+          op_metric.ops_dispatched_async + op_metric.ops_dispatched_async_unref
+            > op_metric.ops_completed_async
+              + op_metric.ops_completed_async_unref
+        })
+        .unwrap_or(false);
+      let host_recv_ctrl = metrics
+        .get(op_id_host_recv_ctrl)
+        .map(|op_metric| {
+          op_metric.ops_dispatched_async + op_metric.ops_dispatched_async_unref
+            > op_metric.ops_completed_async
+              + op_metric.ops_completed_async_unref
+        })
+        .unwrap_or(false);
+      return Err(host_recv_msg || host_recv_ctrl);
+    }
+  }
+  Ok(metrics)
+}
+
+#[op2(fast)]
+#[smi]
+// Returns:
+// 0 - success
+// 1 - for more accurate results, spin event loop and call again with force=true
+// 2 - for more accurate results, delay(1ms) and call again with force=true
+fn op_test_op_sanitizer_collect(
+  state: &mut OpState,
+  #[smi] id: u32,
+  force: bool,
+  #[smi] op_id_host_recv_msg: usize,
+  #[smi] op_id_host_recv_ctrl: usize,
+) -> Result<u8, AnyError> {
+  let metrics = {
+    let metrics = match try_collect_metrics(
+      state,
+      force,
+      op_id_host_recv_msg,
+      op_id_host_recv_ctrl,
+    ) {
+      Ok(metrics) => metrics,
+      Err(false) => {
+        return Ok(1);
+      }
+      Err(true) => {
+        return Ok(2);
+      }
+    };
+    metrics.clone()
+  };
+  let op_sanitizers = state.borrow_mut::<TestOpSanitizers>();
+  match op_sanitizers.0.entry(id) {
+    Entry::Vacant(entry) => {
+      entry.insert(TestOpSanitizerState::Collecting { metrics });
+    }
+    Entry::Occupied(_) => {
+      return Err(generic_error(format!(
+        "Test metrics already being collected for test id {id}",
+      )));
+    }
+  }
+  Ok(0)
+}
+
+#[derive(Serialize)]
+#[serde(rename_all = "camelCase")]
+struct TestOpSanitizerReport {
+  id: usize,
+  diff: i64,
+}
+
+#[op2(fast)]
+#[smi]
+// Returns:
+// 0 - sanitizer finished with no pending ops
+// 1 - for more accurate results, spin event loop and call again with force=true
+// 2 - for more accurate results, delay(1ms) and call again with force=true
+// 3 - sanitizer finished with pending ops, collect the report with op_test_op_sanitizer_report
+fn op_test_op_sanitizer_finish(
+  state: &mut OpState,
+  #[smi] id: u32,
+  force: bool,
+  #[smi] op_id_host_recv_msg: usize,
+  #[smi] op_id_host_recv_ctrl: usize,
+) -> Result<u8, AnyError> {
+  let report = {
+    let after_metrics = match try_collect_metrics(
+      state,
+      force,
+      op_id_host_recv_msg,
+      op_id_host_recv_ctrl,
+    ) {
+      Ok(metrics) => metrics,
+      Err(false) => {
+        return Ok(1);
+      }
+      Err(true) => {
+        return Ok(2);
+      }
+    };
+
+    let op_sanitizers = state.borrow::<TestOpSanitizers>();
+    let before_metrics = match op_sanitizers.0.get(&id) {
+      Some(TestOpSanitizerState::Collecting { metrics }) => metrics,
+      _ => {
+        return Err(generic_error(format!(
+          "Metrics not collected before for test id {id}",
+        )));
+      }
+    };
+    let mut report = vec![];
+
+    for (id, (before, after)) in
+      before_metrics.iter().zip(after_metrics.iter()).enumerate()
+    {
+      let async_pending_before = before.ops_dispatched_async
+        + before.ops_dispatched_async_unref
+        - before.ops_completed_async
+        - before.ops_completed_async_unref;
+      let async_pending_after = after.ops_dispatched_async
+        + after.ops_dispatched_async_unref
+        - after.ops_completed_async
+        - after.ops_completed_async_unref;
+      let diff = async_pending_after as i64 - async_pending_before as i64;
+      if diff != 0 {
+        report.push(TestOpSanitizerReport { id, diff });
+      }
+    }
+
+    report
+  };
+
+  let op_sanitizers = state.borrow_mut::<TestOpSanitizers>();
+
+  if report.is_empty() {
+    op_sanitizers
+      .0
+      .remove(&id)
+      .expect("TestOpSanitizerState::Collecting");
+    Ok(0)
+  } else {
+    op_sanitizers
+      .0
+      .insert(id, TestOpSanitizerState::Finished { report })
+      .expect("TestOpSanitizerState::Collecting");
+    Ok(3)
+  }
+}
+
+#[op2]
+#[serde]
+fn op_test_op_sanitizer_report(
+  state: &mut OpState,
+  #[smi] id: u32,
+) -> Result<Vec<TestOpSanitizerReport>, AnyError> {
+  let op_sanitizers = state.borrow_mut::<TestOpSanitizers>();
+  match op_sanitizers.0.remove(&id) {
+    Some(TestOpSanitizerState::Finished { report }) => Ok(report),
+    _ => Err(generic_error(format!(
+      "Metrics not finished collecting for test id {id}",
+    ))),
+  }
+}