Analyzing Block Process in RSK Logs

4 min readApr 5, 2020

As you know, I do many personal experiments using RSK Ethereum-like node, in local mode or synchronized with a network. Read my post Running RSK Node. In that post I describe the file logs, where they are, and the log configuration using logback. I also wrote:

The topics I changed to TRACE level are: execute, blockvalidator, blockexecutor, blockchain, messagehandler, blockchain, blockprocessor.

Well, I selected these topics when I want to analyze the block execution. Because the block execution data could be intermixed with other log lines, I wrote a simple nodejs script blocksdata.js (part of my RSK utils scripts personal project) to extract only those topics. It is so simple that it could be replaced by a simple grep command.

An example

These lines show a typical block execution (a block with only one transactions):

// Start and Validation2020-03-27-15:19:15.408 TRACE [blockchain]  Try connect block hash: c259f0, number: 722119
2020-03-27-15:19:15.408 TRACE [blockchain]  Start try connect
2020-03-27-15:19:15.408 TRACE [blockchain]  get current state
2020-03-27-15:19:15.408 DEBUG [blockvalidator]  Validating block c259f0 722119
2020-03-27-15:19:15.408 DEBUG [blockvalidator]  Validation rule BlockTxsFieldsValidationRule
2020-03-27-15:19:15.408 DEBUG [blockvalidator]  Validation rule BlockTxsValidationRule
2020-03-27-15:19:15.408 DEBUG [blockvalidator]  Validation rule PrevMinGasPriceRule
2020-03-27-15:19:15.408 DEBUG [blockvalidator]  Validation rule BlockParentNumberRule
2020-03-27-15:19:15.408 DEBUG [blockvalidator]  Validation rule BlockDifficultyRule
2020-03-27-15:19:15.408 DEBUG [blockvalidator]  Validation rule BlockParentGasLimitRule
2020-03-27-15:19:15.408 DEBUG [blockvalidator]  Validating block c259f0 722119
2020-03-27-15:19:15.408 DEBUG [blockvalidator]  Validation rule TxsMinGasPriceRule
2020-03-27-15:19:15.408 DEBUG [blockvalidator]  Validation rule BlockUnclesValidationRule
2020-03-27-15:19:15.409 DEBUG [blockvalidator]  Validating header 46facc 722117
2020-03-27-15:19:15.409 DEBUG [blockvalidator]  Validation rule ProofOfWorkRule
2020-03-27-15:19:15.409 DEBUG [blockvalidator]  Validation rule ForkDetectionDataRule
2020-03-27-15:19:15.423 DEBUG [blockvalidator]  Validation rule BlockTimeStampValidationRule
2020-03-27-15:19:15.423 DEBUG [blockvalidator]  Validation rule ValidGasUsedRule
2020-03-27-15:19:15.423 DEBUG [blockvalidator]  Validating header 46facc 722117
2020-03-27-15:19:15.423 DEBUG [blockvalidator]  Validation rule PrevMinGasPriceRule
2020-03-27-15:19:15.423 DEBUG [blockvalidator]  Validation rule BlockParentNumberRule
2020-03-27-15:19:15.423 DEBUG [blockvalidator]  Validation rule BlockTimeStampValidationRule
2020-03-27-15:19:15.423 DEBUG [blockvalidator]  Validation rule BlockDifficultyRule
2020-03-27-15:19:15.423 DEBUG [blockvalidator]  Validation rule BlockParentGasLimitRule
2020-03-27-15:19:15.423 DEBUG [blockvalidator]  Validation rule BlockRootValidationRule
2020-03-27-15:19:15.424 DEBUG [blockvalidator]  Validation rule ProofOfWorkRule
2020-03-27-15:19:15.424 DEBUG [blockvalidator]  Validation rule RemascValidationRule
2020-03-27-15:19:15.424 DEBUG [blockvalidator]  Validation rule BlockTimeStampValidationRule
2020-03-27-15:19:15.424 DEBUG [blockvalidator]  Validation rule GasLimitRule
2020-03-27-15:19:15.424 DEBUG [blockvalidator]  Validation rule ExtraDataRule
2020-03-27-15:19:15.424 DEBUG [blockvalidator]  Validation rule ForkDetectionDataRule// Execution2020-03-27-15:19:15.439 TRACE [blockchain]  execute start
2020-03-27-15:19:15.439 TRACE [blockexecutor]  applyBlock: block: [722119] tx.list: [1]
2020-03-27-15:19:15.439 TRACE [blockexecutor]  apply block: [722119] tx: [1]
2020-03-27-15:19:15.439 TRACE [execute]  Execute transaction 722118 21a27d0f152475cd0a6f0074f2e2b75510ec1a93e6f78973efff097341eb2b41
2020-03-27-15:19:15.439 TRACE [execute]  Paying: txGasCost: [0], gasPrice: [0], gasLimit: [0]
2020-03-27-15:19:15.439 TRACE [execute]  Call transaction 722118 21a27d0f152475cd0a6f0074f2e2b75510ec1a93e6f78973efff097341eb2b41
2020-03-27-15:19:15.441 TRACE [execute]  Finalize transaction 722118 21a27d0f152475cd0a6f0074f2e2b75510ec1a93e6f78973efff097341eb2b41
2020-03-27-15:19:15.441 TRACE [execute]  Building transaction execution summary
2020-03-27-15:19:15.441 TRACE [execute]  Pay total refund to sender: [0000000000000000000000000000000000000000], refund val: [0]
2020-03-27-15:19:15.441 TRACE [execute]  Adding fee to remasc contract account
2020-03-27-15:19:15.441 TRACE [execute]  Processing result
2020-03-27-15:19:15.441 TRACE [execute]  tx listener done
2020-03-27-15:19:15.441 TRACE [execute]  tx finalization done
2020-03-27-15:19:15.441 TRACE [blockexecutor]  tx executed
2020-03-27-15:19:15.441 TRACE [blockexecutor]  track commit
2020-03-27-15:19:15.441 TRACE [blockexecutor]  block: [722119] executed tx: [21a27d0f152475cd0a6f0074f2e2b75510ec1a93e6f78973efff097341eb2b41]
2020-03-27-15:19:15.441 TRACE [blockexecutor]  tx[1].receipt
2020-03-27-15:19:15.441 TRACE [blockexecutor]  tx done// End process2020-03-27-15:19:15.446 TRACE [blockchain]  execute done
2020-03-27-15:19:15.446 TRACE [blockchain]  validate done
2020-03-27-15:19:15.446 TRACE [blockchain]  block: num: [722119] hash: [c259f0], executed after: [7066499]nano
2020-03-27-15:19:15.446 TRACE [blockchain]  TD: updated to 50844448133307692023
2020-03-27-15:19:15.446 TRACE [blockchain]  Start switchToBlockChain
2020-03-27-15:19:15.448 TRACE [blockchain]  Start saveReceipts
2020-03-27-15:19:15.451 TRACE [blockchain]  Start processBest
2020-03-27-15:19:15.451 TRACE [blockchain]  Start onBestBlock
2020-03-27-15:19:15.451 TRACE [blockchain]  Start onBlock
2020-03-27-15:19:15.451 TRACE [blockchain]  Start flushData
2020-03-27-15:19:15.451 TRACE [blockchain]  Better block 722119 c259f0
2020-03-27-15:19:15.451 DEBUG [blockchain]  block added to the blockChain: index: [722119]
2020-03-27-15:19:15.451 INFO [blockchain]  block: num: [722119] hash: [c259f0], processed after: [42973500]nano, result IMPORTED_BEST

The last line gives us the total time (in nanoseconds) of the block process. This is only an example, and the times depends a lot of the execution machine you use for experiments.

I added some comments to clarify three sections. I usually divide the analysis into three parts:

Validation: before execution many validations rules are applied, in order to not execute invalid blocks.
Execution: execute the list of transactions included into the block
Save: final validation (i.e. the calculate state root hash is equal to the hash that came into the block header), and saving results (accounts and storage data, save receipts, some block information like its total difficulty)

In the above example are some additional logs that are not yet included in the released versions, related to block validation that I added to my experiment, to have a better description of which rules are invokes. I plan to make a pull request with those additional lines.

Although the analysis could be do using other tools, like performance metrics in the code, the logs are good to:

Have more context, i.e. the number of transactions or the uncles that a block have, and then, you can analyze the relations between process time and that information
You can analyze a remote machine execution AFTER the process, without having to have performance metric previously activated

I plan to write a post to analyze the process of a incoming transaction.

Angel “Java” Lopez

Analyzing Block Process in RSK Logs

An example

Written by Angel Java Lopez