fix(forge): total duration is not the sum of individual runs (#7228)

* fix(forge): total duration is not the sum of individual runs

* updates

* update

* chore: clippy

crates/forge/bin/cmd/test/mod.rs

@@ -32,7 +32,7 @@ use foundry_config::{
 };
 use foundry_debugger::Debugger;
 use regex::Regex;
-use std::{collections::BTreeMap, sync::mpsc::channel};
+use std::{sync::mpsc::channel, time::Instant};
 use watchexec::config::{InitConfig, RuntimeConfig};
 use yansi::Paint;
 
@@ -296,6 +296,7 @@ impl TestArgs {
 
  // Run tests.
  let (tx, rx) = channel::<(String, SuiteResult)>();
+ let timer = Instant::now();
  let handle = tokio::task::spawn({
  let filter = filter.clone();
  async move { runner.test(&filter, tx, test_options).await }
@@ -419,6 +420,7 @@ impl TestArgs {
  break;
  }
  }
+ let duration = timer.elapsed();
 
  trace!(target: "forge::test", len=outcome.results.len(), %any_test_failed, "done with results");
 
@@ -429,7 +431,7 @@ impl TestArgs {
  }
 
  if !outcome.results.is_empty() {
- shell::println(outcome.summary())?;
+ shell::println(outcome.summary(duration))?;
 
  if self.summary {
  let mut summary_table = TestSummaryReporter::new(self.detailed);
@@ -515,7 +517,7 @@ fn list(
  }
  }
  }
- Ok(TestOutcome::new(BTreeMap::new(), false))
+ Ok(TestOutcome::empty(false))
 }
 
 #[cfg(test)]

crates/forge/src/result.rs

@@ -42,7 +42,7 @@ impl TestOutcome {
 
  /// Creates a new empty test outcome.
  pub fn empty(allow_failure: bool) -> Self {
- Self { results: BTreeMap::new(), allow_failure, decoder: None }
+ Self::new(BTreeMap::new(), allow_failure)
  }
 
  /// Returns an iterator over all individual succeeding tests and their names.
@@ -112,24 +112,27 @@ impl TestOutcome {
  self.failures().count()
  }
 
- /// Calculates the total duration of all test suites.
- pub fn duration(&self) -> Duration {
+ /// Sums up all the durations of all individual test suites.
+ ///
+ /// Note that this is not necessarily the wall clock time of the entire test run.
+ pub fn total_time(&self) -> Duration {
  self.results.values().map(|suite| suite.duration).sum()
  }
 
  /// Formats the aggregated summary of all test suites into a string (for printing).
- pub fn summary(&self) -> String {
+ pub fn summary(&self, wall_clock_time: Duration) -> String {
  let num_test_suites = self.results.len();
  let suites = if num_test_suites == 1 { "suite" } else { "suites" };
  let total_passed = self.passed();
  let total_failed = self.failed();
  let total_skipped = self.skipped();
  let total_tests = total_passed + total_failed + total_skipped;
  format!(
- "\nRan {} test {} in {:.2?}: {} tests passed, {} failed, {} skipped ({} total tests)",
+ "\nRan {} test {} in {:.2?} ({:.2?} CPU time): {} tests passed, {} failed, {} skipped ({} total tests)",
  num_test_suites,
  suites,
- self.duration(),
+ wall_clock_time,
+ self.total_time(),
  Paint::green(total_passed),
  Paint::red(total_failed),
  Paint::yellow(total_skipped),
@@ -180,7 +183,7 @@ impl TestOutcome {
 /// A set of test results for a single test suite, which is all the tests in a single contract.
 #[derive(Clone, Debug, Serialize)]
 pub struct SuiteResult {
- /// Total duration of the test run for this block of tests.
+ /// Wall clock time it took to execute all tests in this suite.
  pub duration: Duration,
  /// Individual test results: `test fn signature -> TestResult`.
  pub test_results: BTreeMap<String, TestResult>,
@@ -242,17 +245,25 @@ impl SuiteResult {
  self.test_results.len()
  }
 
+ /// Sums up all the durations of all individual tests in this suite.
+ ///
+ /// Note that this is not necessarily the wall clock time of the entire test suite.
+ pub fn total_time(&self) -> Duration {
+ self.test_results.values().map(|result| result.duration).sum()
+ }
+
  /// Returns the summary of a single test suite.
  pub fn summary(&self) -> String {
  let failed = self.failed();
  let result = if failed == 0 { Paint::green("ok") } else { Paint::red("FAILED") };
  format!(
- "Test result: {}. {} passed; {} failed; {} skipped; finished in {:.2?}",
+ "Suite result: {}. {} passed; {} failed; {} skipped; finished in {:.2?} ({:.2?} CPU time)",
  result,
  Paint::green(self.passed()),
  Paint::red(failed),
  Paint::yellow(self.skipped()),
  self.duration,
+ self.total_time(),
  )
  }
 }
@@ -357,6 +368,8 @@ pub struct TestResult {
  /// The debug nodes of the call
  pub debug: Option<DebugArena>,
 
+ pub duration: Duration,
+
  /// pc breakpoint char map
  pub breakpoints: Breakpoints,
 }

crates/forge/src/runner.rs

@@ -386,6 +386,7 @@ impl<'a> ContractRunner<'a> {
  traces,
  labeled_addresses,
  kind: TestKind::Standard(0),
+ duration: start.elapsed(),
  ..Default::default()
  }
  }
@@ -397,6 +398,7 @@ impl<'a> ContractRunner<'a> {
  traces,
  labeled_addresses,
  kind: TestKind::Standard(0),
+ duration: start.elapsed(),
  ..Default::default()
  }
  }
@@ -410,13 +412,8 @@ impl<'a> ContractRunner<'a> {
  );
 
  // Record test execution time
- debug!(
- duration = ?start.elapsed(),
- gas,
- reverted,
- should_fail,
- success,
- );
+ let duration = start.elapsed();
+ debug!(?duration, gas, reverted, should_fail, success);
 
  TestResult {
  status: match success {
@@ -433,6 +430,7 @@ impl<'a> ContractRunner<'a> {
  labeled_addresses,
  debug: debug_arena,
  breakpoints,
+ duration,
  }
  }
 
@@ -452,6 +450,7 @@ impl<'a> ContractRunner<'a> {
  let TestSetup { address, logs, traces, labeled_addresses, coverage, .. } = setup;
 
  // First, run the test normally to see if it needs to be skipped.
+ let start = Instant::now();
  if let Err(EvmError::SkipError) = self.executor.clone().execute_test::<_, _>(
  self.sender,
  address,
@@ -468,6 +467,7 @@ impl<'a> ContractRunner<'a> {
  labeled_addresses,
  kind: TestKind::Invariant { runs: 1, calls: 1, reverts: 1 },
  coverage,
+ duration: start.elapsed(),
  ..Default::default()
  }
  };
@@ -495,6 +495,7 @@ impl<'a> ContractRunner<'a> {
  traces,
  labeled_addresses,
  kind: TestKind::Invariant { runs: 0, calls: 0, reverts: 0 },
+ duration: start.elapsed(),
  ..Default::default()
  }
  }
@@ -542,12 +543,6 @@ impl<'a> ContractRunner<'a> {
  }
  }
 
- let kind = TestKind::Invariant {
- runs: cases.len(),
- calls: cases.iter().map(|sequence| sequence.cases().len()).sum(),
- reverts,
- };
-
  TestResult {
  status: match success {
  true => TestStatus::Success,
@@ -557,10 +552,15 @@ impl<'a> ContractRunner<'a> {
  counterexample,
  decoded_logs: decode_console_logs(&logs),
  logs,
- kind,
+ kind: TestKind::Invariant {
+ runs: cases.len(),
+ calls: cases.iter().map(|sequence| sequence.cases().len()).sum(),
+ reverts,
+ },
  coverage,
  traces,
  labeled_addresses: labeled_addresses.clone(),
+ duration: start.elapsed(),
  ..Default::default() // TODO collect debug traces on the last run or error
  }
  }
@@ -612,6 +612,7 @@ impl<'a> ContractRunner<'a> {
  debug,
  breakpoints,
  coverage,
+ duration: start.elapsed(),
  ..Default::default()
  }
  }
@@ -668,10 +669,8 @@ impl<'a> ContractRunner<'a> {
  coverage = merge_coverages(coverage, result.coverage);
 
  // Record test execution time
- debug!(
- duration = ?start.elapsed(),
- success = %result.success
- );
+ let duration = start.elapsed();
+ debug!(?duration, success = %result.success);
 
  TestResult {
  status: match result.success {
@@ -688,6 +687,7 @@ impl<'a> ContractRunner<'a> {
  labeled_addresses,
  debug,
  breakpoints,
+ duration,
  }
  }
 }

crates/forge/tests/fixtures/can_check_snapshot.stdout

@@ -4,6 +4,6 @@ Compiler run successful!
 
 Ran 1 test for src/ATest.t.sol:ATest
 [PASS] testExample() (gas: 168)
-Test result: ok. 1 passed; 0 failed; 0 skipped; finished in 4.42ms
+Suite result: ok. 1 passed; 0 failed; 0 skipped; finished in 4.42ms
 
 Ran 1 test suite: 1 tests passed, 0 failed, 0 skipped (1 total tests)

crates/forge/tests/fixtures/can_run_test_in_custom_test_folder.stdout

@@ -4,6 +4,6 @@ Compiler run successful!
 
 Ran 1 test for src/nested/forge-tests/MyTest.t.sol:MyTest
 [PASS] testTrue() (gas: 168)
-Test result: ok. 1 passed; 0 failed; 0 skipped; finished in 2.93ms
+Suite result: ok. 1 passed; 0 failed; 0 skipped; finished in 2.93ms
 
 Ran 1 test suite: 1 tests passed, 0 failed, 0 skipped (1 total tests)

crates/forge/tests/fixtures/can_test_repeatedly.stdout

@@ -3,6 +3,6 @@ No files changed, compilation skipped
 Ran 2 tests for test/Counter.t.sol:CounterTest
 [PASS] testFuzz_SetNumber(uint256) (runs: 256, μ: 26521, ~: 28387)
 [PASS] test_Increment() (gas: 28379)
-Test result: ok. 2 passed; 0 failed; 0 skipped; finished in 9.42ms
+Suite result: ok. 2 passed; 0 failed; 0 skipped; finished in 9.42ms
 
 Ran 1 test suite: 2 tests passed, 0 failed, 0 skipped (2 total tests)

crates/forge/tests/fixtures/can_use_libs_in_multi_fork.stdout

@@ -4,6 +4,6 @@ Compiler run successful!
 
 Ran 1 test for test/Contract.t.sol:ContractTest
 [PASS] test() (gas: 70360)
-Test result: ok. 1 passed; 0 failed; 0 skipped; finished in 3.21s
+Suite result: ok. 1 passed; 0 failed; 0 skipped; finished in 3.21s
 
 Ran 1 test suite: 1 tests passed, 0 failed, 0 skipped (1 total tests)

crates/forge/tests/fixtures/include_custom_types_in_traces.stdout

@@ -14,7 +14,7 @@ Traces:
  ├─ emit MyEvent(a: 100)
  └─ ← ()
 
-Test result: FAILED. 1 passed; 1 failed; 0 skipped; finished in 3.88ms
+Suite result: FAILED. 1 passed; 1 failed; 0 skipped; finished in 3.88ms
 
 Ran 1 test suite: 1 tests passed, 1 failed, 0 skipped (2 total tests)
 

crates/forge/tests/fixtures/repro_6531.stdout

@@ -14,6 +14,6 @@ Traces:
  │ └─ ← "USD Coin"
  └─ ← ()
 
-Test result: ok. 1 passed; 0 failed; 0 skipped; finished in 3.43s
+Suite result: ok. 1 passed; 0 failed; 0 skipped; finished in 3.43s
 
 Ran 1 test suite: 1 tests passed, 0 failed, 0 skipped (1 total tests)

crates/forge/tests/fixtures/runs_tests_exactly_once_with_changed_versions.1.stdout

@@ -4,6 +4,6 @@ Compiler run successful!
 
 Ran 1 test for src/Contract.t.sol:ContractTest
 [PASS] testExample() (gas: 190)
-Test result: ok. 1 passed; 0 failed; 0 skipped; finished in 1.89ms
+Suite result: ok. 1 passed; 0 failed; 0 skipped; finished in 1.89ms
 
 Ran 1 test suite: 1 tests passed, 0 failed, 0 skipped (1 total tests)

crates/forge/tests/fixtures/runs_tests_exactly_once_with_changed_versions.2.stdout

@@ -4,6 +4,6 @@ Compiler run successful!
 
 Ran 1 test for src/Contract.t.sol:ContractTest
 [PASS] testExample() (gas: 190)
-Test result: ok. 1 passed; 0 failed; 0 skipped; finished in 1.89ms
+Suite result: ok. 1 passed; 0 failed; 0 skipped; finished in 1.89ms
 
 Ran 1 test suite: 1 tests passed, 0 failed, 0 skipped (1 total tests)

crates/test-utils/src/util.rs

@@ -1054,7 +1054,7 @@ static IGNORE_IN_FIXTURES: Lazy<Regex> = Lazy::new(|| {
  // solc runs
  r"runs: \d+, μ: \d+, ~: \d+",
  // elapsed time
- "(?:finished)? ?in .*?s",
+ r"(?:finished)? ?in .*?s(?: \(.*?s CPU time\))?",
  // file paths
  r"-->.*\.sol",
  r"Location(.|\n)*\.rs(.|\n)*Backtrace",