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

Enhance report-time option #64873

Merged
merged 7 commits into from
Oct 13, 2019
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
80 changes: 80 additions & 0 deletions src/doc/unstable-book/src/compiler-flags/report-time.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,80 @@
# `report-time`

The tracking issue for this feature is: [#64888]

[#64888]: https://github.com/rust-lang/rust/issues/64888

------------------------

The `report-time` feature adds a possibility to report execution time of the
tests generated via `libtest`.

This is unstable feature, so you have to provide `-Zunstable-options` to get
this feature working.

Sample usage command:

```sh
./test_executable -Zunstable-options --report-time
```

Available options:

```sh
--report-time [plain|colored]
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.
Expected format of environment variable is
`VARIABLE=WARN_TIME,CRITICAL_TIME`.
Not available for --format=terse
--ensure-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.
Expected format of environment variable is
`VARIABLE=WARN_TIME,CRITICAL_TIME`.
`CRITICAL_TIME` here means the limit that should not be
exceeded by test.
```

Example of the environment variable format:

```sh
RUST_TEST_TIME_UNIT=100,200
```

where 100 stands for warn time, and 200 stands for critical time.

## Examples

```sh
cargo test --tests -- -Zunstable-options --report-time
Finished dev [unoptimized + debuginfo] target(s) in 0.02s
Running target/debug/deps/example-27fb188025bec02c

running 3 tests
test tests::unit_test_quick ... ok <0.000s>
test tests::unit_test_warn ... ok <0.055s>
test tests::unit_test_critical ... ok <0.110s>

test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out

Running target/debug/deps/tests-cedb06f6526d15d9

running 3 tests
test unit_test_quick ... ok <0.000s>
test unit_test_warn ... ok <0.550s>
test unit_test_critical ... ok <1.100s>

test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out
```
1 change: 1 addition & 0 deletions src/librustdoc/test.rs
Original file line number Diff line number Diff line change
Expand Up @@ -702,6 +702,7 @@ impl Tester for Collector {
// compiler failures are test failures
should_panic: testing::ShouldPanic::No,
allow_fail: config.allow_fail,
test_type: testing::TestType::DocTest,
},
testfn: testing::DynTestFn(box move || {
let res = run_test(
Expand Down
44 changes: 44 additions & 0 deletions src/libsyntax_ext/test.rs
Original file line number Diff line number Diff line change
Expand Up @@ -106,6 +106,11 @@ pub fn expand_test_or_bench(
cx.path(sp, vec![test_id, cx.ident_of("ShouldPanic", sp), cx.ident_of(name, sp)])
};

// creates test::TestType::$name
let test_type_path = |name| {
cx.path(sp, vec![test_id, cx.ident_of("TestType", sp), cx.ident_of(name, sp)])
};

// creates $name: $expr
let field = |name, expr| cx.field_imm(sp, cx.ident_of(name, sp), expr);

Expand Down Expand Up @@ -181,6 +186,17 @@ pub fn expand_test_or_bench(
cx.expr_path(should_panic_path("YesWithMessage")),
vec![cx.expr_str(sp, sym)]),
}),
// test_type: ...
field("test_type", match test_type(cx) {
// test::TestType::UnitTest
TestType::UnitTest => cx.expr_path(test_type_path("UnitTest")),
// test::TestType::IntegrationTest
TestType::IntegrationTest => cx.expr_path(
test_type_path("IntegrationTest")
),
// test::TestPath::Unknown
TestType::Unknown => cx.expr_path(test_type_path("Unknown")),
}),
// },
])),
// testfn: test::StaticTestFn(...) | test::StaticBenchFn(...)
Expand Down Expand Up @@ -261,6 +277,34 @@ fn should_panic(cx: &ExtCtxt<'_>, i: &ast::Item) -> ShouldPanic {
}
}

enum TestType {
UnitTest,
IntegrationTest,
Unknown,
}

/// Attempts to determine the type of test.
/// Since doctests are created without macro expanding, only possible variants here
/// are `UnitTest`, `IntegrationTest` or `Unknown`.
fn test_type(cx: &ExtCtxt<'_>) -> TestType {
// Root path from context contains the topmost sources directory of the crate.
// I.e., for `project` with sources in `src` and tests in `tests` folders
// (no matter how many nested folders lie inside),
// there will be two different root paths: `/project/src` and `/project/tests`.
let crate_path = cx.root_path.as_path();

if crate_path.ends_with("src") {
// `/src` folder contains unit-tests.
TestType::UnitTest
} else if crate_path.ends_with("tests") {
// `/tests` folder contains integration tests.
TestType::IntegrationTest
} else {
// Crate layout doesn't match expected one, test type is unknown.
TestType::Unknown
}
}

fn has_test_signature(cx: &ExtCtxt<'_>, i: &ast::Item) -> bool {
let has_should_panic_attr = attr::contains_name(&i.attrs, sym::should_panic);
let ref sd = cx.parse_sess.span_diagnostic;
Expand Down
9 changes: 9 additions & 0 deletions src/libtest/formatters/json.rs
Original file line number Diff line number Diff line change
Expand Up @@ -94,6 +94,15 @@ impl<T: Write> OutputFormatter for JsonFormatter<T> {
self.write_event("test", desc.name.as_slice(), "failed", exec_time, stdout, None)
}

TrTimedFail => self.write_event(
"test",
desc.name.as_slice(),
"failed",
exec_time,
stdout,
Some(r#""reason": "time limit exceeded""#),
),

TrFailedMsg(ref m) => self.write_event(
"test",
desc.name.as_slice(),
Expand Down
134 changes: 84 additions & 50 deletions src/libtest/formatters/pretty.rs
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@ use super::*;
pub(crate) struct PrettyFormatter<T> {
out: OutputLocation<T>,
use_color: bool,
time_options: Option<TestTimeOptions>,

/// Number of columns to fill when aligning names
max_name_len: usize,
Expand All @@ -16,12 +17,14 @@ impl<T: Write> PrettyFormatter<T> {
use_color: bool,
max_name_len: usize,
is_multithreaded: bool,
time_options: Option<TestTimeOptions>,
) -> Self {
PrettyFormatter {
out,
use_color,
max_name_len,
is_multithreaded,
time_options
}
}

Expand All @@ -30,20 +33,24 @@ impl<T: Write> PrettyFormatter<T> {
&self.out
}

pub fn write_ok(&mut self, exec_time: Option<&TestExecTime>) -> io::Result<()> {
self.write_short_result("ok", term::color::GREEN, exec_time)
pub fn write_ok(&mut self) -> io::Result<()> {
self.write_short_result("ok", term::color::GREEN)
}

pub fn write_failed(&mut self, exec_time: Option<&TestExecTime>) -> io::Result<()> {
self.write_short_result("FAILED", term::color::RED, exec_time)
pub fn write_failed(&mut self) -> io::Result<()> {
self.write_short_result("FAILED", term::color::RED)
}

pub fn write_ignored(&mut self, exec_time: Option<&TestExecTime>) -> io::Result<()> {
self.write_short_result("ignored", term::color::YELLOW, exec_time)
pub fn write_ignored(&mut self) -> io::Result<()> {
self.write_short_result("ignored", term::color::YELLOW)
}

pub fn write_allowed_fail(&mut self, exec_time: Option<&TestExecTime>) -> io::Result<()> {
self.write_short_result("FAILED (allowed)", term::color::YELLOW, exec_time)
pub fn write_allowed_fail(&mut self) -> io::Result<()> {
self.write_short_result("FAILED (allowed)", term::color::YELLOW)
}

pub fn write_time_failed(&mut self) -> io::Result<()> {
self.write_short_result("FAILED (time limit exceeded)", term::color::RED)
}

pub fn write_bench(&mut self) -> io::Result<()> {
Expand All @@ -54,13 +61,8 @@ impl<T: Write> PrettyFormatter<T> {
&mut self,
result: &str,
color: term::color::Color,
exec_time: Option<&TestExecTime>,
) -> io::Result<()> {
self.write_pretty(result, color)?;
if let Some(exec_time) = exec_time {
self.write_plain(format!(" {}", exec_time))?;
}
self.write_plain("\n")
self.write_pretty(result, color)
}

pub fn write_pretty(&mut self, word: &str, color: term::color::Color) -> io::Result<()> {
Expand Down Expand Up @@ -88,12 +90,48 @@ impl<T: Write> PrettyFormatter<T> {
self.out.flush()
}

pub fn write_successes(&mut self, state: &ConsoleTestState) -> io::Result<()> {
self.write_plain("\nsuccesses:\n")?;
let mut successes = Vec::new();
fn write_time(
&mut self,
desc: &TestDesc,
exec_time: Option<&TestExecTime>
) -> io::Result<()> {
if let (Some(opts), Some(time)) = (self.time_options, exec_time) {
let time_str = format!(" <{}>", time);

let color = if opts.colored {
if opts.is_critical(desc, time) {
Some(term::color::RED)
} else if opts.is_warn(desc, time) {
Some(term::color::YELLOW)
} else {
None
}
} else {
None
};

match color {
Some(color) => self.write_pretty(&time_str, color)?,
None => self.write_plain(&time_str)?
}
}

Ok(())
}

fn write_results(
&mut self,
inputs: &Vec<(TestDesc, Vec<u8>)>,
results_type: &str
) -> io::Result<()> {
let results_out_str = format!("\n{}:\n", results_type);

self.write_plain(&results_out_str)?;

let mut results = Vec::new();
let mut stdouts = String::new();
for &(ref f, ref stdout) in &state.not_failures {
successes.push(f.name.to_string());
for &(ref f, ref stdout) in inputs {
results.push(f.name.to_string());
if !stdout.is_empty() {
stdouts.push_str(&format!("---- {} stdout ----\n", f.name));
let output = String::from_utf8_lossy(stdout);
Expand All @@ -106,38 +144,24 @@ impl<T: Write> PrettyFormatter<T> {
self.write_plain(&stdouts)?;
}

self.write_plain("\nsuccesses:\n")?;
successes.sort();
for name in &successes {
self.write_plain(&results_out_str)?;
results.sort();
for name in &results {
self.write_plain(&format!(" {}\n", name))?;
}
Ok(())
}

pub fn write_successes(&mut self, state: &ConsoleTestState) -> io::Result<()> {
self.write_results(&state.not_failures, "successes")
}

pub fn write_failures(&mut self, state: &ConsoleTestState) -> io::Result<()> {
self.write_plain("\nfailures:\n")?;
let mut failures = Vec::new();
let mut fail_out = String::new();
for &(ref f, ref stdout) in &state.failures {
failures.push(f.name.to_string());
if !stdout.is_empty() {
fail_out.push_str(&format!("---- {} stdout ----\n", f.name));
let output = String::from_utf8_lossy(stdout);
fail_out.push_str(&output);
fail_out.push_str("\n");
}
}
if !fail_out.is_empty() {
self.write_plain("\n")?;
self.write_plain(&fail_out)?;
}
self.write_results(&state.failures, "failures")
}

self.write_plain("\nfailures:\n")?;
failures.sort();
for name in &failures {
self.write_plain(&format!(" {}\n", name))?;
}
Ok(())
pub fn write_time_failures(&mut self, state: &ConsoleTestState) -> io::Result<()> {
self.write_results(&state.time_failures, "failures (time limit exceeded)")
}

fn write_test_name(&mut self, desc: &TestDesc) -> io::Result<()> {
Expand Down Expand Up @@ -179,15 +203,19 @@ impl<T: Write> OutputFormatter for PrettyFormatter<T> {
}

match *result {
TrOk => self.write_ok(exec_time),
TrFailed | TrFailedMsg(_) => self.write_failed(exec_time),
TrIgnored => self.write_ignored(exec_time),
TrAllowedFail => self.write_allowed_fail(exec_time),
TrOk => self.write_ok()?,
TrFailed | TrFailedMsg(_) => self.write_failed()?,
TrIgnored => self.write_ignored()?,
TrAllowedFail => self.write_allowed_fail()?,
TrBench(ref bs) => {
self.write_bench()?;
self.write_plain(&format!(": {}\n", fmt_bench_samples(bs)))
self.write_plain(&format!(": {}", fmt_bench_samples(bs)))?;
}
TrTimedFail => self.write_time_failed()?,
}

self.write_time(desc, exec_time)?;
self.write_plain("\n")
}

fn write_timeout(&mut self, desc: &TestDesc) -> io::Result<()> {
Expand All @@ -207,7 +235,13 @@ impl<T: Write> OutputFormatter for PrettyFormatter<T> {
}
let success = state.failed == 0;
if !success {
self.write_failures(state)?;
if !state.failures.is_empty() {
self.write_failures(state)?;
}

if !state.time_failures.is_empty() {
self.write_time_failures(state)?;
}
}

self.write_plain("\ntest result: ")?;
Expand Down
2 changes: 1 addition & 1 deletion src/libtest/formatters/terse.rs
Original file line number Diff line number Diff line change
Expand Up @@ -180,7 +180,7 @@ impl<T: Write> OutputFormatter for TerseFormatter<T> {
) -> io::Result<()> {
match *result {
TrOk => self.write_ok(),
TrFailed | TrFailedMsg(_) => self.write_failed(),
TrFailed | TrFailedMsg(_) | TrTimedFail => self.write_failed(),
TrIgnored => self.write_ignored(),
TrAllowedFail => self.write_allowed_fail(),
TrBench(ref bs) => {
Expand Down
Loading