From 9006913bf5c1ecfebbffd5c3417bd26c3d6c4aeb Mon Sep 17 00:00:00 2001 From: Felix Rath Date: Sat, 6 Aug 2016 00:53:10 +0200 Subject: [PATCH 1/2] add warning timeout for tests that run >1min this makes it easier to identify hanging tests --- src/libtest/lib.rs | 48 +++++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 47 insertions(+), 1 deletion(-) diff --git a/src/libtest/lib.rs b/src/libtest/lib.rs index 248f6f98650a5..106c14850ca24 100644 --- a/src/libtest/lib.rs +++ b/src/libtest/lib.rs @@ -42,6 +42,7 @@ #![feature(staged_api)] #![feature(question_mark)] #![feature(panic_unwind)] +#![feature(mpsc_recv_timeout)] extern crate getopts; extern crate term; @@ -73,6 +74,8 @@ use std::sync::{Arc, Mutex}; use std::thread; use std::time::{Instant, Duration}; +const TEST_WARN_TIMEOUT_S: u64 = 60; + // to be used by rustc to compile tests in libtest pub mod test { pub use {Bencher, TestName, TestResult, TestDesc, TestDescAndFn, TestOpts, TrFailed, @@ -592,6 +595,10 @@ impl ConsoleTestState { } } + pub fn write_timeout(&mut self, desc: &TestDesc) -> io::Result<()> { + self.write_plain(&format!("test {} has been running for over {} seconds\n", desc.name, TEST_WARN_TIMEOUT_S)) + } + pub fn write_log(&mut self, test: &TestDesc, result: &TestResult) -> io::Result<()> { match self.log_out { None => Ok(()), @@ -709,6 +716,7 @@ pub fn run_tests_console(opts: &TestOpts, tests: Vec) -> io::Resu match (*event).clone() { TeFiltered(ref filtered_tests) => st.write_run_start(filtered_tests.len()), TeWait(ref test, padding) => st.write_test_start(test, padding), + TeTimeout(ref test) => st.write_timeout(test), TeResult(test, result, stdout) => { st.write_log(&test, &result)?; st.write_result(&result)?; @@ -830,6 +838,7 @@ enum TestEvent { TeFiltered(Vec), TeWait(TestDesc, NamePadding), TeResult(TestDesc, TestResult, Vec), + TeTimeout(TestDesc), } pub type MonitorMsg = (TestDesc, TestResult, Vec); @@ -838,6 +847,9 @@ pub type MonitorMsg = (TestDesc, TestResult, Vec); fn run_tests(opts: &TestOpts, tests: Vec, mut callback: F) -> io::Result<()> where F: FnMut(TestEvent) -> io::Result<()> { + use std::collections::HashMap; + use std::sync::mpsc::RecvTimeoutError; + let mut filtered_tests = filter_tests(opts, tests); if !opts.bench_benchmarks { filtered_tests = convert_benchmarks_to_tests(filtered_tests); @@ -867,6 +879,8 @@ fn run_tests(opts: &TestOpts, tests: Vec, mut callback: F) -> let (tx, rx) = channel::(); + let mut running_tests: HashMap = HashMap::new(); + while pending > 0 || !remaining.is_empty() { while pending < concurrency && !remaining.is_empty() { let test = remaining.pop().unwrap(); @@ -876,11 +890,43 @@ fn run_tests(opts: &TestOpts, tests: Vec, mut callback: F) -> // that hang forever. callback(TeWait(test.desc.clone(), test.testfn.padding()))?; } + running_tests.insert(test.desc.clone(), Duration::from_secs(TEST_WARN_TIMEOUT_S)); run_test(opts, !opts.run_tests, test, tx.clone()); pending += 1; } - let (desc, result, stdout) = rx.recv().unwrap(); + let mut res; + if let Some(min_timeout) = running_tests.values().min().cloned() { + loop { + let before = Instant::now(); + res = rx.recv_timeout(min_timeout); + let elapsed = Instant::now() - before; + + let mut to_remove = Vec::new(); + for (desc, time_left) in &mut running_tests { + if *time_left >= elapsed { + *time_left -= elapsed; + } else { + to_remove.push(desc.clone()); + callback(TeTimeout(desc.clone()))?; + } + } + + for rem in to_remove { + running_tests.remove(&rem); + } + + if res != Err(RecvTimeoutError::Timeout) { + break; + } + } + } else { + res = rx.recv().map_err(|_| RecvTimeoutError::Disconnected); + } + + let (desc, result, stdout) = res.unwrap(); + running_tests.remove(&desc); + if concurrency != 1 { callback(TeWait(desc.clone(), PadNone))?; } From e9950618eac5133be9226b8eef2a2a4987245356 Mon Sep 17 00:00:00 2001 From: Felix Rath Date: Sat, 6 Aug 2016 15:07:16 +0200 Subject: [PATCH 2/2] save an Instant for the timeout instead of a Duration requires less bookkeeping. also move some functionality into functions, to keep the loop cleaner. --- src/libtest/lib.rs | 59 +++++++++++++++++++++++++++------------------- 1 file changed, 35 insertions(+), 24 deletions(-) diff --git a/src/libtest/lib.rs b/src/libtest/lib.rs index 106c14850ca24..64515b900d5b1 100644 --- a/src/libtest/lib.rs +++ b/src/libtest/lib.rs @@ -596,7 +596,9 @@ impl ConsoleTestState { } pub fn write_timeout(&mut self, desc: &TestDesc) -> io::Result<()> { - self.write_plain(&format!("test {} has been running for over {} seconds\n", desc.name, TEST_WARN_TIMEOUT_S)) + self.write_plain(&format!("test {} has been running for over {} seconds\n", + desc.name, + TEST_WARN_TIMEOUT_S)) } pub fn write_log(&mut self, test: &TestDesc, result: &TestResult) -> io::Result<()> { @@ -879,7 +881,28 @@ fn run_tests(opts: &TestOpts, tests: Vec, mut callback: F) -> let (tx, rx) = channel::(); - let mut running_tests: HashMap = HashMap::new(); + let mut running_tests: HashMap = HashMap::new(); + + fn get_timed_out_tests(running_tests: &mut HashMap) -> Vec { + let now = Instant::now(); + let timed_out = running_tests.iter() + .filter_map(|(desc, timeout)| if &now >= timeout { Some(desc.clone())} else { None }) + .collect(); + for test in &timed_out { + running_tests.remove(test); + } + timed_out + }; + + fn calc_timeout(running_tests: &HashMap) -> Option { + running_tests.values().min().map(|next_timeout| { + let now = Instant::now(); + if *next_timeout >= now { + *next_timeout - now + } else { + Duration::new(0, 0) + }}) + }; while pending > 0 || !remaining.is_empty() { while pending < concurrency && !remaining.is_empty() { @@ -890,38 +913,26 @@ fn run_tests(opts: &TestOpts, tests: Vec, mut callback: F) -> // that hang forever. callback(TeWait(test.desc.clone(), test.testfn.padding()))?; } - running_tests.insert(test.desc.clone(), Duration::from_secs(TEST_WARN_TIMEOUT_S)); + let timeout = Instant::now() + Duration::from_secs(TEST_WARN_TIMEOUT_S); + running_tests.insert(test.desc.clone(), timeout); run_test(opts, !opts.run_tests, test, tx.clone()); pending += 1; } let mut res; - if let Some(min_timeout) = running_tests.values().min().cloned() { - loop { - let before = Instant::now(); - res = rx.recv_timeout(min_timeout); - let elapsed = Instant::now() - before; - - let mut to_remove = Vec::new(); - for (desc, time_left) in &mut running_tests { - if *time_left >= elapsed { - *time_left -= elapsed; - } else { - to_remove.push(desc.clone()); - callback(TeTimeout(desc.clone()))?; - } - } - - for rem in to_remove { - running_tests.remove(&rem); + loop { + if let Some(timeout) = calc_timeout(&running_tests) { + res = rx.recv_timeout(timeout); + for test in get_timed_out_tests(&mut running_tests) { + callback(TeTimeout(test))?; } - if res != Err(RecvTimeoutError::Timeout) { break; } + } else { + res = rx.recv().map_err(|_| RecvTimeoutError::Disconnected); + break; } - } else { - res = rx.recv().map_err(|_| RecvTimeoutError::Disconnected); } let (desc, result, stdout) = res.unwrap();