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

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",