feat: deno test --trace-ops (#13770)

This commit adds "--trace-ops" flag to "deno test" subcommand.

This flag enables saving of stack traces for async ops, that before were always
saved. While the feature proved to be very useful it comes with a significant performance
hit, it's caused by excessive source mapping of stack frames. 

6 files changed, 78 insertions, 7 deletions

diff --git a/cli/flags.rs b/cli/flags.rs
index 6c3186c55..05c017e81 100644
--- a/cli/flags.rs
+++ b/cli/flags.rs
@@ -150,6 +150,7 @@ pub struct TestFlags {
   pub filter: Option<String>,
   pub shuffle: Option<u64>,
   pub concurrent_jobs: NonZeroUsize,
+  pub trace_ops: bool,
 }
 
 #[derive(Clone, Debug, PartialEq, Deserialize, Serialize)]
@@ -1273,6 +1274,12 @@ fn test_subcommand<'a>() -> App<'a> {
         .takes_value(false),
     )
     .arg(
+      Arg::new("trace-ops")
+        .long("trace-ops")
+        .help("Enable tracing of async ops. Useful when debugging leaking ops in test, but impacts test execution time.")
+        .takes_value(false),
+    )
+    .arg(
       Arg::new("doc")
         .long("doc")
         .help("UNSTABLE: type check code blocks")
@@ -2199,6 +2206,7 @@ fn test_parse(flags: &mut Flags, matches: &clap::ArgMatches) {
   };
 
   let no_run = matches.is_present("no-run");
+  let trace_ops = matches.is_present("trace-ops");
   let doc = matches.is_present("doc");
   let allow_none = matches.is_present("allow-none");
   let filter = matches.value_of("filter").map(String::from);
@@ -2271,6 +2279,7 @@ fn test_parse(flags: &mut Flags, matches: &clap::ArgMatches) {
     shuffle,
     allow_none,
     concurrent_jobs,
+    trace_ops,
   });
 }
 
@@ -4427,7 +4436,7 @@ mod tests {
   #[test]
   fn test_with_flags() {
     #[rustfmt::skip]
-    let r = flags_from_vec(svec!["deno", "test", "--unstable", "--no-run", "--filter", "- foo", "--coverage=cov", "--location", "https:foo", "--allow-net", "--allow-none", "dir1/", "dir2/", "--", "arg1", "arg2"]);
+    let r = flags_from_vec(svec!["deno", "test", "--unstable", "--trace-ops", "--no-run", "--filter", "- foo", "--coverage=cov", "--location", "https:foo", "--allow-net", "--allow-none", "dir1/", "dir2/", "--", "arg1", "arg2"]);
     assert_eq!(
       r.unwrap(),
       Flags {
@@ -4441,6 +4450,7 @@ mod tests {
           ignore: vec![],
           shuffle: None,
           concurrent_jobs: NonZeroUsize::new(1).unwrap(),
+          trace_ops: true,
         }),
         unstable: true,
         coverage_dir: Some("cov".to_string()),
@@ -4509,6 +4519,7 @@ mod tests {
           include: None,
           ignore: vec![],
           concurrent_jobs: NonZeroUsize::new(4).unwrap(),
+          trace_ops: false,
         }),
         ..Flags::default()
       }
@@ -4534,6 +4545,7 @@ mod tests {
           include: None,
           ignore: vec![],
           concurrent_jobs: NonZeroUsize::new(1).unwrap(),
+          trace_ops: false,
         }),
         ..Flags::default()
       }
@@ -4563,6 +4575,7 @@ mod tests {
           include: None,
           ignore: vec![],
           concurrent_jobs: NonZeroUsize::new(1).unwrap(),
+          trace_ops: false,
         }),
         enable_testing_features: true,
         ..Flags::default()
@@ -4586,6 +4599,7 @@ mod tests {
           include: None,
           ignore: vec![],
           concurrent_jobs: NonZeroUsize::new(1).unwrap(),
+          trace_ops: false,
         }),
         watch: None,
         ..Flags::default()
@@ -4609,6 +4623,7 @@ mod tests {
           include: None,
           ignore: vec![],
           concurrent_jobs: NonZeroUsize::new(1).unwrap(),
+          trace_ops: false,
         }),
         watch: Some(vec![]),
         ..Flags::default()
@@ -4633,6 +4648,7 @@ mod tests {
           include: None,
           ignore: vec![],
           concurrent_jobs: NonZeroUsize::new(1).unwrap(),
+          trace_ops: false,
         }),
         watch: Some(vec![]),
         no_clear_screen: true,
diff --git a/cli/tests/integration/test_tests.rs b/cli/tests/integration/test_tests.rs
index 0697fc69c..c80406935 100644
--- a/cli/tests/integration/test_tests.rs
+++ b/cli/tests/integration/test_tests.rs
@@ -146,7 +146,7 @@ itest!(allow_none {
 });
 
 itest!(ops_sanitizer_unstable {
-  args: "test --unstable test/ops_sanitizer_unstable.ts",
+  args: "test --unstable --trace-ops test/ops_sanitizer_unstable.ts",
   exit_code: 1,
   output: "test/ops_sanitizer_unstable.out",
 });
@@ -157,11 +157,17 @@ itest!(ops_sanitizer_timeout_failure {
 });
 
 itest!(ops_sanitizer_multiple_timeout_tests {
-  args: "test test/ops_sanitizer_multiple_timeout_tests.ts",
+  args: "test --trace-ops test/ops_sanitizer_multiple_timeout_tests.ts",
   exit_code: 1,
   output: "test/ops_sanitizer_multiple_timeout_tests.out",
 });
 
+itest!(ops_sanitizer_multiple_timeout_tests_no_trace {
+  args: "test test/ops_sanitizer_multiple_timeout_tests.ts",
+  exit_code: 1,
+  output: "test/ops_sanitizer_multiple_timeout_tests_no_trace.out",
+});
+
 itest!(ops_sanitizer_nexttick {
   args: "test test/ops_sanitizer_nexttick.ts",
   output: "test/ops_sanitizer_nexttick.out",
diff --git a/cli/tests/testdata/test/ops_sanitizer_multiple_timeout_tests_no_trace.out b/cli/tests/testdata/test/ops_sanitizer_multiple_timeout_tests_no_trace.out
new file mode 100644
index 000000000..9dad65525
--- /dev/null
+++ b/cli/tests/testdata/test/ops_sanitizer_multiple_timeout_tests_no_trace.out
@@ -0,0 +1,29 @@
+Check [WILDCARD]/testdata/test/ops_sanitizer_multiple_timeout_tests.ts
+running 2 tests from [WILDCARD]/testdata/test/ops_sanitizer_multiple_timeout_tests.ts
+test test 1 ... FAILED ([WILDCARD])
+test test 2 ... FAILED ([WILDCARD])
+
+failures:
+
+test 1
+Test case is leaking async ops.
+
+- 2 async operations to sleep for a duration were started in this test, but never completed. This is often caused by not cancelling a `setTimeout` or `setInterval` call.
+
+To get more details where ops were leaked, run again with --trace-ops flag.
+
+test 2
+Test case is leaking async ops.
+
+- 2 async operations to sleep for a duration were started in this test, but never completed. This is often caused by not cancelling a `setTimeout` or `setInterval` call.
+
+To get more details where ops were leaked, run again with --trace-ops flag.
+
+failures:
+
+	test 1
+	test 2
+
+test result: FAILED. 0 passed; 2 failed; 0 ignored; 0 measured; 0 filtered out ([WILDCARD])
+
+error: Test failed
diff --git a/cli/tools/test.rs b/cli/tools/test.rs
index 97a7ddf4f..2a43e3813 100644
--- a/cli/tools/test.rs
+++ b/cli/tools/test.rs
@@ -158,6 +158,7 @@ struct TestSpecifierOptions {
   fail_fast: Option<NonZeroUsize>,
   filter: Option<String>,
   shuffle: Option<u64>,
+  trace_ops: bool,
 }
 
 impl TestSummary {
@@ -477,9 +478,14 @@ async fn test_specifier(
 
   // Enable op call tracing in core to enable better debugging of op sanitizer
   // failures.
-  worker
-    .execute_script(&located_script_name!(), "Deno.core.enableOpCallTracing();")
-    .unwrap();
+  if options.trace_ops {
+    worker
+      .execute_script(
+        &located_script_name!(),
+        "Deno.core.enableOpCallTracing();",
+      )
+      .unwrap();
+  }
 
   // We only execute the specifier as a module if it is tagged with TestMode::Module or
   // TestMode::Both.
@@ -1043,6 +1049,7 @@ pub async fn run_tests(
       fail_fast: test_flags.fail_fast,
       filter: test_flags.filter,
       shuffle: test_flags.shuffle,
+      trace_ops: test_flags.trace_ops,
     },
   )
   .await?;
@@ -1277,6 +1284,7 @@ pub async fn run_tests_with_watch(
           fail_fast: test_flags.fail_fast,
           filter: filter.clone(),
           shuffle: test_flags.shuffle,
+          trace_ops: test_flags.trace_ops,
         },
       )
       .await?;
diff --git a/core/01_core.js b/core/01_core.js
index 3a05a0cff..50d4537f0 100644
--- a/core/01_core.js
+++ b/core/01_core.js
@@ -57,6 +57,10 @@
     opCallTracingEnabled = true;
   }
 
+  function isOpCallTracingEnabled() {
+    return opCallTracingEnabled;
+  }
+
   function setPromise(promiseId) {
     const idx = promiseId % RING_SIZE;
     // Move old promise from ring to map
@@ -246,6 +250,7 @@
     Interrupted,
     InterruptedPrototype,
     enableOpCallTracing,
+    isOpCallTracingEnabled,
     opCallTraces,
   });
 
diff --git a/runtime/js/40_testing.js b/runtime/js/40_testing.js
index b15b28c9e..0a40e19f1 100644
--- a/runtime/js/40_testing.js
+++ b/runtime/js/40_testing.js
@@ -208,9 +208,16 @@
         }
       }
 
-      throw `Test case is leaking async ops.
+      let msg = `Test case is leaking async ops.
 
 - ${ArrayPrototypeJoin(details, "\n - ")}`;
+
+      if (!core.isOpCallTracingEnabled()) {
+        msg +=
+          `\n\nTo get more details where ops were leaked, run again with --trace-ops flag.`;
+      }
+
+      throw msg;
     };
   }