Heavily Degraded Performance When Increasing Test Verbosity (from `-vv` to `-vvv`)

[Philogy]

Component

Forge

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

• [X] Foundry
• [X] Foundryup

What version of Foundry are you on?

forge 0.2.0 (89f0fb9 2024-04-13T00:15:22.318339000Z)

What command(s) is the bug in?

forge test -vvv

Operating System

macOS (Apple Silicon)

Describe the bug

When adding a single verbosity level (going from -vv to -vvv) in tests the performance and runtime of the tests heavily degrades, despite no additional logs being generated.

Reproduction

1. Clone https://github.com/Philogy/tradable-addresses
2. Compile via forge build
3. Run test forge t -vv --mt test_bubblesIncreaseRevert (nothing too special about this test besides the fact that it suffers the worst) to observe "normal" runtime
4. Run same test with increased verbosity forge t -vvv --mt test_bubblesIncreaseRevert and observe degraded runtime

P.S.: Ignore the warning related to FFI, I have some niche dependencies I didn't want you to have to install for repro. so I made a fallback mode that hardcoded certain contracts if FFI was disabled (this issue persists whether FFI is enabled or not).

[DaniPopes]

I can't reproduce 2 to 3, but I can at 4 and 5 (~800ms-1s from a few ms). For me this is trying to identify selectors from api.openchain.xyz, and disappears with --offline. A single request to this URL takes 750ms for me which is what this test does :/ https://api.openchain.xyz/signature-database/v1/lookup?function=0x60288060,0xff608060,0x60806040

[Philogy]

Weirdly enough --offline speeds it up for me too, (from >70s runtime back down to ~1s). But I don't have any RPC specified or environment variables like ETH_RPC_URL even configured?

Although now it's only reproducible with --ffi somehow (repo changed in the meantime, should've pinned a commit :P)

[zerosnacks]

Weirdly enough --offline speeds it up for me too, (from >70s runtime back down to ~1s). But I don't have any RPC specified or environment variables like ETH_RPC_URL even configured?

Although now it's only reproducible with --ffi somehow (repo changed in the meantime, should've pinned a commit :P)

I'm having trouble running with --ffi, is huffy a special build of Huff? A pinned commit hash would be great

[Philogy]

I'm having trouble running with --ffi, is huffy a special build of Huff? A pinned commit hash would be great

Haha yes, to install clone https://github.com/philogy/py-huff and then do pip3 install -e . when cd'd into the folder

[DaniPopes]

It likely just does a bunch of calls to api.openchain.xyz as I said. It doesn't require RPC URLs, we do this by default when displaying traces.

[zerosnacks]

It likely just does a bunch of calls to api.openchain.xyz as I said. It doesn't require RPC URLs, we do this by default when displaying traces.

I figured that as well, one thing I noticed is that unavailable selectors do not get cached and therefore will be refetched on each test suite run.

https://github.com/foundry-rs/foundry/blob/f8a9d5e4151e6f9f22a277f7213a20d6f7a68472/crates/evm/traces/src/identifier/signatures.rs#L122-L131

The --offline flag has effect here: https://github.com/foundry-rs/foundry/blob/f8a9d5e4151e6f9f22a277f7213a20d6f7a68472/crates/evm/traces/src/identifier/signatures.rs#L112-L134

[Philogy]

It likely just does a bunch of calls to api.openchain.xyz as I said. It doesn't require RPC URLs, we do this by default when displaying traces.

Oh I see, but then why is it querying even if it's not displaying any traces?

[zerosnacks]

The caching issue has since been resolved in https://github.com/foundry-rs/block-explorers/pull/40

The Etherscan querying will still occuring upon the initial run but this was deemed low priority given implementation complexity around the different types of forks and the lack of impact past for anything beyond an initial run