squiid/rust
1
0
Fork 0
Code Issues Pull requests Projects Activity

Auto merge of #64663 - jakoschiko:report-time, r=alexcrichton

Browse source 
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
```
This commit is contained in:
bors 2019-09-25 09:54:50 +00:00
parent c7bc0bf82f d91b965664
commit acf7b50c73
6 changed files with 168 additions and 48 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

32
src/libtest/formatters/json.rs
View file

@ -27,6 +27,7 @@ impl<T: Write> JsonFormatter<T> {
ty: &str,
name: &str,
evt: &str,
exec_time: Option<&TestExecTime>,
stdout: Option<Cow<'_, str>>,
extra: Option<&str>,
) -> io::Result<()> {
@ -34,6 +35,12 @@ impl<T: Write> JsonFormatter<T> {
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": "{}""#,
@ -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<()> {
@ -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;

1
src/libtest/formatters/mod.rs
View file

@ -16,6 +16,7 @@ pub(crate) trait OutputFormatter {
&mut self,
desc: &TestDesc,
result: &TestResult,
exec_time: Option<&TestExecTime>,
stdout: &[u8],
state: &ConsoleTestState,
) -> io::Result<()>;

29
src/libtest/formatters/pretty.rs
View file

@ -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<()> {
@ -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")
}
@ -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<()> {
@ -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)))

1
src/libtest/formatters/terse.rs
View file

@ -174,6 +174,7 @@ impl<T: Write> OutputFormatter for TerseFormatter<T> {
&mut self,
desc: &TestDesc,
result: &TestResult,
_: Option<&TestExecTime>,
_: &[u8],
_: &ConsoleTestState,
) -> io::Result<()> {

107
src/libtest/lib.rs
View file

@ -378,6 +378,7 @@ pub struct TestOpts {
pub format: OutputFormat,
pub test_threads: Option<usize>,
pub skip: Vec<String>,
pub report_time: bool,
pub options: Options,
}
@ -460,6 +461,11 @@ fn optgroups() -> getopts::Options {
"Enable nightly-only flags:
unstable-options = Allow use of experimental features",
"unstable-options",
)
.optflag(
"",
"report-time",
"Show execution time of each test. Not available for --format=terse"
);
return opts;
}
@ -560,6 +566,13 @@ pub fn parse_opts(args: &[String]) -> Option<OptRes> {
));
}
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 run_ignored = match (include_ignored, matches.opt_present("ignored")) {
(true, true) => {
return Some(Err(
@ -653,6 +666,7 @@ pub fn parse_opts(args: &[String]) -> Option<OptRes> {
format,
test_threads,
skip: matches.opt_strs("skip"),
report_time,
options: Options::new().display_output(matches.opt_present("show-output")),
};
@ -677,6 +691,16 @@ pub enum TestResult {
unsafe impl Send for TestResult {}
/// The meassured execution time of a unit test.
#[derive(Clone, PartialEq)]
pub struct TestExecTime(Duration);
impl fmt::Display for TestExecTime {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
write!(f, "{:.3}s", self.0.as_secs_f64())
}
}
enum OutputLocation<T> {
Pretty(Box<term::StdoutTerminal>),
Raw(T),
@ -736,17 +760,30 @@ impl ConsoleTestState {
})
}
pub fn write_log<S: AsRef<str>>(&mut self, msg: S) -> io::Result<()> {
let msg = msg.as_ref();
pub fn write_log<F, S>(
&mut self,
msg: F,
) -> io::Result<()>
where
S: AsRef<str>,
F: FnOnce() -> S,
{
match self.log_out {
None => Ok(()),
Some(ref mut o) => o.write_all(msg.as_bytes()),
Some(ref mut o) => {
let msg = msg();
let msg = msg.as_ref();
o.write_all(msg.as_bytes())
},
}
}
pub fn write_log_result(&mut self, test: &TestDesc, result: &TestResult) -> io::Result<()> {
self.write_log(format!(
"{} {}\n",
pub fn write_log_result(&mut self,test: &TestDesc,
result: &TestResult,
exec_time: Option<&TestExecTime>,
) -> io::Result<()> {
self.write_log(|| format!(
"{} {}",
match *result {
TrOk => "ok".to_owned(),
TrFailed => "failed".to_owned(),
@ -755,8 +792,12 @@ impl ConsoleTestState {
TrAllowedFail => "failed (allowed)".to_owned(),
TrBench(ref bs) => fmt_bench_samples(bs),
},
test.name
))
test.name,
))?;
if let Some(exec_time) = exec_time {
self.write_log(|| format!(" {}", exec_time))?;
}
self.write_log(|| "\n")
}
fn current_test_count(&self) -> usize {
@ -843,7 +884,7 @@ pub fn list_tests_console(opts: &TestOpts, tests: Vec<TestDescAndFn>) -> io::Res
};
writeln!(output, "{}: {}", name, fntype)?;
st.write_log(format!("{} {}\n", fntype, name))?;
st.write_log(|| format!("{} {}\n", fntype, name))?;
}
fn plural(count: u32, s: &str) -> String {
@ -884,9 +925,9 @@ pub fn run_tests_console(opts: &TestOpts, tests: Vec<TestDescAndFn>) -> io::Resu
TeFilteredOut(filtered_out) => Ok(st.filtered_out = filtered_out),
TeWait(ref test) => out.write_test_start(test),
TeTimeout(ref test) => out.write_timeout(test),
TeResult(test, result, stdout) => {
st.write_log_result(&test, &result)?;
out.write_result(&test, &result, &*stdout, &st)?;
TeResult(test, result, exec_time, stdout) => {
st.write_log_result(&test, &result, exec_time.as_ref())?;
out.write_result(&test, &result, exec_time.as_ref(), &*stdout, &st)?;
match result {
TrOk => {
st.passed += 1;
@ -1004,12 +1045,12 @@ fn stdout_isatty() -> bool {
pub enum TestEvent {
TeFiltered(Vec<TestDesc>),
TeWait(TestDesc),
TeResult(TestDesc, TestResult, Vec<u8>),
TeResult(TestDesc, TestResult, Option<TestExecTime>, Vec<u8>),
TeTimeout(TestDesc),
TeFilteredOut(usize),
}
pub type MonitorMsg = (TestDesc, TestResult, Vec<u8>);
pub type MonitorMsg = (TestDesc, TestResult, Option<TestExecTime>, Vec<u8>);
struct Sink(Arc<Mutex<Vec<u8>>>);
impl Write for Sink {
@ -1105,8 +1146,8 @@ where
let test = remaining.pop().unwrap();
callback(TeWait(test.desc.clone()))?;
run_test(opts, !opts.run_tests, test, tx.clone(), Concurrent::No);
let (test, result, stdout) = rx.recv().unwrap();
callback(TeResult(test, result, stdout))?;
let (test, result, exec_time, stdout) = rx.recv().unwrap();
callback(TeResult(test, result, exec_time, stdout))?;
}
} else {
while pending > 0 || !remaining.is_empty() {
@ -1135,10 +1176,10 @@ where
}
}
let (desc, result, stdout) = res.unwrap();
let (desc, result, exec_time, stdout) = res.unwrap();
running_tests.remove(&desc);
callback(TeResult(desc, result, stdout))?;
callback(TeResult(desc, result, exec_time, stdout))?;
pending -= 1;
}
}
@ -1148,8 +1189,8 @@ where
for b in filtered_benchs {
callback(TeWait(b.desc.clone()))?;
run_test(opts, false, b, tx.clone(), Concurrent::No);
let (test, result, stdout) = rx.recv().unwrap();
callback(TeResult(test, result, stdout))?;
let (test, result, exec_time, stdout) = rx.recv().unwrap();
callback(TeResult(test, result, exec_time, stdout))?;
}
}
Ok(())
@ -1384,7 +1425,7 @@ pub fn run_test(
&& desc.should_panic != ShouldPanic::No;
if force_ignore || desc.ignore || ignore_because_panic_abort {
monitor_ch.send((desc, TrIgnored, Vec::new())).unwrap();
monitor_ch.send((desc, TrIgnored, None, Vec::new())).unwrap();
return;
}
@ -1392,6 +1433,7 @@ pub fn run_test(
desc: TestDesc,
monitor_ch: Sender<MonitorMsg>,
nocapture: bool,
report_time: bool,
testfn: Box<dyn FnOnce() + Send>,
concurrency: Concurrent,
) {
@ -1410,7 +1452,16 @@ pub fn run_test(
None
};
let start = if report_time {
Some(Instant::now())
} else {
None
};
let result = catch_unwind(AssertUnwindSafe(testfn));
let exec_time = start.map(|start| {
let duration = start.elapsed();
TestExecTime(duration)
});
if let Some((printio, panicio)) = oldio {
io::set_print(printio);
@ -1420,7 +1471,7 @@ pub fn run_test(
let test_result = calc_result(&desc, result);
let stdout = data.lock().unwrap().to_vec();
monitor_ch
.send((desc.clone(), test_result, stdout))
.send((desc.clone(), test_result, exec_time, stdout))
.unwrap();
};
@ -1449,12 +1500,20 @@ pub fn run_test(
}
DynTestFn(f) => {
let cb = move || __rust_begin_short_backtrace(f);
run_test_inner(desc, monitor_ch, opts.nocapture, Box::new(cb), concurrency)
run_test_inner(
desc,
monitor_ch,
opts.nocapture,
opts.report_time,
Box::new(cb),
concurrency,
)
}
StaticTestFn(f) => run_test_inner(
desc,
monitor_ch,
opts.nocapture,
opts.report_time,
Box::new(move || __rust_begin_short_backtrace(f)),
concurrency,
),
@ -1702,7 +1761,7 @@ pub mod bench {
};
let stdout = data.lock().unwrap().to_vec();
monitor_ch.send((desc, test_result, stdout)).unwrap();
monitor_ch.send((desc, test_result, None, stdout)).unwrap();
}
pub fn run_once<F>(f: F)

46
src/libtest/tests.rs
View file

@ -23,6 +23,7 @@ impl TestOpts {
format: OutputFormat::Pretty,
test_threads: None,
skip: vec![],
report_time: false,
options: Options::new(),
}
}
@ -67,7 +68,7 @@ pub fn do_not_run_ignored_tests() {
};
let (tx, rx) = channel();
run_test(&TestOpts::new(), false, desc, tx, Concurrent::No);
let (_, res, _) = rx.recv().unwrap();
let (_, res, _, _) = rx.recv().unwrap();
assert!(res != TrOk);
}
@ -85,7 +86,7 @@ pub fn ignored_tests_result_in_ignored() {
};
let (tx, rx) = channel();
run_test(&TestOpts::new(), false, desc, tx, Concurrent::No);
let (_, res, _) = rx.recv().unwrap();
let (_, res, _, _) = rx.recv().unwrap();
assert!(res == TrIgnored);
}
@ -105,7 +106,7 @@ fn test_should_panic() {
};
let (tx, rx) = channel();
run_test(&TestOpts::new(), false, desc, tx, Concurrent::No);
let (_, res, _) = rx.recv().unwrap();
let (_, res, _, _) = rx.recv().unwrap();
assert!(res == TrOk);
}
@ -125,7 +126,7 @@ fn test_should_panic_good_message() {
};
let (tx, rx) = channel();
run_test(&TestOpts::new(), false, desc, tx, Concurrent::No);
let (_, res, _) = rx.recv().unwrap();
let (_, res, _, _) = rx.recv().unwrap();
assert!(res == TrOk);
}
@ -147,7 +148,7 @@ fn test_should_panic_bad_message() {
};
let (tx, rx) = channel();
run_test(&TestOpts::new(), false, desc, tx, Concurrent::No);
let (_, res, _) = rx.recv().unwrap();
let (_, res, _, _) = rx.recv().unwrap();
assert!(res == TrFailedMsg(format!("{} '{}'", failed_msg, expected)));
}
@ -165,10 +166,43 @@ fn test_should_panic_but_succeeds() {
};
let (tx, rx) = channel();
run_test(&TestOpts::new(), false, desc, tx, Concurrent::No);
let (_, res, _) = rx.recv().unwrap();
let (_, res, _, _) = rx.recv().unwrap();
assert!(res == TrFailed);
}
fn report_time_test_template(report_time: bool) -> Option<TestExecTime> {
fn f() {}
let desc = TestDescAndFn {
desc: TestDesc {
name: StaticTestName("whatever"),
ignore: false,
should_panic: ShouldPanic::No,
allow_fail: false,
},
testfn: DynTestFn(Box::new(f)),
};
let test_opts = TestOpts {
report_time,
..TestOpts::new()
};
let (tx, rx) = channel();
run_test(&test_opts, false, desc, tx, Concurrent::No);
let (_, _, exec_time, _) = rx.recv().unwrap();
exec_time
}
#[test]
fn test_should_not_report_time() {
let exec_time = report_time_test_template(false);
assert!(exec_time.is_none());
}
#[test]
fn test_should_report_time() {
let exec_time = report_time_test_template(true);
assert!(exec_time.is_some());
}
#[test]
fn parse_ignored_flag() {
let args = vec![