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.

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)]
@@ -1272,6 +1273,12 @@ fn test_subcommand<'a>() -> App<'a> {
         .help("Cache test modules, but don't run tests")
         .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")
@@ -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,

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",

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

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?;

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,
   });
 

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;
     };
   }