Implement Vrank metrics and logs

[ian0371]

Proposed changes

We collect all commits between two preprepares.

collect      start                                     stop
---------------|--------------|------------|-------------|
state:     preprepared      prepared     commit      preprepared

Existing implementation discards "late commit messages" that we receive after turning into the "commit" state.
To receive those commit messages, we must define an independent data structure, hence Vrank struct.

Metrics

• target: the time elapsed between the preprepared time (start time) and the followings:
  • the first commit arrival time
  • the [2f+1]-th commit arrival time
  • the average arrival times from the first commit to the [2f+1]-th commit
  • the last commit before stop

See further comments for an examplery metric output.

Logs

We assess each validator in the committee by how fast it sent its commit message:

• early: received before threshold
• late: received after threshold
• not received

The threshold that divides early and late commits is defined as follows:

• threshold = min( [2f+1]-th commit arrival time, preprepared time + 300ms )

This is logged as bitmap.
In addition, the arrival times of late commits are logged as late.

See further comments for log interpretation.

Types of changes

Please put an x in the boxes related to your change.

• Bugfix
• New feature or enhancement
• Others

Checklist

Put an x in the boxes that apply. You can also fill these out after creating the PR. If you're unsure about any of them, don't hesitate to ask. We're here to help! This is simply a reminder of what we are going to look for before merging your code.

• I have read the CONTRIBUTING GUIDELINES doc
• I have signed the CLA
• Lint and unit tests pass locally with my changes ($ make test)
• I have added tests that prove my fix is effective or that my feature works
• I have added necessary documentation (if appropriate)
• Any dependent changes have been merged and published in downstream modules

Related issues

• Please leave the issue numbers or links related to this PR here.

Further comments

Example metric output:

klaytn_vrank_avg_commit_within_quorum 1.944361e+06
klaytn_vrank_first_commit 1.520958e+06
klaytn_vrank_last_commit 6.891958e+06
klaytn_vrank_quorum_commit 2.290458e+06

Example log:

INFO[07/21,22:12:16 +09] [25|consensus/istanbul/core/vrank.go:118]  VRank     bitmap=01 late=[2]

It means that the fourth validator in the committee is late, and that its arrival time is 2ms.
Interpretation of bitmap: 01 => 0x01 => 0b00_00_00_01 => fourth 2-bit is vrankArrivedLate, others are vrankArrivedEarly.

Q. Why compress the log?
A. We wanted to reduce the log size as much as possible and reduce verbosity. If the threshold is [2f+1]-th commit arrival time, the size of late is f. If the threshold is preprepared time + 300ms, the size of late is more than f.

Q. Why not use existing variables such as consensusTimestamp, or currentView?
A. They are reset at startNewRound(), which is called almost immediately after turning into the "commit" state.

Q. Why threshold is 300ms?
A. In an ideal network, a validator is supposed to receive 2f+1 number of commits within 300ms.