Enhance report-time option

This commit is contained in:
Igor Aleksanov
2019-09-28 17:07:18 +03:00
parent 06c68947ad
commit 75a297573f
8 changed files with 547 additions and 96 deletions

View File

@@ -56,6 +56,7 @@ use std::panic::{self, catch_unwind, AssertUnwindSafe, PanicInfo};
use std::path::PathBuf;
use std::process;
use std::process::{ExitStatus, Command, Termination};
use std::str::FromStr;
use std::sync::mpsc::{channel, Sender};
use std::sync::{Arc, Mutex};
use std::thread;
@@ -75,13 +76,54 @@ const SECONDARY_TEST_INVOKER_VAR: &'static str = "__RUST_TEST_INVOKE";
const TR_OK: i32 = 50;
const TR_FAILED: i32 = 51;
/// This small module contains constants used by `report-time` option.
/// Those constants values will be used if corresponding environment variables are not set.
///
/// To override values for unit-tests, use a constant `RUST_TEST_TIME_UNIT`,
/// To override values for integration tests, use a constant `RUST_TEST_TIME_INTEGRATION`,
/// To override values for doctests, use a constant `RUST_TEST_TIME_DOCTEST`.
///
/// Example of the expected format is `RUST_TEST_TIME_xxx=100,200`, where 100 means
/// warn time, and 200 means critical time.
pub mod time_constants {
use std::time::Duration;
use super::TEST_WARN_TIMEOUT_S;
/// Environment variable for overriding default threshold for unit-tests.
pub const UNIT_ENV_NAME: &str = "RUST_TEST_TIME_UNIT";
// Unit tests are supposed to be really quick.
pub const UNIT_WARN: Duration = Duration::from_millis(50);
pub const UNIT_CRITICAL: Duration = Duration::from_millis(100);
/// Environment variable for overriding default threshold for unit-tests.
pub const INTEGRATION_ENV_NAME: &str = "RUST_TEST_TIME_INTEGRATION";
// Integration tests may have a lot of work, so they can take longer to execute.
pub const INTEGRATION_WARN: Duration = Duration::from_millis(500);
pub const INTEGRATION_CRITICAL: Duration = Duration::from_millis(1000);
/// Environment variable for overriding default threshold for unit-tests.
pub const DOCTEST_ENV_NAME: &str = "RUST_TEST_TIME_DOCTEST";
// Doctests are similar to integration tests, because they can include a lot of
// initialization code.
pub const DOCTEST_WARN: Duration = INTEGRATION_WARN;
pub const DOCTEST_CRITICAL: Duration = INTEGRATION_CRITICAL;
// Do not suppose anything about unknown tests, base limits on the
// `TEST_WARN_TIMEOUT_S` constant.
pub const UNKNOWN_WARN: Duration = Duration::from_secs(TEST_WARN_TIMEOUT_S);
pub const UNKNOWN_CRITICAL: Duration = Duration::from_secs(TEST_WARN_TIMEOUT_S * 2);
}
// to be used by rustc to compile tests in libtest
pub mod test {
pub use crate::{
assert_test_result, filter_tests, parse_opts, run_test, test_main, test_main_static,
Bencher, DynTestFn, DynTestName, Metric, MetricMap, Options, RunIgnored, RunStrategy,
ShouldPanic, StaticBenchFn, StaticTestFn, StaticTestName, TestDesc, TestDescAndFn, TestName,
TestOpts, TestResult, TrFailed, TrFailedMsg, TrIgnored, TrOk,
TestOpts, TestTimeOptions, TestType, TestResult, TrFailed, TrFailedMsg, TrIgnored, TrOk,
};
}
@@ -97,6 +139,21 @@ pub enum Concurrent {
No,
}
/// Type of the test according to the [rust book](https://doc.rust-lang.org/cargo/guide/tests.html)
/// conventions.
#[derive(Copy, Clone, Debug, PartialEq, Eq, Hash)]
pub enum TestType {
/// Unit-tests are expected to be in the `src` folder of the crate.
UnitTest,
/// Integration-style tests are expected to be in the `tests` folder of the crate.
IntegrationTest,
/// Doctests are created by the `librustdoc` manually, so it's a different type of test.
DocTest,
/// Tests for the sources that don't follow the project layout convention
/// (e.g. tests in raw `main.rs` compiled by calling `rustc --test` directly).
Unknown,
}
// The name of a test. By convention this follows the rules for rust
// paths; i.e., it should be a series of identifiers separated by double
// colons. This way if some test runner wants to arrange the tests
@@ -232,6 +289,7 @@ pub struct TestDesc {
pub ignore: bool,
pub should_panic: ShouldPanic,
pub allow_fail: bool,
pub test_type: TestType,
}
#[derive(Debug)]
@@ -403,6 +461,133 @@ pub enum RunIgnored {
Only,
}
/// Structure denoting time limits for test execution.
#[derive(Copy, Clone, Debug, Default, PartialEq, Eq)]
pub struct TimeThreshold {
pub warn: Duration,
pub critical: Duration,
}
impl TimeThreshold {
/// Creates a new `TimeThreshold` instance with provided durations.
pub fn new(warn: Duration, critical: Duration) -> Self {
Self {
warn,
critical,
}
}
/// Attempts to create a `TimeThreshold` instance with values obtained
/// from the environment variable, and returns `None` if the variable
/// is not set.
/// Environment variable format is expected to match `\d+,\d+`.
///
/// # Panics
///
/// Panics if variable with provided name is set but contains inappropriate
/// value.
pub fn from_env_var(env_var_name: &str) -> Option<Self> {
let durations_str = env::var(env_var_name).ok()?;
// Split string into 2 substrings by comma and try to parse numbers.
let durations: Vec<u64> = durations_str
.splitn(2, ',')
.map(|v| {
u64::from_str(v).unwrap_or_else(|_| {
panic!(
"Duration value in variable {} is expected to be a number, but got {}",
env_var_name, v
)
})
})
.collect();
// Check that we have exactly 2 numbers.
if durations.len() != 2 {
panic!(
"Duration variable {} expected to have 2 numbers separated by comma, but got {}",
env_var_name, durations.len()
);
}
let (warn, critical) = (durations[0], durations[1]);
Some(Self::new(Duration::from_millis(warn), Duration::from_millis(critical)))
}
}
/// Structure with parameters for calculating test execution time.
#[derive(Copy, Clone, Debug, Default, PartialEq, Eq)]
pub struct TestTimeOptions {
pub error_on_excess: bool,
pub colored: bool,
pub unit_threshold: TimeThreshold,
pub integration_threshold: TimeThreshold,
pub doctest_threshold: TimeThreshold,
}
impl TestTimeOptions {
pub fn new_from_env(error_on_excess: bool, colored: bool) -> Self {
let unit_threshold =
TimeThreshold::from_env_var(time_constants::UNIT_ENV_NAME)
.unwrap_or_else(Self::default_unit);
let integration_threshold =
TimeThreshold::from_env_var(time_constants::INTEGRATION_ENV_NAME)
.unwrap_or_else(Self::default_integration);
let doctest_threshold =
TimeThreshold::from_env_var(time_constants::DOCTEST_ENV_NAME)
.unwrap_or_else(Self::default_doctest);
Self {
error_on_excess,
colored,
unit_threshold,
integration_threshold,
doctest_threshold,
}
}
pub fn is_warn(&self, test: &TestDesc, exec_time: &TestExecTime) -> bool {
exec_time.0 >= self.warn_time(test)
}
pub fn is_critical(&self, test: &TestDesc, exec_time: &TestExecTime) -> bool {
exec_time.0 >= self.critical_time(test)
}
fn warn_time(&self, test: &TestDesc) -> Duration {
match test.test_type {
TestType::UnitTest => self.unit_threshold.warn,
TestType::IntegrationTest => self.integration_threshold.warn,
TestType::DocTest => self.doctest_threshold.warn,
TestType::Unknown => time_constants::UNKNOWN_WARN,
}
}
fn critical_time(&self, test: &TestDesc) -> Duration {
match test.test_type {
TestType::UnitTest => self.unit_threshold.critical,
TestType::IntegrationTest => self.integration_threshold.critical,
TestType::DocTest => self.doctest_threshold.critical,
TestType::Unknown => time_constants::UNKNOWN_CRITICAL,
}
}
fn default_unit() -> TimeThreshold {
TimeThreshold::new(time_constants::UNIT_WARN, time_constants::UNIT_CRITICAL)
}
fn default_integration() -> TimeThreshold {
TimeThreshold::new(time_constants::INTEGRATION_WARN, time_constants::INTEGRATION_CRITICAL)
}
fn default_doctest() -> TimeThreshold {
TimeThreshold::new(time_constants::DOCTEST_WARN, time_constants::DOCTEST_CRITICAL)
}
}
#[derive(Debug)]
pub struct TestOpts {
pub list: bool,
@@ -418,7 +603,7 @@ pub struct TestOpts {
pub format: OutputFormat,
pub test_threads: Option<usize>,
pub skip: Vec<String>,
pub report_time: bool,
pub time_options: Option<TestTimeOptions>,
pub options: Options,
}
@@ -502,10 +687,28 @@ fn optgroups() -> getopts::Options {
unstable-options = Allow use of experimental features",
"unstable-options",
)
.optflag(
.optflagopt(
"",
"report-time",
"Show execution time of each test. Not available for --format=terse"
"Show execution time of each test. Awailable values:
plain = do not colorize the execution time (default);
colored = colorize output according to the `color` parameter value;
Threshold values for colorized output can be configured via
`RUST_TEST_TIME_UNIT`, `RUST_TEST_TIME_INTEGRATION` and
`RUST_TEST_TIME_DOCTEST` environment variables.
Not available for --format=terse",
"plain|colored"
)
.optflag(
"",
"ensure-test-time",
"Treat excess of the test execution time limit as error.
Threshold values for this option can be configured via
`RUST_TEST_TIME_UNIT`, `RUST_TEST_TIME_INTEGRATION` and
`RUST_TEST_TIME_DOCTEST` environment variables."
);
return opts;
}
@@ -554,6 +757,21 @@ fn is_nightly() -> bool {
bootstrap || !disable_unstable_features
}
// Gets the option value and checks if unstable features are enabled.
macro_rules! unstable_optflag {
($matches:ident, $allow_unstable:ident, $option_name:literal) => {{
let opt = $matches.opt_present($option_name);
if !$allow_unstable && opt {
return Some(Err(format!(
"The \"{}\" flag is only accepted on the nightly compiler",
$option_name
)));
}
opt
}};
}
// Parses command line arguments into test options
pub fn parse_opts(args: &[String]) -> Option<OptRes> {
let mut allow_unstable = false;
@@ -592,26 +810,9 @@ pub fn parse_opts(args: &[String]) -> Option<OptRes> {
None
};
let exclude_should_panic = matches.opt_present("exclude-should-panic");
if !allow_unstable && exclude_should_panic {
return Some(Err(
"The \"exclude-should-panic\" flag is only accepted on the nightly compiler".into(),
));
}
let exclude_should_panic = unstable_optflag!(matches, allow_unstable, "exclude-should-panic");
let include_ignored = matches.opt_present("include-ignored");
if !allow_unstable && include_ignored {
return Some(Err(
"The \"include-ignored\" flag is only accepted on the nightly compiler".into(),
));
}
let report_time = matches.opt_present("report-time");
if !allow_unstable && report_time {
return Some(Err(
"The \"report-time\" flag is only accepted on the nightly compiler".into(),
));
}
let include_ignored = unstable_optflag!(matches, allow_unstable, "include-ignored");
let run_ignored = match (include_ignored, matches.opt_present("ignored")) {
(true, true) => {
@@ -641,6 +842,19 @@ pub fn parse_opts(args: &[String]) -> Option<OptRes> {
};
}
let report_time = unstable_optflag!(matches, allow_unstable, "report-time");
let colored_opt_str = matches.opt_str("report-time");
let report_time_colored = report_time && colored_opt_str == Some("colored".into());
let ensure_test_time = unstable_optflag!(matches, allow_unstable, "ensure-test-time");
// If `ensure-test-time` option is provided, time output is enforced,
// so user won't be confused if any of tests will silently fail.
let time_options = if report_time || ensure_test_time {
Some(TestTimeOptions::new_from_env(ensure_test_time, report_time_colored))
} else {
None
};
let test_threads = match matches.opt_str("test-threads") {
Some(n_str) => match n_str.parse::<usize>() {
Ok(0) => return Some(Err("argument for --test-threads must not be 0".to_string())),
@@ -706,20 +920,20 @@ pub fn parse_opts(args: &[String]) -> Option<OptRes> {
format,
test_threads,
skip: matches.opt_strs("skip"),
report_time,
time_options,
options: Options::new().display_output(matches.opt_present("show-output")),
};
Some(Ok(test_opts))
}
#[derive(Clone, PartialEq)]
#[derive(Debug, Clone, PartialEq)]
pub struct BenchSamples {
ns_iter_summ: stats::Summary,
mb_s: usize,
}
#[derive(Clone, PartialEq)]
#[derive(Debug, Clone, PartialEq)]
pub enum TestResult {
TrOk,
TrFailed,
@@ -727,6 +941,7 @@ pub enum TestResult {
TrIgnored,
TrAllowedFail,
TrBench(BenchSamples),
TrTimedFail,
}
unsafe impl Send for TestResult {}
@@ -774,6 +989,7 @@ struct ConsoleTestState {
metrics: MetricMap,
failures: Vec<(TestDesc, Vec<u8>)>,
not_failures: Vec<(TestDesc, Vec<u8>)>,
time_failures: Vec<(TestDesc, Vec<u8>)>,
options: Options,
}
@@ -796,6 +1012,7 @@ impl ConsoleTestState {
metrics: MetricMap::new(),
failures: Vec::new(),
not_failures: Vec::new(),
time_failures: Vec::new(),
options: opts.options,
})
}
@@ -831,11 +1048,12 @@ impl ConsoleTestState {
TrIgnored => "ignored".to_owned(),
TrAllowedFail => "failed (allowed)".to_owned(),
TrBench(ref bs) => fmt_bench_samples(bs),
TrTimedFail => "failed (time limit exceeded)".to_owned(),
},
test.name,
))?;
if let Some(exec_time) = exec_time {
self.write_log(|| format!(" {}", exec_time))?;
self.write_log(|| format!(" <{}>", exec_time))?;
}
self.write_log(|| "\n")
}
@@ -993,6 +1211,10 @@ pub fn run_tests_console(opts: &TestOpts, tests: Vec<TestDescAndFn>) -> io::Resu
stdout.extend_from_slice(format!("note: {}", msg).as_bytes());
st.failures.push((test, stdout));
}
TrTimedFail => {
st.failed += 1;
st.time_failures.push((test, stdout));
}
}
Ok(())
}
@@ -1018,6 +1240,7 @@ pub fn run_tests_console(opts: &TestOpts, tests: Vec<TestDescAndFn>) -> io::Resu
use_color(opts),
max_name_len,
is_multithreaded,
opts.time_options,
)),
OutputFormat::Terse => Box::new(TerseFormatter::new(
output,
@@ -1487,15 +1710,20 @@ pub fn run_test(
return;
}
struct TestRunOpts {
pub nocapture: bool,
pub concurrency: Concurrent,
pub time: Option<TestTimeOptions>,
}
fn run_test_inner(
desc: TestDesc,
nocapture: bool,
report_time: bool,
strategy: RunStrategy,
monitor_ch: Sender<MonitorMsg>,
testfn: Box<dyn FnOnce() + Send>,
concurrency: Concurrent,
opts: TestRunOpts,
) {
let concurrency = opts.concurrency;
let name = desc.name.clone();
let runtest = move || {
@@ -1518,6 +1746,12 @@ pub fn run_test(
}
}
let test_run_opts = TestRunOpts {
nocapture: opts.nocapture,
concurrency,
time: opts.time_options
};
match testfn {
DynBenchFn(bencher) => {
// Benchmarks aren't expected to panic, so we run them all in-process.
@@ -1538,8 +1772,6 @@ pub fn run_test(
};
run_test_inner(
desc,
opts.nocapture,
opts.report_time,
strategy,
monitor_ch,
Box::new(move || __rust_begin_short_backtrace(f)),
@@ -1548,12 +1780,10 @@ pub fn run_test(
}
StaticTestFn(f) => run_test_inner(
desc,
opts.nocapture,
opts.report_time,
strategy,
monitor_ch,
Box::new(move || __rust_begin_short_backtrace(f)),
concurrency,
test_run_opts,
),
}
}
@@ -1564,10 +1794,13 @@ fn __rust_begin_short_backtrace<F: FnOnce()>(f: F) {
f()
}
fn calc_result<'a>(desc: &TestDesc,
task_result: Result<(), &'a (dyn Any + 'static + Send)>)
fn calc_result<'a>(
desc: &TestDesc,
task_result: Result<(), &'a (dyn Any + 'static + Send)>)
time_opts: &Option<TestTimeOptions>,
exec_time: &Option<TestExecTime>)
-> TestResult {
match (&desc.should_panic, task_result) {
let result = match (&desc.should_panic, task_result) {
(&ShouldPanic::No, Ok(())) | (&ShouldPanic::Yes, Err(_)) => TrOk,
(&ShouldPanic::YesWithMessage(msg), Err(ref err)) => {
if err
@@ -1589,7 +1822,22 @@ fn calc_result<'a>(desc: &TestDesc,
(&ShouldPanic::Yes, Ok(())) => TrFailedMsg("test did not panic as expected".to_string()),
_ if desc.allow_fail => TrAllowedFail,
_ => TrFailed,
};
// If test is already failed (or allowed to fail), do not change the result.
if result != TrOk {
return result;
}
// Check if test is failed due to timeout.
if let (Some(opts), Some(time)) = (time_opts, exec_time) {
if opts.error_on_excess && opts.is_critical(desc, time) {
return TrTimedFail;
}
}
result
}
fn get_result_from_exit_code(desc: &TestDesc, code: i32) -> TestResult {