Foundry fuzz test time doubled over the last 2-3 days

[pcaversaccio]

Component

Forge

Have you ensured that all of these are up to date?

• Foundry
• Foundryup

What version of Foundry are you on?

forge 0.2.0 (0396e22 2023-07-01T00:04:34.413676821Z)

What command(s) is the bug in?

forge test

Operating System

Linux

Describe the bug

For context: https://twitter.com/pcaversaccio/status/1675085794963337216

See my repo actions: https://github.com/pcaversaccio/snekmate/actions/workflows/test-contracts.yml

The same is true for OpenZeppelin or Solady fuzz tests (cc @Vectorized)

Maybe that PR triggered the issue?

[pcaversaccio]

@DaniPopes already did a preliminary analysis (posting this here for completeness):

here's what I have so far on snekmate
1. nightly-31d6498c79af595577f200fc2136b31f43885397: forge test  136,57s user 7,99s system 1036% cpu 13,944 total
2. nightly-f9fc9294d480c69a51837a586040ffb51d3e57dc: forge test  203,52s user 8,39s system 1365% cpu 15,515 total

31d6498...f9fc929

[plotchy]

Really sorry to see this. Based on recent prs it would make sense #5246 caused the time increase.

Some thoughts on what may be the cause specifically:

• Each value in state has comparisons to U256::zero() and U256::max()
  • match on value does effectively the same thing yeah?
• ~3x Vec pushes in collect_push_bytes -> leading to 1-2+ Vec reallocs in the fn
  • an iterator over the original bytes output would do a similar job without the reallocs
• ~3x HashSet insertions into state
  • Not sure how to get increase performance on this
• The fuzz corpus could be providing values that get deeper into the fns, executing more opcodes

OTOH, causing a doubling in time seems really unexpected based on these changes. There could be side effects I'm not aware of. Spitballing here - proptest generation time could be linear on state size?

In any case, @mds1 had good instinct with fearing fuzz merges without extensive benching on daedaluzz/etc. It makes sense to revert the pr and I can work on testing it more rigorously with metrics of time/findings/etc. 🫡

[DaniPopes]

It is not #5246, I compared the affected nightlies (31d6498...f9fc929) and also manually reverting the #5246 commit does not fix the regression.

[DaniPopes]

I've confirmed it's #5205, which added an extra run to each fuzz tests. This is unnecessary. cc @Evalir we can probably just check the fuzz result, like below. It might also be possible to count up the number of skips, and if above a certain threshold, then skip the entire fuzz test?

---

Updated timings for time forge test on snekmate (note the first user time in seconds):

pre #5205:
    forge 0.2.0 (31d6498 2023-07-01T11:13:40.594658904Z)
    forge1 test  131,41s user 7,15s system 1006% cpu 13,765 total

latest master:
    forge 0.2.0 (b325876 2023-07-01T14:13:43.245541431Z)
    forge2 test  187,32s user 7,29s system 1294% cpu 15,033 total

patched:
    forge 0.2.0 (c7a3c18 2023-07-01T15:01:42.893226493Z)
    forge3 test  132,52s user 7,39s system 980% cpu 14,263 total

---

Patch

--- a/forge/src/runner.rs
+++ b/forge/src/runner.rs
@@ -537,31 +537,23 @@ impl<'a> ContractRunner<'a> {
     ) -> TestResult {
         let TestSetup { address, mut logs, mut traces, mut labeled_addresses, .. } = setup;
 
-        let skip_fuzz_config = FuzzConfig { runs: 1, ..Default::default() };
-
-        // Fuzz the test with only 1 run to check if it needs to be skipped.
-        let result =
-            FuzzedExecutor::new(&self.executor, runner.clone(), self.sender, skip_fuzz_config)
-                .fuzz(func, address, should_fail, self.errors);
-        if let Some(reason) = result.reason {
-            if matches!(reason.as_str(), "SKIPPED") {
-                return TestResult {
-                    status: TestStatus::Skipped,
-                    reason: None,
-                    decoded_logs: decode_console_logs(&logs),
-                    traces,
-                    labeled_addresses,
-                    kind: TestKind::Standard(0),
-                    ..Default::default()
-                }
-            }
-        }
-
         // Run fuzz test
         let start = Instant::now();
         let mut result = FuzzedExecutor::new(&self.executor, runner, self.sender, fuzz_config)
             .fuzz(func, address, should_fail, self.errors);
 
+        if let Some("SKIPPED") = result.reason.as_deref() {
+            return TestResult {
+                status: TestStatus::Skipped,
+                reason: None,
+                decoded_logs: decode_console_logs(&logs),
+                traces,
+                labeled_addresses,
+                kind: TestKind::Standard(0),
+                ..Default::default()
+            }
+        }
+
         let kind = TestKind::Fuzz {
             median_gas: result.median_gas(false),
             mean_gas: result.mean_gas(false),

[Evalir]

Thanks @DaniPopes — actually pretty surprised fuzzing with only one run adds so much overhead—the intention was to cut fuzzing time by skipping the whole test altogether if it's marked as skipped. Let's patch the fuzzer ASAP then so this doesn't keep happening and CI comes back to normal again 🙏

[DaniPopes]

I guess building the state, dictionary etc is very expensive. Might be worth looking into

[Evalir]

Yeah agreed, I definitely wanna look into it. Even if just patching solves the issue I'd love to see what causes the overhead on the fuzz runner and improve it—looks to me like we can go even faster