From 6f7ac9f8d088987b888b884a00aac6b881e4b7b0 Mon Sep 17 00:00:00 2001 From: Matt Mastracci Date: Fri, 17 May 2024 09:36:17 -0600 Subject: [PATCH 1/4] feat(cli): Add slow test warning --- cli/lsp/testing/execution.rs | 5 +++++ cli/tools/test/mod.rs | 4 ++++ cli/tools/test/reporters/compound.rs | 6 ++++++ cli/tools/test/reporters/dot.rs | 1 + cli/tools/test/reporters/junit.rs | 1 + cli/tools/test/reporters/mod.rs | 1 + cli/tools/test/reporters/pretty.rs | 12 ++++++++++++ cli/tools/test/reporters/tap.rs | 1 + 8 files changed, 31 insertions(+) diff --git a/cli/lsp/testing/execution.rs b/cli/lsp/testing/execution.rs index 29b6a4f190ebf9..75a93ba8c90db6 100644 --- a/cli/lsp/testing/execution.rs +++ b/cli/lsp/testing/execution.rs @@ -353,6 +353,9 @@ impl TestRun { test::TestEvent::Output(_, output) => { reporter.report_output(&output); } + test::TestEvent::Slow(id, elapsed) => { + reporter.report_slow(tests.read().get(&id).unwrap(), elapsed); + } test::TestEvent::Result(id, result, elapsed) => { if tests_with_result.insert(id) { let description = tests.read().get(&id).unwrap().clone(); @@ -610,6 +613,8 @@ impl LspTestReporter { self.progress(lsp_custom::TestRunProgressMessage::Started { test }); } + fn report_slow(&mut self, desc: &test::TestDescription, elapsed: u64) {} + fn report_output(&mut self, output: &[u8]) { let test = self .current_test diff --git a/cli/tools/test/mod.rs b/cli/tools/test/mod.rs index 2ff7203b769f98..83a152fbf38195 100644 --- a/cli/tools/test/mod.rs +++ b/cli/tools/test/mod.rs @@ -454,6 +454,7 @@ pub enum TestEvent { Plan(TestPlan), Wait(usize), Output(TestStdioStream, Vec), + Slow(usize, u64), Result(usize, TestResult, u64), UncaughtError(String, Box), StepRegister(TestStepDescription), @@ -1458,6 +1459,9 @@ pub async fn report_tests( TestEvent::Output(_, output) => { reporter.report_output(&output); } + TestEvent::Slow(id, elapsed) => { + reporter.report_slow(tests.get(&id).unwrap(), elapsed); + } TestEvent::Result(id, result, elapsed) => { if tests_with_result.insert(id) { match result { diff --git a/cli/tools/test/reporters/compound.rs b/cli/tools/test/reporters/compound.rs index 1af0b284b41069..3ab7297db59b60 100644 --- a/cli/tools/test/reporters/compound.rs +++ b/cli/tools/test/reporters/compound.rs @@ -31,6 +31,12 @@ impl TestReporter for CompoundTestReporter { } } + fn report_slow(&mut self, description: &TestDescription, elapsed: u64) { + for reporter in &mut self.test_reporters { + reporter.report_slow(description, elapsed); + } + } + fn report_output(&mut self, output: &[u8]) { for reporter in &mut self.test_reporters { reporter.report_output(output); diff --git a/cli/tools/test/reporters/dot.rs b/cli/tools/test/reporters/dot.rs index 854ef96660e120..8fbd59232cc512 100644 --- a/cli/tools/test/reporters/dot.rs +++ b/cli/tools/test/reporters/dot.rs @@ -95,6 +95,7 @@ impl TestReporter for DotTestReporter { std::io::stdout().flush().unwrap(); } + fn report_slow(&mut self, _description: &TestDescription, _elapsed: u64) {} fn report_output(&mut self, _output: &[u8]) {} fn report_result( diff --git a/cli/tools/test/reporters/junit.rs b/cli/tools/test/reporters/junit.rs index eea1d2aca8238e..4b69218dfffef2 100644 --- a/cli/tools/test/reporters/junit.rs +++ b/cli/tools/test/reporters/junit.rs @@ -92,6 +92,7 @@ impl TestReporter for JunitTestReporter { fn report_plan(&mut self, _plan: &TestPlan) {} + fn report_slow(&mut self, _description: &TestDescription, _elapsed: u64) {} fn report_wait(&mut self, _description: &TestDescription) {} fn report_output(&mut self, _output: &[u8]) { diff --git a/cli/tools/test/reporters/mod.rs b/cli/tools/test/reporters/mod.rs index a152029c46d092..07351e9c3bef45 100644 --- a/cli/tools/test/reporters/mod.rs +++ b/cli/tools/test/reporters/mod.rs @@ -19,6 +19,7 @@ pub trait TestReporter { fn report_register(&mut self, description: &TestDescription); fn report_plan(&mut self, plan: &TestPlan); fn report_wait(&mut self, description: &TestDescription); + fn report_slow(&mut self, description: &TestDescription, elapsed: u64); fn report_output(&mut self, output: &[u8]); fn report_result( &mut self, diff --git a/cli/tools/test/reporters/pretty.rs b/cli/tools/test/reporters/pretty.rs index f9121a4825fbe4..be13ecc00fddc4 100644 --- a/cli/tools/test/reporters/pretty.rs +++ b/cli/tools/test/reporters/pretty.rs @@ -197,6 +197,18 @@ impl TestReporter for PrettyTestReporter { self.started_tests = true; } + fn report_slow(&mut self, description: &TestDescription, elapsed: u64) { + writeln!( + &mut self.writer, + "{}", + colors::yellow_bold(format!( + "{} is running very slowly {}", + description.name, + colors::gray(format!("({})", display::human_elapsed(elapsed.into()))), + )) + ) + .unwrap(); + } fn report_output(&mut self, output: &[u8]) { if !self.echo_output { return; diff --git a/cli/tools/test/reporters/tap.rs b/cli/tools/test/reporters/tap.rs index 6dc690e6bde3d1..ac5ec0c59c5923 100644 --- a/cli/tools/test/reporters/tap.rs +++ b/cli/tools/test/reporters/tap.rs @@ -140,6 +140,7 @@ impl TestReporter for TapTestReporter { std::io::stdout().flush().unwrap(); } + fn report_slow(&mut self, _description: &TestDescription, elapsed: u64) {} fn report_output(&mut self, _output: &[u8]) {} fn report_result( From 63f87adfb8d81c690d3aaa4f6f1d7c718e8a50e9 Mon Sep 17 00:00:00 2001 From: Matt Mastracci Date: Fri, 17 May 2024 10:04:48 -0600 Subject: [PATCH 2/4] . --- cli/lsp/testing/execution.rs | 2 +- cli/tools/test/mod.rs | 40 +++++++++++++++++++++-- cli/tools/test/reporters/pretty.rs | 2 +- cli/tools/test/reporters/tap.rs | 2 +- tests/specs/test/slow_test/__test__.jsonc | 8 +++++ tests/specs/test/slow_test/main.js | 4 +++ tests/specs/test/slow_test/main.out | 3 ++ 7 files changed, 55 insertions(+), 6 deletions(-) create mode 100644 tests/specs/test/slow_test/__test__.jsonc create mode 100644 tests/specs/test/slow_test/main.js create mode 100644 tests/specs/test/slow_test/main.out diff --git a/cli/lsp/testing/execution.rs b/cli/lsp/testing/execution.rs index 75a93ba8c90db6..f56f5010f139a4 100644 --- a/cli/lsp/testing/execution.rs +++ b/cli/lsp/testing/execution.rs @@ -613,7 +613,7 @@ impl LspTestReporter { self.progress(lsp_custom::TestRunProgressMessage::Started { test }); } - fn report_slow(&mut self, desc: &test::TestDescription, elapsed: u64) {} + fn report_slow(&mut self, _desc: &test::TestDescription, _elapsed: u64) {} fn report_output(&mut self, output: &[u8]) { let test = self diff --git a/cli/tools/test/mod.rs b/cli/tools/test/mod.rs index 83a152fbf38195..56b09f1c735519 100644 --- a/cli/tools/test/mod.rs +++ b/cli/tools/test/mod.rs @@ -74,6 +74,7 @@ use std::collections::BTreeMap; use std::collections::BTreeSet; use std::collections::HashMap; use std::collections::HashSet; +use std::env; use std::fmt::Write as _; use std::future::poll_fn; use std::io::Write; @@ -913,11 +914,44 @@ async fn run_tests_for_worker_inner( let earlier = Instant::now(); let call = worker.js_runtime.call(&function); - let result = match worker + + let slow_state_rc = state_rc.clone(); + let slow_test_id = desc.id; + let slow_test_warning = spawn(async move { + // The slow test warning should pop up every DENO_SLOW_TEST_TIMEOUT*(2**n) seconds, + // with a duration that is doubling each time. So for a warning time of 60s, + // we should get a warning at 60s, 120s, 240s, etc. + let base_timeout = env::var("DENO_SLOW_TEST_TIMEOUT").unwrap_or_default(); + let base_timeout = base_timeout.parse().unwrap_or(60).max(1); + let mut multiplier = 1; + let mut elapsed = 0; + loop { + tokio::time::sleep(Duration::from_secs( + base_timeout * (multiplier - elapsed), + )) + .await; + if send_test_event( + &slow_state_rc, + TestEvent::Slow( + slow_test_id, + Duration::from_secs(base_timeout * multiplier).as_millis() as _, + ), + ) + .is_err() + { + break; + } + multiplier *= 2; + elapsed += 1; + } + }); + + let result = worker .js_runtime .with_event_loop_promise(call, PollEventLoopOptions::default()) - .await - { + .await; + slow_test_warning.abort(); + let result = match result { Ok(r) => r, Err(error) => { if error.is::() { diff --git a/cli/tools/test/reporters/pretty.rs b/cli/tools/test/reporters/pretty.rs index be13ecc00fddc4..d96ea510ef2f41 100644 --- a/cli/tools/test/reporters/pretty.rs +++ b/cli/tools/test/reporters/pretty.rs @@ -202,7 +202,7 @@ impl TestReporter for PrettyTestReporter { &mut self.writer, "{}", colors::yellow_bold(format!( - "{} is running very slowly {}", + "'{}' is running very slowly {}", description.name, colors::gray(format!("({})", display::human_elapsed(elapsed.into()))), )) diff --git a/cli/tools/test/reporters/tap.rs b/cli/tools/test/reporters/tap.rs index ac5ec0c59c5923..62cb58a832201e 100644 --- a/cli/tools/test/reporters/tap.rs +++ b/cli/tools/test/reporters/tap.rs @@ -140,7 +140,7 @@ impl TestReporter for TapTestReporter { std::io::stdout().flush().unwrap(); } - fn report_slow(&mut self, _description: &TestDescription, elapsed: u64) {} + fn report_slow(&mut self, _description: &TestDescription, _elapsed: u64) {} fn report_output(&mut self, _output: &[u8]) {} fn report_result( diff --git a/tests/specs/test/slow_test/__test__.jsonc b/tests/specs/test/slow_test/__test__.jsonc new file mode 100644 index 00000000000000..114b0c2c1a8e6a --- /dev/null +++ b/tests/specs/test/slow_test/__test__.jsonc @@ -0,0 +1,8 @@ +{ + "args": "test main.js", + "envs": { + "DENO_SLOW_TEST_TIMEOUT": "1" + }, + "output": "main.out", + "exitCode": 0 +} diff --git a/tests/specs/test/slow_test/main.js b/tests/specs/test/slow_test/main.js new file mode 100644 index 00000000000000..830d2bf79af06b --- /dev/null +++ b/tests/specs/test/slow_test/main.js @@ -0,0 +1,4 @@ +Deno.test(async function test() { + // We want to get at least one slow test warning + await new Promise((r) => setTimeout(r, 3_000)); +}); diff --git a/tests/specs/test/slow_test/main.out b/tests/specs/test/slow_test/main.out new file mode 100644 index 00000000000000..4a37f8893a9ace --- /dev/null +++ b/tests/specs/test/slow_test/main.out @@ -0,0 +1,3 @@ +running 1 test from [WILDCARD] +test ...'test' is running very slowly (1s) +[WILDCARD] From d060236080a86f87dbdd44fd531feef46c751a32 Mon Sep 17 00:00:00 2001 From: Matt Mastracci Date: Mon, 20 May 2024 09:17:47 -0600 Subject: [PATCH 3/4] Update cli/tools/test/reporters/pretty.rs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Bartek Iwańczuk Signed-off-by: Matt Mastracci --- cli/tools/test/reporters/pretty.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cli/tools/test/reporters/pretty.rs b/cli/tools/test/reporters/pretty.rs index d96ea510ef2f41..cb9f2c435ddbe0 100644 --- a/cli/tools/test/reporters/pretty.rs +++ b/cli/tools/test/reporters/pretty.rs @@ -202,7 +202,7 @@ impl TestReporter for PrettyTestReporter { &mut self.writer, "{}", colors::yellow_bold(format!( - "'{}' is running very slowly {}", + "'{}' has been running for over {}", description.name, colors::gray(format!("({})", display::human_elapsed(elapsed.into()))), )) From 07d45188761875a0708a36eecd4d94d8b2521f3b Mon Sep 17 00:00:00 2001 From: Matt Mastracci Date: Tue, 21 May 2024 09:58:17 -0600 Subject: [PATCH 4/4] . --- tests/specs/test/slow_test/main.out | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/specs/test/slow_test/main.out b/tests/specs/test/slow_test/main.out index 4a37f8893a9ace..43b3d36f7331bc 100644 --- a/tests/specs/test/slow_test/main.out +++ b/tests/specs/test/slow_test/main.out @@ -1,3 +1,3 @@ running 1 test from [WILDCARD] -test ...'test' is running very slowly (1s) +test ...'test' has been running for over (1s) [WILDCARD]