Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(cli): Add slow test warning #23874

Merged
merged 4 commits into from
May 22, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 5 additions & 0 deletions cli/lsp/testing/execution.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down Expand Up @@ -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
Expand Down
44 changes: 41 additions & 3 deletions cli/tools/test/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -454,6 +455,7 @@ pub enum TestEvent {
Plan(TestPlan),
Wait(usize),
Output(TestStdioStream, Vec<u8>),
Slow(usize, u64),
Result(usize, TestResult, u64),
UncaughtError(String, Box<JsError>),
StepRegister(TestStepDescription),
Expand Down Expand Up @@ -912,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::<JsError>() {
Expand Down Expand Up @@ -1458,6 +1493,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 {
Expand Down
6 changes: 6 additions & 0 deletions cli/tools/test/reporters/compound.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
1 change: 1 addition & 0 deletions cli/tools/test/reporters/dot.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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(
Expand Down
1 change: 1 addition & 0 deletions cli/tools/test/reporters/junit.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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]) {
Expand Down
1 change: 1 addition & 0 deletions cli/tools/test/reporters/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down
12 changes: 12 additions & 0 deletions cli/tools/test/reporters/pretty.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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!(
"'{}' has been running for over {}",
description.name,
colors::gray(format!("({})", display::human_elapsed(elapsed.into()))),
))
)
.unwrap();
}
fn report_output(&mut self, output: &[u8]) {
if !self.echo_output {
return;
Expand Down
1 change: 1 addition & 0 deletions cli/tools/test/reporters/tap.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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(
Expand Down
8 changes: 8 additions & 0 deletions tests/specs/test/slow_test/__test__.jsonc
Original file line number Diff line number Diff line change
@@ -0,0 +1,8 @@
{
"args": "test main.js",
"envs": {
"DENO_SLOW_TEST_TIMEOUT": "1"
},
"output": "main.out",
"exitCode": 0
}
4 changes: 4 additions & 0 deletions tests/specs/test/slow_test/main.js
Original file line number Diff line number Diff line change
@@ -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));
});
3 changes: 3 additions & 0 deletions tests/specs/test/slow_test/main.out
Original file line number Diff line number Diff line change
@@ -0,0 +1,3 @@
running 1 test from [WILDCARD]
test ...'test' has been running for over (1s)
[WILDCARD]