core: standardize slow block JSON output for cross-client metrics

[CPerezz]

Implement standardized JSON format for slow block logging to enable cross-client performance analysis and protocol research.

This change is part of the Cross-Client Execution Metrics initiative proposed by Gary Rong: https://hackmd.io/dg7rizTyTXuCf2LSa2LsyQ

The standardized metrics enabled data-driven analysis like the EIP-7907 research: https://ethresear.ch/t/data-driven-analysis-on-eip-7907/23850

JSON format includes:

• block: number, hash, gas_used, tx_count
• timing: execution_ms, total_ms
• throughput: mgas_per_sec
• state_reads: accounts, storage_slots, bytecodes, code_bytes
• state_writes: accounts, storage_slots, bytecodes
• cache: account/storage/code hits, misses, hit_rate

This should come after merging #33522

[rjl493456442]

We can definitely track how many contract codes have been written within the state transition.

Unfortunately the code is mutable now with 7702 :(

[CPerezz]

9e90070 should address this.

[rjl493456442]

Please rebase and resolve the conflicts

[CPerezz]

Please rebase and resolve the conflicts

Done! @rjl493456442

[rjl493456442]

First of all, the mutation counter may be inaccurate due to the potential inner callframe reverts, e.g., the call frame may fail after the code deployement.

We have two options: (a) explicitly revert the statistic (b) measure the code changes at the end of the state transition.

What's more, it's theoretical possible for multiple contracts deploying the same code within the same block. In this case, we are only interested on the de-duplicated data?

[rjl493456442]

Additionally, even after the de-duplication, the dirty contract code may already exists in the DB. In han's post, it turns out there are 90% duplicated code deployment.

I am not so sure how useful the measurements against the code mutations at this moment.

[CPerezz]

cb3122b. should address the first one

As for the seconf comment, we remove the metric if you feel is not useful.

[rjl493456442]

Example output:

WARN [01-28|08:27:13.305] {"level":"warn","msg":"Slow block","block":{"number":24332139,"hash":"0x715e77980e31b8971196f3ccd2b8228c23a6aad6aa799200f754e796ab5d4ca7","gas_used":34749600,"tx_count":288},"timing":{"execution_ms":65.407963,"state_read_ms":4.475989,"state_hash_ms":5.960876,"commit_ms":9.845399,"total_ms":88.240873},"throughput":{"mgas_per_sec":393.8039008294943},"state_reads":{"accounts":1083,"storage_slots":2177,"code":403,"code_bytes":2479332},"state_writes":{"accounts":697,"accounts_deleted":0,"storage_slots":766,"storage_slots_deleted":32,"code":26,"code_bytes":4298},"cache":{"account":{"hits":1067,"misses":16,"hit_rate":98.52262234533703},"storage":{"hits":2132,"misses":45,"hit_rate":97.9329352319706},"code":{"hits":402,"misses":1,"hit_rate":99.75186104218362,"hit_bytes":2457556,"miss_bytes":21776}}}

{
  "level": "warn",
  "msg": "Slow block",
  "block": {
    "number": 24332139,
    "hash": "0x715e77980e31b8971196f3ccd2b8228c23a6aad6aa799200f754e796ab5d4ca7",
    "gas_used": 34749600,
    "tx_count": 288
  },
  "timing": {
    "execution_ms": 65.407963,
    "state_read_ms": 4.475989,
    "state_hash_ms": 5.960876,
    "commit_ms": 9.845399,
    "total_ms": 88.240873
  },
  "throughput": {
    "mgas_per_sec": 393.8039008294943
  },
  "state_reads": {
    "accounts": 1083,
    "storage_slots": 2177,
    "code": 403,
    "code_bytes": 2479332
  },
  "state_writes": {
    "accounts": 697,
    "accounts_deleted": 0,
    "storage_slots": 766,
    "storage_slots_deleted": 32,
    "code": 26,
    "code_bytes": 4298
  },
  "cache": {
    "account": {
      "hits": 1067,
      "misses": 16,
      "hit_rate": 98.52262234533703
    },
    "storage": {
      "hits": 2132,
      "misses": 45,
      "hit_rate": 97.9329352319706
    },
    "code": {
      "hits": 402,
      "misses": 1,
      "hit_rate": 99.75186104218362,
      "hit_bytes": 2457556,
      "miss_bytes": 21776
    }
  }
}