search

foundry-rs / foundry

Foundry is a blazing fast, portable and modular toolkit for Ethereum application development written in Rust.
https://getfoundry.sh
Apache License 2.0
8.09k stars 1.67k forks source link

bug(`anvil`): contract call extremely slow after `anvil_reset` on a fork hangs #7966

Open cstoneham opened 3 months ago

cstoneham commented 3 months ago

Component

Anvil

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

What version of Foundry are you on?

forge 0.2.0 (a4d79ac 2024-05-10T00:18:07.559888000Z)

What command(s) is the bug in?

cast rpc

Operating System

macOS (Apple Silicon)

Describe the bug

After resetting a forked network to a given block, the next call to a contract fails (but after this it will succeed).

Steps to Repro:

  1. Run Anvil:

    anvil --host 0.0.0.0 --fork-url $MAINNET_RPC_URL --port 8550 --no-rate-limit

  2. Call anvil_reset:

    cast rpc --rpc-url http://localhost:8550/ anvil_reset '{"jsonRpcUrl": $MAINNET_RPC_URL,"blockNumber":19916015}'

  3. Make a call to a contract, in this example we're calling the OneInch OffchainOracle:

    cast call 0x0AdDd25a91563696D8567Df78D5A01C9a991F9B8 --rpc-url http://localhost:8550/ "getRateWithThreshold(address srcToken,address dstToken,bool useWrappers,uint256 thresholdFilter)(uint256)" 0xA0b86991c6218b36c1d19D4a2e9Eb0cE3606eB48 0x6b175474e89094c44da98b954eedeac495271d0f false 50

  4. Notice that this hangs for 30+ seconds.

  5. Notice that if you stop this call and fire the same one again, it's fast.

dqian commented 3 months ago

seeing this too

WardenJakx commented 3 months ago

+1. very annoying plz fix

DaniPopes commented 3 months ago

cc @mattsse

mattsse commented 3 months ago

checking, sorry about the delay

mattsse commented 3 months ago

this is indepent of the anvil_reset call?

could you perhaps point me to the contract code? from the traces I see that this requests a ton of accounts and storage slots which would explain why it takes a while

mjpowersjr commented 3 months ago

I'm wondering if Anvil is clearing the local cache of fetched upstream storage slots when reset is called?

mattsse commented 3 months ago

it does, because after reset this is no longer useful, but the fetched storage for the old height is cached on disk and the new height is initialized with the corresponding cache file for that block if it exists.

cstoneham commented 3 months ago

it's definitely a heavy call but if you make an RPC call directly at this block height it's quite fast

I would've thought that the fork call would effectively be proxying that rpc call locally and then caching it async - though I'm not super familiar with how anvil forks work under the hood.

thanks for looking into this btw!

mattsse commented 3 months ago

the way forked evm works is it translates database calls that the evm issues (storage, code, account) into rpc calls, like eth_getStorageAt, eth_getTransactionCount for nonce etc..

most expensive ones are accounts because this requires 3 calls balance,code,nonce so executing a transaction in fork mode becomes more expensive if a txs touches a lot of accounts and slots

but fetched data is cached based on chain height, so if the same slot/account is requested again it no longer requires an rpc

mjpowersjr commented 3 months ago

Ok, I wrote a little test to understand what's going on. I put together a simple node.js json-rpc proxy that would log out any proxied requests. (I can attach the proxy.js to a gist, etc if needed - but it's nothing special - just a simple logging http proxy).

My setup was as follows:

curl <-- http :8545 --> anvil <-- http :3000 --> proxy.js < -- https --> upstream-rpc-server

Below is what I observed:

  1. Start proxy

    # listens on localhost:3000 - and forwards requests to https://eth.llamarpc.com
node proxy.js

  2. Setup Anvil

    rm -rf ~/.foundry/cache; 
# anvil listening on localhost:8545
anvil --fork-url=http://localhost:3000 --fork-block-number 20013538

The proxy logs:

[2024-06-03T20:35:49.151Z] {"method":"eth_chainId","id":0,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.348Z] {"method":"eth_getBlockByNumber","params":["0x13161e2",false],"id":1,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.404Z] {"method":"eth_gasPrice","id":2,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.462Z] {"method":"eth_getTransactionCount","params":["0xf39fd6e51aad88f6f4ce6ab8827279cfffb92266","0x13161e2"],"id":7,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.472Z] {"method":"eth_getCode","params":["0xf39fd6e51aad88f6f4ce6ab8827279cfffb92266","0x13161e2"],"id":8,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.484Z] {"method":"eth_getTransactionCount","params":["0x70997970c51812dc3a010c7d01b50e0d17dc79c8","0x13161e2"],"id":4,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.494Z] {"method":"eth_getCode","params":["0x70997970c51812dc3a010c7d01b50e0d17dc79c8","0x13161e2"],"id":5,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.503Z] {"method":"eth_getBalance","params":["0x70997970c51812dc3a010c7d01b50e0d17dc79c8","0x13161e2"],"id":3,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.511Z] {"method":"eth_getBalance","params":["0xf39fd6e51aad88f6f4ce6ab8827279cfffb92266","0x13161e2"],"id":6,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.521Z] {"method":"eth_getCode","params":["0x9965507d1a55bcc2695c58ba16fb37d819b0a4dc","0x13161e2"],"id":11,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.522Z] {"method":"eth_getBalance","params":["0x9965507d1a55bcc2695c58ba16fb37d819b0a4dc","0x13161e2"],"id":9,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.525Z] {"method":"eth_getTransactionCount","params":["0x9965507d1a55bcc2695c58ba16fb37d819b0a4dc","0x13161e2"],"id":10,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.528Z] {"method":"eth_getCode","params":["0x15d34aaf54267db7d7c367839aaf71a00a2c6a65","0x13161e2"],"id":14,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.533Z] {"method":"eth_getBalance","params":["0x15d34aaf54267db7d7c367839aaf71a00a2c6a65","0x13161e2"],"id":12,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.536Z] {"method":"eth_getTransactionCount","params":["0x15d34aaf54267db7d7c367839aaf71a00a2c6a65","0x13161e2"],"id":13,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.539Z] {"method":"eth_getCode","params":["0x3c44cdddb6a900fa2b585dd299e03d12fa4293bc","0x13161e2"],"id":17,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.542Z] {"method":"eth_getBalance","params":["0x3c44cdddb6a900fa2b585dd299e03d12fa4293bc","0x13161e2"],"id":15,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.545Z] {"method":"eth_getTransactionCount","params":["0x3c44cdddb6a900fa2b585dd299e03d12fa4293bc","0x13161e2"],"id":16,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.546Z] {"method":"eth_getCode","params":["0x90f79bf6eb2c4f870365e785982e1f101e93b906","0x13161e2"],"id":20,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.549Z] {"method":"eth_getBalance","params":["0x90f79bf6eb2c4f870365e785982e1f101e93b906","0x13161e2"],"id":18,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.552Z] {"method":"eth_getTransactionCount","params":["0x90f79bf6eb2c4f870365e785982e1f101e93b906","0x13161e2"],"id":19,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.554Z] {"method":"eth_getCode","params":["0x14dc79964da2c08b23698b3d3cc7ca32193d9955","0x13161e2"],"id":23,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.556Z] {"method":"eth_getBalance","params":["0x14dc79964da2c08b23698b3d3cc7ca32193d9955","0x13161e2"],"id":21,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.560Z] {"method":"eth_getTransactionCount","params":["0x14dc79964da2c08b23698b3d3cc7ca32193d9955","0x13161e2"],"id":22,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.561Z] {"method":"eth_getCode","params":["0xa0ee7a142d267c1f36714e4a8f75612f20a79720","0x13161e2"],"id":29,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.563Z] {"method":"eth_getCode","params":["0x976ea74026e726554db657fa54763abd0c3a0aa9","0x13161e2"],"id":26,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.565Z] {"method":"eth_getBalance","params":["0x976ea74026e726554db657fa54763abd0c3a0aa9","0x13161e2"],"id":24,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.568Z] {"method":"eth_getTransactionCount","params":["0x976ea74026e726554db657fa54763abd0c3a0aa9","0x13161e2"],"id":25,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.570Z] {"method":"eth_getBalance","params":["0xa0ee7a142d267c1f36714e4a8f75612f20a79720","0x13161e2"],"id":27,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.573Z] {"method":"eth_getTransactionCount","params":["0xa0ee7a142d267c1f36714e4a8f75612f20a79720","0x13161e2"],"id":28,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.575Z] {"method":"eth_getCode","params":["0x23618e81e3f5cdf7f54c3d65f7fbc0abf5b21e8f","0x13161e2"],"id":32,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.577Z] {"method":"eth_getBalance","params":["0x23618e81e3f5cdf7f54c3d65f7fbc0abf5b21e8f","0x13161e2"],"id":30,"jsonrpc":"2.0"}
[2024-06-03T20:35:49.580Z] {"method":"eth_getTransactionCount","params":["0x23618e81e3f5cdf7f54c3d65f7fbc0abf5b21e8f","0x13161e2"],"id":31,"jsonrpc":"2.0"}
  1. Send eth_call request to WETH contract symbol (first call) 
    curl -X POST   --header "Content-Type: application/json"   --data '{
"jsonrpc": "2.0",
"method": "eth_call",
"params": [                                                                                      
  {
    "to": "0xC02aaA39b223FE8D0A0e5C4F27ead9083C756Cc2",
    "data": "0x95d89b41"
  },
  "latest"
],
"id": 1
}'  http://localhost:8545

The proxy logs:

[2024-06-03T20:36:04.575Z] {"method":"eth_getCode","params":["0x0000000000000000000000000000000000000000","0x13161e2"],"id":35,"jsonrpc":"2.0"}
[2024-06-03T20:36:04.580Z] {"method":"eth_getBalance","params":["0x0000000000000000000000000000000000000000","0x13161e2"],"id":33,"jsonrpc":"2.0"}
[2024-06-03T20:36:04.584Z] {"method":"eth_getTransactionCount","params":["0x0000000000000000000000000000000000000000","0x13161e2"],"id":34,"jsonrpc":"2.0"}
[2024-06-03T20:36:04.691Z] {"method":"eth_getTransactionCount","params":["0xc02aaa39b223fe8d0a0e5c4f27ead9083c756cc2","0x13161e2"],"id":37,"jsonrpc":"2.0"}
[2024-06-03T20:36:04.692Z] {"method":"eth_getCode","params":["0xc02aaa39b223fe8d0a0e5c4f27ead9083c756cc2","0x13161e2"],"id":38,"jsonrpc":"2.0"}
[2024-06-03T20:36:04.692Z] {"method":"eth_getBalance","params":["0xc02aaa39b223fe8d0a0e5c4f27ead9083c756cc2","0x13161e2"],"id":36,"jsonrpc":"2.0"}
[2024-06-03T20:36:04.735Z] {"method":"eth_getStorageAt","params":["0xc02aaa39b223fe8d0a0e5c4f27ead9083c756cc2","0x1","0x13161e2"],"id":39,"jsonrpc":"2.0"}

_This output is expected, as it's our first eth_call after clearing our local cache._

  1. Send eth_call request to WETH contract symbol (second call) 
    curl -X POST   --header "Content-Type: application/json"   --data '{
"jsonrpc": "2.0",
"method": "eth_call",
"params": [                                                                                      
  {
    "to": "0xC02aaA39b223FE8D0A0e5C4F27ead9083C756Cc2",
    "data": "0x95d89b41"
  },
  "latest"
],
"id": 1
}'  http://localhost:8545

The proxy did not log any requests - cache is working as expected!

  1. Send anvil_reset - passing in the same rpc endpoint and block number originally used to fork 
    curl -X POST   --header "Content-Type: application/json"   --data '{
"jsonrpc": "2.0",
"method": "anvil_reset",
"params": [{ "forking": { "jsonRpcUrl": "http://localhost:3000", "blockNumber": "20013538" } } ],
"id": 1
}'  http://localhost:8545

The proxy logs:

[2024-06-03T20:36:18.870Z] {"method":"eth_getBlockByNumber","params":["0x13161e2",false],"id":0,"jsonrpc":"2.0"}
[2024-06-03T20:36:19.005Z] {"method":"eth_getBlockByNumber","params":["0x13161e2",true],"id":1,"jsonrpc":"2.0"}
  1. Send eth_call request to WETH contract symbol (third call) 
    curl -X POST   --header "Content-Type: application/json"   --data '{
"jsonrpc": "2.0",
"method": "eth_call",
"params": [                                                                                      
  {
    "to": "0xC02aaA39b223FE8D0A0e5C4F27ead9083C756Cc2",
    "data": "0x95d89b41"
  },
  "latest"
],
"id": 1
}'  http://localhost:8545

The proxy logs:

[2024-06-03T20:36:25.177Z] {"method":"eth_getCode","params":["0x0000000000000000000000000000000000000000","0x13161e2"],"id":42,"jsonrpc":"2.0"}
[2024-06-03T20:36:25.181Z] {"method":"eth_getBalance","params":["0x0000000000000000000000000000000000000000","0x13161e2"],"id":40,"jsonrpc":"2.0"}
[2024-06-03T20:36:25.185Z] {"method":"eth_getTransactionCount","params":["0x0000000000000000000000000000000000000000","0x13161e2"],"id":41,"jsonrpc":"2.0"}
[2024-06-03T20:36:25.287Z] {"method":"eth_getTransactionCount","params":["0xc02aaa39b223fe8d0a0e5c4f27ead9083c756cc2","0x13161e2"],"id":44,"jsonrpc":"2.0"}
[2024-06-03T20:36:25.288Z] {"method":"eth_getCode","params":["0xc02aaa39b223fe8d0a0e5c4f27ead9083c756cc2","0x13161e2"],"id":45,"jsonrpc":"2.0"}
[2024-06-03T20:36:25.288Z] {"method":"eth_getBalance","params":["0xc02aaa39b223fe8d0a0e5c4f27ead9083c756cc2","0x13161e2"],"id":43,"jsonrpc":"2.0"}
[2024-06-03T20:36:25.353Z] {"method":"eth_getStorageAt","params":["0xc02aaa39b223fe8d0a0e5c4f27ead9083c756cc2","0x1","0x13161e2"],"id":46,"jsonrpc":"2.0"}

I would expect that resetting a forked Anvil server to the same rpc endpoint and block number that was used to originally launch the fork, Anvil would continue to used the cached data fetched before calling anvil_reset. (I understand that resetting a fork to a different combination of rpc endpoint / block number would logically flush the local cache).

I'm using Anvil as part of a test harness that forks a upstream server when testing a sdk. Each integration test involves a little setup and modifies state - so I call anvil_reset between each test. If it's possible to re-use the fetched upstream data between tests it would definitely give my tests a performance boost. :-)

cstoneham commented 3 months ago

I think that's how hardhat works actually, they cache the state in a directory as JSON files. +1 that it would be amazing if we could get the same caching w/Anvil.

I'm in a similar position as @mjpowersjr where I'm building out a test environment w/Anvil so the performance wins would be greatly appreciated.

grandizzy commented 1 month ago

@mjpowersjr @cstoneham can't you use evm_snapshot / evm_revert instead anvil_reset for your scenarios?

zzmp commented 1 month ago

afaict and from local testing, evm_snapshot/evm_revert clears the cached fetched data, same as anvil_reset. have you seen different result?

This seems like a big differentiator between anvil and hardhat. Is this on the roadmap at this point?