Analyzing Block Process in RSK Logs

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):

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