Skip to content

metrics: add metric for proposal timestamp difference#7550

Merged
williambanfield merged 1 commit intowb/proposer-based-timestampsfrom
wb/proposal-timestamp-difference
Jan 26, 2022
Merged

metrics: add metric for proposal timestamp difference#7550
williambanfield merged 1 commit intowb/proposer-based-timestampsfrom
wb/proposal-timestamp-difference

Conversation

@williambanfield
Copy link
Contributor

@williambanfield williambanfield commented Jan 10, 2022

This change adds a histogram that tracks the difference between the proposal timestamp and the local time of the validator. This metric aims to help validators determine, in aggregate, how far away their local time is from the the times proposed by the rest of the network.

The metrics added take the following form:

# HELP tendermint_consensus_proposal_timestamp_difference Difference between the timestamp in the proposal message and the local time when the message was received. Only calculated when a new is block proposed.
# TYPE tendermint_consensus_proposal_timestamp_difference histogram
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-aZbwF1",is_timely="true",le="-15"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-aZbwF1",is_timely="true",le="-3"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-aZbwF1",is_timely="true",le="-1"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-aZbwF1",is_timely="true",le="-0.5"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-aZbwF1",is_timely="true",le="0"} 29
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-aZbwF1",is_timely="true",le="0.1"} 29
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-aZbwF1",is_timely="true",le="1"} 29
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-aZbwF1",is_timely="true",le="5"} 29
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-aZbwF1",is_timely="true",le="8"} 29
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-aZbwF1",is_timely="true",le="15"} 29
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-aZbwF1",is_timely="true",le="+Inf"} 29
tendermint_consensus_proposal_timestamp_difference_sum{chain_id="test-chain-aZbwF1",is_timely="true"} -0.231971639
tendermint_consensus_proposal_timestamp_difference_count{chain_id="test-chain-aZbwF1",is_timely="true"} 29

Will merge into wb/proposer-based-timestamps once #7415 is merged.

"message and the local time when the message was received. " +
"Only calculated when a new is block proposed.",
Buckets: []float64{-15, -8, -5, -1, -.5, -.100, 0, .5, 1, 3, 15},
Buckets: []float64{-15, -3, -1, -.5, 0, .100, 1, 5, 8, 15},

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No real objection, but is there some reason we are not symmetric about zero?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One side is much more likely to occur than the other. We expect proposal message timestamps to be in the past much more frequently than the other way around.

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That makes sense, but I'm not sure how having the bucket sizes differ helps. That said, it's fine—the only reason I mention it is that changing the bucket distribution later screws up correlations to existing timeseries from previous runs.

Copy link
Contributor Author

@williambanfield williambanfield Jan 10, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, this definitely wasn't decided using an exact science but to expand a little on my thinking: Proposal timestamps will only be ahead of your local time if your local clock is behind that of the proposer, likely because one of you is not well synced to NTP. If a message is observed 'in the future' of your clock, it seems likely to just be due to clock skew which should be pretty small, hence having a few tightly packed buckets. 15 seconds was added at the top of that range to help people differentiate between 'pretty skewed' and 'nowhere close at all'

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ideally those numbers should be derived from the consensus parameters:

d = delay
p = precision = 2 * max_clock_skew

Then have the large buckets catch how many times and how badly the proposal was not timely, while the others show how accurate d and p are.
{.., -2dp, -dp, -.5dp, -2.dp , 0, .2p, .5p, p, 2p, ..}
where dp = d + p.
Ideally nothing should show outside (-dp, p)

This said, it doesn't seem straightforward to get the consensus parameters here and also they can change through governance and then @creachadair comment comes in.
But i think we are pretty sure that p should be in the order of tens of msec. While d is a magnitude higher.
For example p = 20msec and d = 1sec seem pretty conservative.
So the buckets right of 0 seem a bit large imho, maybe ..., 0, .01, .02, 0.05, 0.1}, with everything above 0.1 sec caught in inf.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I consider this histogram in terms of what we want to learn from it. From this perspective, I can see five "regions" (intervals) of interest:

  • timestamp - receiveTime < -Precision: definitely untimely proposal
  • -Precision < timestamp - receiveTime < 0: awkward timestamp, as we shouldn't see this case occurring
  • timestamp - receiveTime < msgDelay: the typical case
  • msgDelay < timestamp - receiveTime < msgDelay + Precision: unlikely case, which observation indicates that msgDelay has possibly been underestimated.
  • timestamp - msgDelay > msgDelay + Precision: untimely proposal

I'm not sure which of this regions should have more than one bucket, to retrieve additional data, neither how to put generic numbers to these intervals.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In terms of the proposed buckets, I think that 4-5 buckets in the negative side are too much. I think that for this situation a "little" negative (say, 20ms like suggested) and more than "a little" negative (so, likely to be untimely) are enough.

For positive numbers, maybe a geometric distribution of buckets (say 0.1, 1, 10) would be ideal in a first moment. Then we should try to identify the "real" msgDelay, to somehow distinguish between something like 0.5, 1, 1.5, and 2s, assuming that most of the values will be in the 0.1-1 and 1-10 buckets.

I don't know, it is an open question also for me, I can elaborate on this better and comment here.

Copy link
Contributor Author

@williambanfield williambanfield Jan 11, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My thinking with these values was to try to create some buckets that implied an action for node operators and networks.

In the case of precision, this roughly boils down to

  1. your ntp values are slightly out of alignment but to an acceptable degree -> no change
  2. your ntp servers are quite out of alignment -> consider changing servers or examining your ntp settings
  3. your values are so far apart as to imply one or both of you are not at all sync'd to ntp -> restart your ntp daemon/debug your ntp connection.

I think overly narrow buckets don't really help operators disambiguate between these cases. Perhaps reasonable buckets for this are .025, .5 and 10?

To @creachadair's point above, I'd prefer to not resize these in the future. We can just keep both ranges, for message delay buckets: .1, .5, 1 1.5, 2, 10.
However, I have also opened #7551 to help identify the 'real' message delay on networks where applicable.

Copy link

@cason cason Jan 12, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Negative values in this measurement will only occur if:

  • The receiver's clock is ahead of the sender's clock by s
  • And the message delay is d < s

As previous commented, message delays are expected to be and order of magnitude higher than clock skews, so the situation above should be very uncommon...

Copy link
Contributor Author

@williambanfield williambanfield Jan 12, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Flipped the subtraction. Now, the 'negative' side is values where the receive time is before the proposal time, which should be quite rare.

To clarify, the metrics that I'm proposing would be:
[-10, -.5, -.025, 0, .1, .5, 1, 1.5, 2, 10]. I've updated the pull request to reflect this.

These metrics are now

# HELP tendermint_consensus_proposal_timestamp_difference Difference in seconds between the timestamp in the proposal message and the local time when the message was received. Only calculated when a new block is proposed.
# TYPE tendermint_consensus_proposal_timestamp_difference histogram
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-BCFLOg",is_timely="true",le="-10"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-BCFLOg",is_timely="true",le="-0.5"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-BCFLOg",is_timely="true",le="-0.025"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-BCFLOg",is_timely="true",le="0"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-BCFLOg",is_timely="true",le="0.1"} 21
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-BCFLOg",is_timely="true",le="0.5"} 21
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-BCFLOg",is_timely="true",le="1"} 21
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-BCFLOg",is_timely="true",le="1.5"} 21
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-BCFLOg",is_timely="true",le="2"} 21
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-BCFLOg",is_timely="true",le="10"} 21
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-BCFLOg",is_timely="true",le="+Inf"} 21
tendermint_consensus_proposal_timestamp_difference_sum{chain_id="test-chain-BCFLOg",is_timely="true"} 0.180253306
tendermint_consensus_proposal_timestamp_difference_count{chain_id="test-chain-BCFLOg",is_timely="true"} 21

Copy link
Contributor

@tychoish tychoish left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm modulo what @creachadair said, which I wish I had spotted on my own.

@ancazamfir ancazamfir force-pushed the anca/prevote_nil_untimely branch from a6e5a89 to 693bae7 Compare January 11, 2022 08:57
Base automatically changed from anca/prevote_nil_untimely to wb/proposer-based-timestamps January 11, 2022 10:44
@ancazamfir
Copy link
Contributor

ancazamfir commented Jan 11, 2022

The metrics added take the following form:

# HELP tendermint_consensus_proposal_timestamp_difference Difference between the timestamp in the proposal message and the local time when the message was received. Only calculated when a new is block proposed.
# TYPE tendermint_consensus_proposal_timestamp_difference histogram
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="-15"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="-8"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="-5"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="-1"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="-0.5"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="-0.1"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="0"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="0.5"} 9
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="1"} 9
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="3"} 9
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="15"} 9
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="+Inf"} 9
tendermint_consensus_proposal_timestamp_difference_sum{chain_id="test-chain-bXHoLM"} 0.071183513
tendermint_consensus_proposal_timestamp_difference_count{chain_id="test-chain-bXHoLM"} 9

how did you get these? looks like proposals are counted in multiple buckets (?).

@williambanfield
Copy link
Contributor Author

The metrics added take the following form:

# HELP tendermint_consensus_proposal_timestamp_difference Difference between the timestamp in the proposal message and the local time when the message was received. Only calculated when a new is block proposed.
# TYPE tendermint_consensus_proposal_timestamp_difference histogram
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="-15"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="-8"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="-5"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="-1"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="-0.5"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="-0.1"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="0"} 0
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="0.5"} 9
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="1"} 9
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="3"} 9
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="15"} 9
tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="+Inf"} 9
tendermint_consensus_proposal_timestamp_difference_sum{chain_id="test-chain-bXHoLM"} 0.071183513
tendermint_consensus_proposal_timestamp_difference_count{chain_id="test-chain-bXHoLM"} 9

how did you get these? looks like proposals are counted in multiple buckets (?).

Yeah, this is the structure of prometheus histogram metrics. The general structure is that each bucket keeps track of how many observations were less than or equal to the bucket's value. I.e. tendermint_consensus_proposal_timestamp_difference_bucket{chain_id="test-chain-bXHoLM",le="0.5"} 9 indicates that 9 observations occurred that were less than or equal .5 seconds. This is why the value 9 occurs in multiple places.

@williambanfield williambanfield force-pushed the wb/proposal-timestamp-difference branch from 9d120d6 to 0b509ff Compare January 11, 2022 15:35
Copy link

@cason cason left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I believe the discussion regarding the histogram buckets is still open.

"message and the local time when the message was received. " +
"Only calculated when a new is block proposed.",
Buckets: []float64{-15, -8, -5, -1, -.5, -.100, 0, .5, 1, 3, 15},
Buckets: []float64{-15, -3, -1, -.5, 0, .100, 1, 5, 8, 15},
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I consider this histogram in terms of what we want to learn from it. From this perspective, I can see five "regions" (intervals) of interest:

  • timestamp - receiveTime < -Precision: definitely untimely proposal
  • -Precision < timestamp - receiveTime < 0: awkward timestamp, as we shouldn't see this case occurring
  • timestamp - receiveTime < msgDelay: the typical case
  • msgDelay < timestamp - receiveTime < msgDelay + Precision: unlikely case, which observation indicates that msgDelay has possibly been underestimated.
  • timestamp - msgDelay > msgDelay + Precision: untimely proposal

I'm not sure which of this regions should have more than one bucket, to retrieve additional data, neither how to put generic numbers to these intervals.

"message and the local time when the message was received. " +
"Only calculated when a new is block proposed.",
Buckets: []float64{-15, -8, -5, -1, -.5, -.100, 0, .5, 1, 3, 15},
Buckets: []float64{-15, -3, -1, -.5, 0, .100, 1, 5, 8, 15},
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In terms of the proposed buckets, I think that 4-5 buckets in the negative side are too much. I think that for this situation a "little" negative (say, 20ms like suggested) and more than "a little" negative (so, likely to be untimely) are enough.

For positive numbers, maybe a geometric distribution of buckets (say 0.1, 1, 10) would be ideal in a first moment. Then we should try to identify the "real" msgDelay, to somehow distinguish between something like 0.5, 1, 1.5, and 2s, assuming that most of the values will be in the 0.1-1 and 1-10 buckets.

I don't know, it is an open question also for me, I can elaborate on this better and comment here.

@williambanfield williambanfield force-pushed the wb/proposal-timestamp-difference branch from 0b509ff to d63ee70 Compare January 11, 2022 15:47
@cason
Copy link

cason commented Jan 11, 2022

What we want to capture here is the distribution of a value that is the sum of two values: the clock skew and the delay of the proposal message.

The clock skew can be represented as a normal distribution centered at zero and with -Precision and Precision being already points of very low probability. This of course considering correct processes.

The latency for a message is more complex, in particular when using gossip. But traditional message delay distributions are like this: https://www.researchgate.net/figure/Examples-of-latency-distributions-on-a-wired-network-Starting-at-the-upper-left-the_fig2_253841639

The difference is that, in our case, as the proposer receives its proposal, we should have a small (1/n) concentration of values very close to zero, but yet positive. So we can consider a such distribution that has also a small peak around zero.

@williambanfield williambanfield force-pushed the wb/proposal-timestamp-difference branch from 0d3711f to f2e4b7d Compare January 12, 2022 22:01
@williambanfield williambanfield force-pushed the wb/proposal-timestamp-difference branch from f2e4b7d to 48a4e21 Compare January 12, 2022 23:52
@github-actions
Copy link

This pull request has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

@github-actions github-actions bot added the stale for use by stalebot label Jan 23, 2022
@creachadair creachadair removed the stale for use by stalebot label Jan 23, 2022
Copy link

@cason cason left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Approving the addition of metrics to measure the "delay" (adjusted by clock skew) of proposals, while I am not convinced, but also don't have a strong opinion, regarding the choice of slots boundaries for the histogram.

@williambanfield williambanfield merged commit f100d44 into wb/proposer-based-timestamps Jan 26, 2022
@williambanfield williambanfield deleted the wb/proposal-timestamp-difference branch January 26, 2022 22:22
mergify bot pushed a commit that referenced this pull request Jan 27, 2022
Moving this over from the proposer-based timestamps branch #7550.
@williambanfield williambanfield restored the wb/proposal-timestamp-difference branch September 9, 2022 16:13
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants