21 KiB
Testing of new releases of Erigon should ideally include these checks.
Incremental Sync
This check requires having the Erigon database synced previously. Lets assume (for command line examples) it is in the directory ~/mainnet/erigon/chaindata.
Using git pull or git checkout, update the code to the version that is to be released (or very close to it). Then, build erigon executable:
make erigon
Now run Erigon as usually, to try to catch up with the mainnet
./build/bin/erigon --datadir ~/mainnet
It is useful to pipe the output into a text file for later inspection, for example:
./build/bin/erigon --datadir ~/mainnet 2>&1 | tee erigon.log
Wait until Erigon catches up with the network. This can be determined by looking at the output and seeing that sync cycles usually go through just a single block, and that block is recent (can be verified on etherscan.io, for example). For example, output may look like this:
INFO [03-24|13:41:14.101] [1/14 Headers] Imported new block headers count=1 elapsed=1.621ms number=12101885 hash="8fe088…b877ee"
INFO [03-24|13:41:14.213] [3/14 Bodies] Downloading block bodies count=1
INFO [03-24|13:41:17.789] [3/14 Bodies] Imported new chain segment blocks=1 txs=175 elapsed=1.045ms number=12101885 hash="8fe088…b877ee"
INFO [03-24|13:41:17.793] [4/14 Senders] Started from=12101884 to=12101885
INFO [03-24|13:41:17.793] [4/14 Senders] Read canonical hashes amount=1
INFO [03-24|13:41:17.829] [5/14 Execution] Blocks execution from=12101884 to=12101885
INFO [03-24|13:41:17.905] [5/14 Execution] Completed on block=12101885
INFO [03-24|13:41:17.905] [6/14 HashState] Promoting plain state from=12101884 to=12101885
INFO [03-24|13:41:17.905] [6/14 HashState] Incremental promotion started from=12101884 to=12101885 codes=true csbucket=PLAIN-ACS
INFO [03-24|13:41:17.912] [6/14 HashState] Incremental promotion started from=12101884 to=12101885 codes=false csbucket=PLAIN-ACS
INFO [03-24|13:41:17.935] [6/14 HashState] Incremental promotion started from=12101884 to=12101885 codes=false csbucket=PLAIN-SCS
INFO [03-24|13:41:17.961] [7/14 IntermediateHashes] Generating intermediate hashes from=12101884 to=12101885
INFO [03-24|13:41:18.064] [7/14 IntermediateHashes] Trie root hash=0x7937f8c3881e27e1696a36b0a5f84e83792cff7966e97b68059442dadd404368 in=99.621957ms
INFO [03-24|13:41:18.162] [11/14 CallTraces] disabled. Work In Progress
INFO [03-24|13:41:18.225] [13/14 TxPool] Read canonical hashes hashes=1
INFO [03-24|13:41:18.227] [13/14 TxPool] Transaction stats pending=3909 queued=1036
INFO [03-24|13:41:18.227] [14/14 Finish] Update current block for the RPC API to=12101885
INFO [03-24|13:41:18.227] Memory alloc=572.23MiB sys=757.02MiB
INFO [03-24|13:41:18.227] Timings Headers=468.891825ms BlockHashes=1.652309ms Bodies=3.579430574s Bodies="619.203µs" Senders=36.435667ms Execution=75.538895ms HashState=56.27559ms IntermediateHashes=113.255714ms AccountHistoryIndex=29.369386ms StorageHistoryIndex=37.829112ms LogIndex=20.112169ms TxLookup=48.53473ms TxPool=16.63633ms Finish="37.623µs"
INFO [03-24|13:41:18.227] Tables PLAIN-CST2=10.66GiB PLAIN-SCS=101.86GiB eth_tx=229.75GiB hAT=25.38GiB hST=70.64GiB hashed_accounts=11.74GiB l=81.02GiB log=227.30GiB log_topic_index=18.76GiB r=10.05GiB txSenders=29.52GiB freelist=47.69MiB
INFO [03-24|13:41:20.391] Commit cycle in=2.163782297s
Here we see that the sync cycle went through all the stages for a single block 12101885.
After that, it is useful to wait more until an Unwind is encoutered and check that Erigon handled it without errors. Usually, errors occur at the stage
[7/14 IntermediateHashes] and manifest in the wrong trie root. Here is an example of processing an unwind without errors (look for the word "Unwind" in the log):
INFO [03-24|13:41:34.318] [1/14 Headers] Imported new block headers count=2 elapsed=1.855ms number=12101886 hash="20d688…fdaaa6" reorg=true forkBlockNumber=12101884
INFO [03-24|13:41:34.318] UnwindTo block=12101884
INFO [03-24|13:41:34.332] Unwinding... stage=TxLookup
INFO [03-24|13:41:34.341] Unwinding... stage=LogIndex
INFO [03-24|13:41:34.371] Unwinding... stage=StorageHistoryIndex
INFO [03-24|13:41:34.428] Unwinding... stage=AccountHistoryIndex
INFO [03-24|13:41:34.462] Unwinding... stage=HashState
INFO [03-24|13:41:34.462] [6/14 HashState] Unwinding started from=12101885 to=12101884 storage=false codes=true
INFO [03-24|13:41:34.464] [6/14 HashState] Unwinding started from=12101885 to=12101884 storage=false codes=false
INFO [03-24|13:41:34.467] [6/14 HashState] Unwinding started from=12101885 to=12101884 storage=true codes=false
INFO [03-24|13:41:34.472] Unwinding... stage=IntermediateHashes
INFO [03-24|13:41:34.472] [7/14 IntermediateHashes] Unwinding of trie hashes from=12101885 to=12101884 csbucket=PLAIN-ACS
INFO [03-24|13:41:34.474] [7/14 IntermediateHashes] Unwinding of trie hashes from=12101885 to=12101884 csbucket=PLAIN-SCS
INFO [03-24|13:41:34.511] [7/14 IntermediateHashes] Trie root hash=0xa06f932426150e3a8c78607fc873bb15259c57fc2a1b8136ed4065073b9ee6b6 in=33.835208ms
INFO [03-24|13:41:34.518] Unwinding... stage=Execution
INFO [03-24|13:41:34.518] [5/14 Execution] Unwind Execution from=12101885 to=12101884
INFO [03-24|13:41:34.522] Unwinding... stage=Senders
INFO [03-24|13:41:34.522] Unwinding... stage=TxPool
INFO [03-24|13:41:34.537] [13/14 TxPool] Read canonical hashes hashes=1
INFO [03-24|13:41:34.537] [13/14 TxPool] Injecting txs into the pool number=0
INFO [03-24|13:41:34.537] [13/14 TxPool] Injection complete
INFO [03-24|13:41:34.538] [13/14 TxPool] Transaction stats pending=4090 queued=1023
INFO [03-24|13:41:34.538] Commit cycle
INFO [03-24|13:41:36.643] Unwinding... stage=Bodies
INFO [03-24|13:41:36.645] Unwinding... stage=BlockHashes
INFO [03-24|13:41:36.647] Unwinding... stage=Headers
INFO [03-24|13:41:36.727] [3/14 Bodies] Downloading block bodies count=2
INFO [03-24|13:41:36.769] [3/14 Bodies] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=45.70KiB throttle=1434
INFO [03-24|13:41:36.772] [3/14 Bodies] Imported new chain segment blocks=2 txs=408 elapsed=2.032ms number=12101886 hash="20d688…fdaaa6"
INFO [03-24|13:41:36.776] [4/14 Senders] Started from=12101884 to=12101886
INFO [03-24|13:41:36.776] [4/14 Senders] Read canonical hashes amount=2
INFO [03-24|13:41:36.809] [5/14 Execution] Blocks execution from=12101884 to=12101886
INFO [03-24|13:41:36.911] [5/14 Execution] Completed on block=12101886
INFO [03-24|13:41:36.912] [6/14 HashState] Promoting plain state from=12101884 to=12101886
INFO [03-24|13:41:36.912] [6/14 HashState] Incremental promotion started from=12101884 to=12101886 codes=true csbucket=PLAIN-ACS
INFO [03-24|13:41:36.917] [6/14 HashState] Incremental promotion started from=12101884 to=12101886 codes=false csbucket=PLAIN-ACS
INFO [03-24|13:41:36.946] [6/14 HashState] Incremental promotion started from=12101884 to=12101886 codes=false csbucket=PLAIN-SCS
INFO [03-24|13:41:36.972] [7/14 IntermediateHashes] Generating intermediate hashes from=12101884 to=12101886
INFO [03-24|13:41:37.100] [7/14 IntermediateHashes] Trie root hash=0x38aa726427894df05393eb41779f3f74e69dd68553ad301aaf9a9fdb2e60d53d in=120.544291ms
INFO [03-24|13:41:37.228] [11/14 CallTraces] disabled. Work In Progress
ERROR[03-24|13:41:37.323] Demoting invalidated transaction hash="7f686f…05d457"
ERROR[03-24|13:41:37.343] Demoting invalidated transaction hash="e809f5…81245e"
INFO [03-24|13:41:37.347] [13/14 TxPool] Read canonical hashes hashes=2
INFO [03-24|13:41:37.353] [13/14 TxPool] Transaction stats pending=3885 queued=1039
INFO [03-24|13:41:37.353] [14/14 Finish] Update current block for the RPC API to=12101886
INFO [03-24|13:41:37.353] Memory alloc=314.65MiB sys=757.02MiB
INFO [03-24|13:41:37.353] Timings (first 50) Headers=72.394932ms Unwind TxLookup=9.141155ms Unwind LogIndex=29.275311ms Unwind StorageHistoryIndex=57.562267ms Unwind AccountHistoryIndex=33.71906ms Unwind HashState=10.102642ms Unwind IntermediateHashes=46.475857ms Unwind Execution=3.449326ms Unwind Senders="
31.255µs" Unwind TxPool=16.378952ms Unwind Bodies=1.81026ms Unwind BlockHashes=1.636441ms Unwind Headers=1.883299ms Headers=77.905179ms BlockHashes="138.005µs" Bodies=48.816311ms Bodies="551.032µs" Senders=33.397734ms Execution=102.095383ms HashState=60.080073ms IntermediateHashes=142.317001ms AccountHistoryIndex=45.261
032ms StorageHistoryIndex=42.51298ms LogIndex=26.347729ms TxLookup=78.822422ms
INFO [03-24|13:41:37.353] Tables PLAIN-CST2=10.66GiB PLAIN-SCS=101.86GiB eth_tx=229.75GiB hAT=25.38GiB hST=70.64GiB hashed_accounts=11.74GiB l=81.02GiB log=227.30GiB log_topic_index=18.76GiB r=10.05GiB txSenders=29.52GiB freelist=47.69MiB
INFO [03-24|13:41:39.443] Commit cycle in=2.090509095s
In this example, the Unwind starts with the stage [1/14 Headers] reporting the reorg: reorg=true
and also showing how back do we need to rewind to perform the reorg: forkBlockNumber=12101884. After that, all the stages are unwound in the "Unwinding order",
which is almost the reverse order of stages, but with some exceptions (like TxPool stage). After unwinding all the stages to the forkBlockNumber, Erigon
applies the new chain branch, in the example above it is two new blocks. In the Timings log output one can see the timings of unwinding stages as well as timings
of normal stage operation when the chain branch is applied.
Errors to ignore for now
There are couple of types of errors that are encountered during this check, which need to be ignored for now, until we handle them better or fix the underlying issues. The first error is probably a result of some data race in the code, and this code will be replaced by the new sentry/downloader design, therefore we are not keen on investigating/fixing it.
ERROR[03-24|13:49:53.343] Ethereum peer removal failed peer=bfa4a38e err="peer not registered"
The second error happens during the unwinding the TxPool stage. It has been reported in this issue: https://github.com/ledgerwatch/erigon/issues/848
ERROR[08-01|14:30:38.297] Demoting invalidated transaction hash="6ee8a8…92bf22"
ERROR[08-01|14:30:38.299] Demoting invalidated transaction hash="7abab0…eccbed"
ERROR[08-01|14:30:38.299] Demoting invalidated transaction hash="de485c…dcd575"
ERROR[08-01|14:30:38.299] Demoting invalidated transaction hash="3d33a1…bc8f61"
ERROR[08-01|14:30:38.299] Demoting invalidated transaction hash="b11d49…481e7c"
ERROR[08-01|14:30:38.299] Demoting invalidated transaction hash="832d13…076faa"
ERROR[08-01|14:30:38.299] Demoting invalidated transaction hash="859191…0366c0"
ERROR[08-01|14:30:38.299] Demoting invalidated transaction hash="25ee67…e73153"
this is also likely to disappered after the introduction of new downloader/sentry design
Assessing relative performance of sync
From one release to another, there should not be noticeable degradation in the sync performance, unless there are clear reasons for it. These reasons may include raised gas limit on Ethereum network, adding new table to the database, etc.
In order to assess relative performance of the sync compared to the previous release, one needs to capture these log lines from the log files (but only after the sync has "stabilised", meaning it is over few initial long sync cycles:
INFO [03-24|13:41:18.227] Timings Headers=468.891825ms BlockHashes=1.652309ms Bodies=3.579430574s Bodies="619.203µs" Senders=36.435667ms Execution=75.538895ms HashState=56.27559ms IntermediateHashes=113.255714ms AccountHistoryIndex=29.369386ms StorageHistoryIndex=37.829112ms LogIndex=20.112169ms TxLookup=48.53473ms TxPool=16.63633ms Finish="37.623µs"
The line above shows how much time each stage of processing takes.
INFO [03-24|13:41:20.391] Commit cycle in=2.163782297s
The line above shows how long was commit cycle. We saw in the past that after some changes the commit time dramatically increases, and these regressions need to be investigaged. We expect "commit cycle" on Linux with NVMe drive to usually take less than a second. For other operating systems and devices the typical time may vary, but it should significantly increase from one release to another. Perhaps we need to log some extra information in the log to make it easier for the tester to filter out the log statements after the sync "stabilised".
Fresh sync (only when there are serious changes in the data model)
The way to perform this check is almost the same as the Incremental Sync, but starting with an empty directory for the database. This process takes much longer (can take 2-3 days on good hardware), that is why it should be done perhaps weekly.
Executing historical transactions
Having up-to-date database, and having shut down the Erigon node (it will work without shutting down, but it will lead to bloating of the database file), this command can be executed:
./build/bin/state checkChangeSets --datadir <path to datadir> --block 11000000
Please note the difference in notation when referring to the database. Erigon command uses --datadir which points to ~mainnet, and it looks for the
actual database directory under erigon/chaindata, but checkChangeSets need to be given slightly different path, pointing directly to the database directory.
Parameter --block is used to specify from which historical block the execution needs to start.
Normally, this command reports the progress after every 1000 blocks, and if there are no errors after few thousand blocks, this check can be regarded as complete. We might add another option to this command to specify at which block number to stop, so that this check can be automated.
JSON RPC comparative tests
These tests have been originally created to compare the responses that RPC daemon gives to various JSON RPC queries with go-ethereum and OpenEthereum.
However, such tests require access to archive nodes of go-ethereum or OpenEthereum, and those require a long time to set up. Therefore, if we make
assumption that the previous release of Erigon worked correctly, we can compare behaviour of the new release compared to the previous one.
To set this up, imagine that we have two computer, on the network addresses 192.168.1.1 (previous release) and 192.168.1.2 (new release).
On the first computer, we launch Erigon:
git checkout PREV_RELEASE_TAG
git pull
make erigon
./build/bin/erigon --datadir ~/mainnet --private.api.addr 192.168.1.1:9090
And in another terminal window (or in other way to launch separate process), RPC daemon connected to it (it can also be launched on a different computer)
git checkout PREV_RELEASE_TAG
git pull
make rpcdaemon
./build/bin/rpcdaemon --private.api.addr 192.168.1.1:9090 --http.addr 192.168.1.1 --http.port 8545 --http.api eth,debug,trace
Note that if Erigon and RPC daemon are running on the same computer, they can also communicate via loopback (localhost, 127.0.0.1) interface. To
make this happen, pass --private.api.addr localhost:9090 or --private.api.addr 127.0.0.1:9090 to both Erigon and RPC daemon. Also note that
choice of the port 9090 is arbitrary, it can be any port free port number, as long as the value matches in Erigon and RPC daemon.
On the second computer (or on the same computer, but using different directories and port numbers), the same combination of processes is launched,
but from the master branch or the tag that is being tested:
git checkout master
git pull
make erigon
./build/bin/erigon --datadir ~/mainnet --private.api.addr 192.168.1.2:9090
git checkout master
git pull
make rpcdaemon
./build/bin/rpcdaemon --private.api.addr 192.168.1.2:9090 --http.addr 192.168.1.2 --http.port 8545 --http.api eth,debug,trace
Once both RPC daemons are running, RPC test utility can be run:
git checkout master
git pull
make rpctest
./build/bin/rpctest bench8 --erigonUrl http://192.168.1.2:8545 --gethUrl http://192.168.1.1:8545 --needCompare --blockFrom 9000000 --blockTo 9000100
In the example above, the bench8 command is used. RPC test utility has a few of such "benches". These benches automatically generate JSON RPC
requests for certain RPC methods, using hits provided by options --blockFrom and --blockTo. Currently the most useful ones are:
bench8testseth_getLogsRPC method (compatibility with go-ethereum and OpenEthereum)bench11teststrace_callRPC method (compatiblity with OpenEthereum tracing)bench12testsdebug_traceCallRPC method (compatibility with go-ethereum tracing)bench13teststrace_callManyRPC method (compability with OpenEthereum tracing)
Options --erigonUrl and --gethUrl specify HTTP endpoints that needs to be tested against each other. Despite its name, --gethUrl option does not have to
point to go-ethereum node, it can point to anything that it supposed to be "correct" for the purpose of the test (go-ethereum node, OpenEthereum node,
or Erigon RPC daemon & Erigon node built from the previous release code).
Option --needCompare triggers the comparison of JSON RPC responses. If omitted, requests to --gethUrl are not done. When comparison is turned on,
the utility stops at the first occurrence of mistmatch.
RPC test recording and replay
In order to facilitate the automation of testing, we are adding the ability to record JSON RPC requests generated by RPC test utility, and responses
received from Erigon. Once these are recorded in a file, they can be later replayed, without the need of having the second RPC daemon present.
To turn on recording, option --recordFile <filename> needs to be added. Currently, only bench8, bench11 and bench13 support recording.
Only queries and responses for which the comparison produced the match, are recorded. If --needCompare is not specified, but --recordFile is,
then all generated queries and responses are recorded. This can be used to separate the testing into 2 parts in time.
Example of recording command:
./build/bin/rpctest bench8 --erigonUrl http://192.168.1.2:8545 --gethUrl http://192.168.1.1:8545 --needCompare --blockFrom 9000000 --blockTo 9000100 --recordFile req.txt
The file format is plain text, with requests and responses are written in separate lines, and delimited by the tripple line breaks, like this:
{"jsonrpc":"2.0","method":"eth_getLogs","params":[{"fromBlock": "0x7a1200", "toBlock": "0x7a3974", "address": "0xcf8800f7cd90cbf3b7f5eb3681db88d8c686f54b", "topics": ["0x0000000000000000000000000000000000000000000000000000000000000000"]}],"id":63}
{"jsonrpc":"2.0","id":63,"result":[]}
{"jsonrpc":"2.0","method":"eth_getLogs","params":[{"fromBlock": "0x7a1200", "toBlock": "0x7a1264", "address": "0xe522dc278cf97ce026e461dca63331dc64274dec"}],"id":64}
{"jsonrpc":"2.0","id":64,"result":[{"address":"0xe522dc278cf97ce026e461dca63331dc64274dec","topics":["0xddf252ad1be2c89b69c2b068fc378daa952ba7f163c4a11628f55a4df523b3ef","0x0000000000000000000000005663028af4745308d5249de455e096f6eac12635","0x000000000000000000000000c41e18a3de27615492b8a6927ddf2735f12ed88f"],"data":"0x000000000000000000000000000000000000000000000001403ade3e50238000","blockNumber":"0x7a1236","transactionHash":"0xc722e8133ade4d29c1221ac211ffc886d416250f0910ebfa3dd6c72f006303c2","transactionIndex":"0x60","blockHash":"0xfd36ee4392c693c4b9f8cacef0816225077b3dd565e68945ab5a248fc8fb8b29","logIndex":"0x49","removed":false},{"address":"0xe522dc278cf97ce026e461dca63331dc64274dec","topics":["0xddf252ad1be2c89b69c2b068fc378daa952ba7f163c4a11628f55a4df523b3ef","0x0000000000000000000000005663028af4745308d5249de455e096f6eac12635","0x000000000000000000000000fc10cab6a50a1ab10c56983c80cc82afc6559cf1"],"data":"0x0000000000000000000000000000000000000000000000000000000000000000","blockNumber":"0x7a1236","transactionHash":"0xc722e8133ade4d29c1221ac211ffc886d416250f0910ebfa3dd6c72f006303c2","transactionIndex":"0x60","blockHash":"0xfd36ee4392c693c4b9f8cacef0816225077b3dd565e68945ab5a248fc8fb8b29","logIndex":"0x4a","removed":false}]}
{"jsonrpc":"2.0","method":"eth_getLogs","params":[{"fromBlock": "0x7a1200", "toBlock": "0x7a3974", "address": "0xe522dc278cf97ce026e461dca63331dc64274dec", "topics": ["0x0000000000000000000000000000000000000000000000000000000000000000"]}],"id":65}
{"jsonrpc":"2.0","id":65,"result":[]}
To replay recorded queries, replay command can be used:
./build/bin/rpctest replay --erigonUrl http://192.168.1.2:8545 --recordFile req.txt