Auto merge of #35405 - futile:tests_warn_timeout, r=brson

bors · web-flow · commit ae7741035013 · 2016-08-10T03:00:56.000-07:00
Add warning timeout for tests that run >1min This makes it easier to identify hanging tests. As described in #2873, when a test doesn't finish, we so far had no information on which test that was. In this PR, we add a duration of 60 seconds for each test, after which a warning will be printed mentioning that this specific test has been running for a long time already. Example output: https://gist.github.com/futile/6ea3eed85fe632df8633c1b03c08b012 r? @brson
diff --git 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,12 @@ impl<T: Write> ConsoleTestState<T> {
         }
     }
 
+    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 +718,7 @@ pub fn run_tests_console(opts: &TestOpts, tests: Vec<TestDescAndFn>) -> 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 +840,7 @@ enum TestEvent {
     TeFiltered(Vec<TestDesc>),
     TeWait(TestDesc, NamePadding),
     TeResult(TestDesc, TestResult, Vec<u8>),
+    TeTimeout(TestDesc),
 }
 
 pub type MonitorMsg = (TestDesc, TestResult, Vec<u8>);
@@ -838,6 +849,9 @@ pub type MonitorMsg = (TestDesc, TestResult, Vec<u8>);
 fn run_tests<F>(opts: &TestOpts, tests: Vec<TestDescAndFn>, 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 +881,29 @@ fn run_tests<F>(opts: &TestOpts, tests: Vec<TestDescAndFn>, mut callback: F) ->
 
     let (tx, rx) = channel::<MonitorMsg>();
 
+    let mut running_tests: HashMap<TestDesc, Instant> = HashMap::new();
+
+    fn get_timed_out_tests(running_tests: &mut HashMap<TestDesc, Instant>) -> Vec<TestDesc> {
+        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<TestDesc, Instant>) -> Option<Duration> {
+        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() {
             let test = remaining.pop().unwrap();
@@ -876,11 +913,31 @@ fn run_tests<F>(opts: &TestOpts, tests: Vec<TestDescAndFn>, mut callback: F) ->
                 // that hang forever.
                 callback(TeWait(test.desc.clone(), test.testfn.padding()))?;
             }
+            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 (desc, result, stdout) = rx.recv().unwrap();
+        let mut res;
+        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;
+            }
+        }
+
+        let (desc, result, stdout) = res.unwrap();
+        running_tests.remove(&desc);
+
         if concurrency != 1 {
             callback(TeWait(desc.clone(), PadNone))?;
         }
