From d473c88e883d60b8fcd5384448f3246c327b6659 Mon Sep 17 00:00:00 2001 From: DaniPopes <57450786+DaniPopes@users.noreply.github.com> Date: Sat, 24 Feb 2024 03:39:35 +0100 Subject: [PATCH 1/4] fix(forge): total duration is not the sum of individual runs --- crates/forge/bin/cmd/test/mod.rs | 8 ++++--- crates/forge/src/result.rs | 29 ++++++++++++++++++------- crates/forge/src/runner.rs | 36 ++++++++++++++++---------------- 3 files changed, 44 insertions(+), 29 deletions(-) diff --git a/crates/forge/bin/cmd/test/mod.rs b/crates/forge/bin/cmd/test/mod.rs index d84817659da7..3a29ff2ab896 100644 --- a/crates/forge/bin/cmd/test/mod.rs +++ b/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::{collections::BTreeMap, fs, 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)] diff --git a/crates/forge/src/result.rs b/crates/forge/src/result.rs index cb53756551d7..07cf82cf0571 100644 --- a/crates/forge/src/result.rs +++ b/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,13 +112,15 @@ 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(); @@ -126,10 +128,11 @@ impl TestOutcome { 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?} user 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, @@ -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?} user 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, + pub duration: Duration, + /// pc breakpoint char map pub breakpoints: Breakpoints, } diff --git a/crates/forge/src/runner.rs b/crates/forge/src/runner.rs index 912fbb895d20..356248a61c62 100644 --- a/crates/forge/src/runner.rs +++ b/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, } } } From 5ec5f5e3bbed8f04b4d04eb299e16476a377c75c Mon Sep 17 00:00:00 2001 From: DaniPopes <57450786+DaniPopes@users.noreply.github.com> Date: Sat, 24 Feb 2024 03:55:16 +0100 Subject: [PATCH 2/4] updates --- crates/forge/src/result.rs | 4 ++-- crates/forge/tests/fixtures/can_check_snapshot.stdout | 2 +- .../tests/fixtures/can_run_test_in_custom_test_folder.stdout | 2 +- crates/forge/tests/fixtures/can_test_repeatedly.stdout | 2 +- crates/forge/tests/fixtures/can_use_libs_in_multi_fork.stdout | 2 +- crates/forge/tests/fixtures/repro_6531.stdout | 2 +- .../runs_tests_exactly_once_with_changed_versions.1.stdout | 2 +- .../runs_tests_exactly_once_with_changed_versions.2.stdout | 2 +- crates/test-utils/src/util.rs | 2 +- 9 files changed, 10 insertions(+), 10 deletions(-) diff --git a/crates/forge/src/result.rs b/crates/forge/src/result.rs index 07cf82cf0571..1605f72fe8f9 100644 --- a/crates/forge/src/result.rs +++ b/crates/forge/src/result.rs @@ -128,7 +128,7 @@ impl TestOutcome { let total_skipped = self.skipped(); let total_tests = total_passed + total_failed + total_skipped; format!( - "\nRan {} test {} in {:.2?} ({:.2?} user time): {} tests passed, {} failed, {} skipped ({} total tests)", + "\nRan {} test {} in {:.2?} ({:.2?} CPU time): {} tests passed, {} failed, {} skipped ({} total tests)", num_test_suites, suites, wall_clock_time, @@ -257,7 +257,7 @@ impl SuiteResult { let failed = self.failed(); let result = if failed == 0 { Paint::green("ok") } else { Paint::red("FAILED") }; format!( - "Suite result: {}. {} passed; {} failed; {} skipped; finished in {:.2?} ({:.2?} user time)", + "Suite result: {}. {} passed; {} failed; {} skipped; finished in {:.2?} ({:.2?} CPU time)", result, Paint::green(self.passed()), Paint::red(failed), diff --git a/crates/forge/tests/fixtures/can_check_snapshot.stdout b/crates/forge/tests/fixtures/can_check_snapshot.stdout index 1846bd5778b6..bce1c6972521 100644 --- a/crates/forge/tests/fixtures/can_check_snapshot.stdout +++ b/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) diff --git a/crates/forge/tests/fixtures/can_run_test_in_custom_test_folder.stdout b/crates/forge/tests/fixtures/can_run_test_in_custom_test_folder.stdout index 1701d90029b9..cd92d6ebeed8 100644 --- a/crates/forge/tests/fixtures/can_run_test_in_custom_test_folder.stdout +++ b/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) diff --git a/crates/forge/tests/fixtures/can_test_repeatedly.stdout b/crates/forge/tests/fixtures/can_test_repeatedly.stdout index 3d782aa35872..dbab2812511d 100644 --- a/crates/forge/tests/fixtures/can_test_repeatedly.stdout +++ b/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) diff --git a/crates/forge/tests/fixtures/can_use_libs_in_multi_fork.stdout b/crates/forge/tests/fixtures/can_use_libs_in_multi_fork.stdout index 5a5b2f621811..70c72887aaea 100644 --- a/crates/forge/tests/fixtures/can_use_libs_in_multi_fork.stdout +++ b/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) diff --git a/crates/forge/tests/fixtures/repro_6531.stdout b/crates/forge/tests/fixtures/repro_6531.stdout index 1dfca09d72ff..159c6476eb98 100644 --- a/crates/forge/tests/fixtures/repro_6531.stdout +++ b/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) diff --git a/crates/forge/tests/fixtures/runs_tests_exactly_once_with_changed_versions.1.stdout b/crates/forge/tests/fixtures/runs_tests_exactly_once_with_changed_versions.1.stdout index c46d083296fa..c98d9f93e42f 100644 --- a/crates/forge/tests/fixtures/runs_tests_exactly_once_with_changed_versions.1.stdout +++ b/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) diff --git a/crates/forge/tests/fixtures/runs_tests_exactly_once_with_changed_versions.2.stdout b/crates/forge/tests/fixtures/runs_tests_exactly_once_with_changed_versions.2.stdout index 28dbffcc86c3..abfd712db4c1 100644 --- a/crates/forge/tests/fixtures/runs_tests_exactly_once_with_changed_versions.2.stdout +++ b/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) diff --git a/crates/test-utils/src/util.rs b/crates/test-utils/src/util.rs index f5beda778563..a26936489314 100644 --- a/crates/test-utils/src/util.rs +++ b/crates/test-utils/src/util.rs @@ -1054,7 +1054,7 @@ static IGNORE_IN_FIXTURES: Lazy = 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", From f90ed3a8caf5835c00ef28537d6210e4668c2585 Mon Sep 17 00:00:00 2001 From: DaniPopes <57450786+DaniPopes@users.noreply.github.com> Date: Sat, 24 Feb 2024 04:06:02 +0100 Subject: [PATCH 3/4] update --- .../forge/tests/fixtures/include_custom_types_in_traces.stdout | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/crates/forge/tests/fixtures/include_custom_types_in_traces.stdout b/crates/forge/tests/fixtures/include_custom_types_in_traces.stdout index 19771e0920f5..786679a6736b 100644 --- a/crates/forge/tests/fixtures/include_custom_types_in_traces.stdout +++ b/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) From 8313388f8e8ce896f033228ed0e71d39f85dda48 Mon Sep 17 00:00:00 2001 From: DaniPopes <57450786+DaniPopes@users.noreply.github.com> Date: Sat, 24 Feb 2024 11:23:35 +0100 Subject: [PATCH 4/4] chore: clippy --- crates/forge/bin/cmd/test/mod.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/crates/forge/bin/cmd/test/mod.rs b/crates/forge/bin/cmd/test/mod.rs index 3a29ff2ab896..ba928f6ea313 100644 --- a/crates/forge/bin/cmd/test/mod.rs +++ b/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, fs, sync::mpsc::channel, time::Instant}; +use std::{sync::mpsc::channel, time::Instant}; use watchexec::config::{InitConfig, RuntimeConfig}; use yansi::Paint;