Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
2 tasks done
Tracked by #8269
cstoneham opened this issue May 21, 2024 · 13 comments
Open
2 tasks done
Tracked by #8269
Labels
C-anvil Command: anvil T-bug Type: bug T-to-investigate Type: to investigate

Comments

@cstoneham
Copy link

cstoneham commented May 21, 2024

Component

Anvil

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

  • Foundry
  • Foundryup

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
  1. Call anvil_reset:
cast rpc --rpc-url http://localhost:8550/ anvil_reset '{"jsonRpcUrl": $MAINNET_RPC_URL,"blockNumber":19916015}'
  1. 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
  1. Notice that this hangs for 30+ seconds.
  2. Notice that if you stop this call and fire the same one again, it's fast.
@cstoneham cstoneham added the T-bug Type: bug label May 21, 2024
@cstoneham cstoneham changed the title Contract call after anvil_reset on a fork hangs indefinitely Contract call extremely slow after anvil_reset on a fork hangs May 21, 2024
@dqian
Copy link

dqian commented May 21, 2024

seeing this too

@WardenJakx
Copy link
Contributor

+1. very annoying plz fix

@DaniPopes
Copy link
Member

cc @mattsse

@mattsse
Copy link
Member

mattsse commented May 29, 2024

checking, sorry about the delay

@mattsse
Copy link
Member

mattsse commented May 30, 2024

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
Copy link

mjpowersjr commented Jun 3, 2024

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

@mattsse
Copy link
Member

mattsse commented Jun 3, 2024

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
Copy link
Author

cstoneham commented Jun 3, 2024

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
Copy link
Member

mattsse commented Jun 3, 2024

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
Copy link

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
  1. 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
Copy link
Author

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.

@zerosnacks zerosnacks added the C-anvil Command: anvil label Jun 27, 2024
@zerosnacks zerosnacks changed the title Contract call extremely slow after anvil_reset on a fork hangs bug(anvil): contract call extremely slow after anvil_reset on a fork hangs Jul 16, 2024
@zerosnacks zerosnacks added the T-to-investigate Type: to investigate label Jul 16, 2024
@grandizzy
Copy link
Collaborator

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

@zzmp
Copy link

zzmp commented Jul 25, 2024

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?

@zerosnacks zerosnacks added this to the v1.0.0 milestone Jul 26, 2024
@zerosnacks zerosnacks removed this from the v1.0.0 milestone Oct 22, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
C-anvil Command: anvil T-bug Type: bug T-to-investigate Type: to investigate
Projects
Status: Todo
Development

No branches or pull requests

9 participants