From d332bf113259f65e90b18b543f19def248e38daa Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bartek=20Iwa=C5=84czuk?= Date: Fri, 25 Feb 2022 16:14:46 +0100 Subject: [PATCH] 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 | 18 +++++++++++- cli/tests/integration/test_tests.rs | 10 +++++-- ...itizer_multiple_timeout_tests_no_trace.out | 29 +++++++++++++++++++ cli/tools/test.rs | 14 +++++++-- core/01_core.js | 5 ++++ runtime/js/40_testing.js | 9 +++++- 6 files changed, 78 insertions(+), 7 deletions(-) create mode 100644 cli/tests/testdata/test/ops_sanitizer_multiple_timeout_tests_no_trace.out diff --git a/cli/flags.rs b/cli/flags.rs index 6c3186c557..05c017e81c 100644 --- a/cli/flags.rs +++ b/cli/flags.rs @@ -150,6 +150,7 @@ pub struct TestFlags { pub filter: Option, pub shuffle: Option, 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, diff --git a/cli/tests/integration/test_tests.rs b/cli/tests/integration/test_tests.rs index 0697fc69cf..c80406935a 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 0000000000..9dad65525b --- /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 97a7ddf4f2..2a43e3813e 100644 --- a/cli/tools/test.rs +++ b/cli/tools/test.rs @@ -158,6 +158,7 @@ struct TestSpecifierOptions { fail_fast: Option, filter: Option, shuffle: Option, + 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 3a05a0cff2..50d4537f0e 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 b15b28c9e7..0a40e19f15 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; }; }