Skip to content

Commit

Permalink
Auto merge of #64663 - jakoschiko:report-time, r=alexcrichton
Browse files Browse the repository at this point in the history
libtest: Add --report-time flag to print test execution time

Implements the flag `--report-time` to print the execution time of each executed (successful or failed) test.

Closes #46610

# Example

`cargo test -- --report-time` produces the following output to stdout:
```
running 6 tests
test tests::ignore ... ignored
test tests::noop ... ok 0.000s
test tests::should_panic ... ok 0.000s
test tests::panic_after_10millis ... FAILED 0.010s
test tests::sleep_100millis ... ok 0.100s
test tests::sleep_10secs ... ok 10.001s

failures:

---- tests::panic_after_10millis stdout ----
thread 'tests::panic_after_10millis' panicked at 'foo', src\lib.rs:31:9

failures:
    tests::panic_after_10millis

test result: FAILED. 4 passed; 1 failed; 1 ignored; 0 measured; 0 filtered out
```
`cargo test -- --report-time -Z unstable-options --format=json` produces the following output to stdout:
```
{ "type": "suite", "event": "started", "test_count": 6 }
{ "type": "test", "event": "started", "name": "tests::ignore" }
{ "type": "test", "event": "started", "name": "tests::noop" }
{ "type": "test", "event": "started", "name": "tests::panic_after_10millis" }
{ "type": "test", "event": "started", "name": "tests::should_panic" }
{ "type": "test", "name": "tests::ignore", "event": "ignored" }
{ "type": "test", "event": "started", "name": "tests::sleep_100millis" }
{ "type": "test", "name": "tests::noop", "event": "ok", "exec_time": "0.000s" }
{ "type": "test", "event": "started", "name": "tests::sleep_10secs" }
{ "type": "test", "name": "tests::should_panic", "event": "ok", "exec_time": "0.000s" }
{ "type": "test", "name": "tests::panic_after_10millis", "event": "failed", "exec_time": "0.010s", "stdout": "thread 'tests::panic_after_10millis' panicked at 'foo', src\\lib.rs:31:9\n" }
{ "type": "test", "name": "tests::sleep_100millis", "event": "ok", "exec_time": "0.101s" }
{ "type": "test", "name": "tests::sleep_10secs", "event": "ok", "exec_time": "10.000s" }
{ "type": "suite", "event": "failed", "passed": 4, "failed": 1, "allowed_fail": 0, "ignored": 1, "measured": 0, "filtered_out": 0 }
```
`cargo test -- --report-time --logfile foo.log` produces the following logfile:
```
ignored tests::ignore
ok tests::noop 0.000s
ok tests::should_panic 0.000s
failed tests::panic_after_10millis 0.010s
ok tests::sleep_100millis 0.100s
ok tests::sleep_10secs 10.001s
```
  • Loading branch information
bors committed Sep 25, 2019
2 parents c7bc0bf + d91b965 commit acf7b50
Show file tree
Hide file tree
Showing 6 changed files with 168 additions and 48 deletions.
32 changes: 26 additions & 6 deletions src/libtest/formatters/json.rs
Original file line number Diff line number Diff line change
Expand Up @@ -27,13 +27,20 @@ impl<T: Write> JsonFormatter<T> {
ty: &str,
name: &str,
evt: &str,
exec_time: Option<&TestExecTime>,
stdout: Option<Cow<'_, str>>,
extra: Option<&str>,
) -> io::Result<()> {
self.write_message(&*format!(
r#"{{ "type": "{}", "name": "{}", "event": "{}""#,
ty, name, evt
))?;
if let Some(exec_time) = exec_time {
self.write_message(&*format!(
r#", "exec_time": "{}""#,
exec_time
))?;
}
if let Some(stdout) = stdout {
self.write_message(&*format!(
r#", "stdout": "{}""#,
Expand Down Expand Up @@ -69,6 +76,7 @@ impl<T: Write> OutputFormatter for JsonFormatter<T> {
&mut self,
desc: &TestDesc,
result: &TestResult,
exec_time: Option<&TestExecTime>,
stdout: &[u8],
state: &ConsoleTestState,
) -> io::Result<()> {
Expand All @@ -78,24 +86,36 @@ impl<T: Write> OutputFormatter for JsonFormatter<T> {
None
};
match *result {
TrOk => self.write_event("test", desc.name.as_slice(), "ok", stdout, None),
TrOk => {
self.write_event("test", desc.name.as_slice(), "ok", exec_time, stdout, None)
}

TrFailed => self.write_event("test", desc.name.as_slice(), "failed", stdout, None),
TrFailed => {
self.write_event("test", desc.name.as_slice(), "failed", exec_time, stdout, None)
}

TrFailedMsg(ref m) => self.write_event(
"test",
desc.name.as_slice(),
"failed",
exec_time,
stdout,
Some(&*format!(r#""message": "{}""#, EscapedString(m))),
),

TrIgnored => self.write_event("test", desc.name.as_slice(), "ignored", stdout, None),

TrAllowedFail => {
self.write_event("test", desc.name.as_slice(), "allowed_failure", stdout, None)
TrIgnored => {
self.write_event("test", desc.name.as_slice(), "ignored", exec_time, stdout, None)
}

TrAllowedFail => self.write_event(
"test",
desc.name.as_slice(),
"allowed_failure",
exec_time,
stdout,
None,
),

TrBench(ref bs) => {
let median = bs.ns_iter_summ.median as usize;
let deviation = (bs.ns_iter_summ.max - bs.ns_iter_summ.min) as usize;
Expand Down
1 change: 1 addition & 0 deletions src/libtest/formatters/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@ pub(crate) trait OutputFormatter {
&mut self,
desc: &TestDesc,
result: &TestResult,
exec_time: Option<&TestExecTime>,
stdout: &[u8],
state: &ConsoleTestState,
) -> io::Result<()>;
Expand Down
29 changes: 17 additions & 12 deletions src/libtest/formatters/pretty.rs
Original file line number Diff line number Diff line change
Expand Up @@ -30,20 +30,20 @@ impl<T: Write> PrettyFormatter<T> {
&self.out
}

pub fn write_ok(&mut self) -> io::Result<()> {
self.write_short_result("ok", term::color::GREEN)
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_failed(&mut self) -> io::Result<()> {
self.write_short_result("FAILED", term::color::RED)
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_ignored(&mut self) -> io::Result<()> {
self.write_short_result("ignored", term::color::YELLOW)
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_allowed_fail(&mut self) -> io::Result<()> {
self.write_short_result("FAILED (allowed)", 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_bench(&mut self) -> io::Result<()> {
Expand All @@ -54,8 +54,12 @@ 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")
}

Expand Down Expand Up @@ -166,6 +170,7 @@ impl<T: Write> OutputFormatter for PrettyFormatter<T> {
&mut self,
desc: &TestDesc,
result: &TestResult,
exec_time: Option<&TestExecTime>,
_: &[u8],
_: &ConsoleTestState,
) -> io::Result<()> {
Expand All @@ -174,10 +179,10 @@ impl<T: Write> OutputFormatter for PrettyFormatter<T> {
}

match *result {
TrOk => self.write_ok(),
TrFailed | TrFailedMsg(_) => self.write_failed(),
TrIgnored => self.write_ignored(),
TrAllowedFail => self.write_allowed_fail(),
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),
TrBench(ref bs) => {
self.write_bench()?;
self.write_plain(&format!(": {}\n", fmt_bench_samples(bs)))
Expand Down
1 change: 1 addition & 0 deletions src/libtest/formatters/terse.rs
Original file line number Diff line number Diff line change
Expand Up @@ -174,6 +174,7 @@ impl<T: Write> OutputFormatter for TerseFormatter<T> {
&mut self,
desc: &TestDesc,
result: &TestResult,
_: Option<&TestExecTime>,
_: &[u8],
_: &ConsoleTestState,
) -> io::Result<()> {
Expand Down
Loading

0 comments on commit acf7b50

Please sign in to comment.