Skip to content
This repository has been archived by the owner on Jan 13, 2025. It is now read-only.

uses current timestamp when flushing local pending push queue #16808

Merged
merged 1 commit into from
Apr 28, 2021

Conversation

behzadnouri
Copy link
Contributor

@behzadnouri behzadnouri commented Apr 24, 2021

Problem

local_message_pending_push_queue is recording timestamps at the time the
value is created, and uses that when the pending values are flushed:
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/cluster_info.rs#L321
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/crds_gossip.rs#L96-L102

which is then used as the insert_timestamp when inserting values in the
crds table:
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/crds_gossip_push.rs#L183

The flushing may happen 100ms after the values are created (or even
later if there is a lock contention). This will cause non-monotone
insert_timestamps in the crds table (where time goes backward),
hindering the usability of insert_timestamps for other computations.

For example both ClusterInfo::get_votes and get_epoch_slots_since rely
on monotone insert_timestamps when values are inserted into the table:
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/cluster_info.rs#L1197-L1215
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/cluster_info.rs#L1274-L1298

Summary of Changes

This commit removes timestamps from local_message_pending_push_queue and
uses current timestamp when flushing the queue.

also related: #16806

local_message_pending_push_queue is recording timestamps at the time the
value is created, and uses that when the pending values are flushed:
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/cluster_info.rs#L321
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/crds_gossip.rs#L96-L102

which is then used as the insert_timestamp when inserting values in the
crds table:
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/crds_gossip_push.rs#L183

The flushing may happen 100ms after the values are created (or even
later if there is a lock contention). This will cause non-monotone
insert_timestamps in the crds table (where time goes backward),
hindering the usability of insert_timestamps for other computations.

For example both ClusterInfo::get_votes and get_epoch_slots_since rely
on monotone insert_timestamps when values are inserted into the table:
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/cluster_info.rs#L1197-L1215
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/cluster_info.rs#L1274-L1298

This commit removes timestamps from local_message_pending_push_queue and
uses current timestamp when flushing the queue.
@codecov
Copy link

codecov bot commented Apr 24, 2021

Codecov Report

Merging #16808 (b9b4697) into master (ec37a84) will increase coverage by 0.0%.
The diff coverage is 94.7%.

@@           Coverage Diff           @@
##           master   #16808   +/-   ##
=======================================
  Coverage    82.8%    82.8%           
=======================================
  Files         419      419           
  Lines      116251   116245    -6     
=======================================
+ Hits        96305    96337   +32     
+ Misses      19946    19908   -38     

now: u64,
) -> HashMap<Pubkey, Vec<CrdsValue>> {
self.process_push_messages(pending_push_messages);
self.process_push_messages(pending_push_messages, now);
Copy link
Contributor

@carllin carllin Apr 27, 2021

Choose a reason for hiding this comment

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

Will using the same "now" cause an ordering problem if there are two messages with the same gossip key are drained at the same time, and thus end up both in pending_push_messages

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I think it would be fine. The 2nd one will overwrite the 1st one since the vector is processed in order and that is consistent with how values are pushed to this queue.

@carllin
Copy link
Contributor

carllin commented Apr 27, 2021

The flushing may happen 100ms after the values are created (or even
later if there is a lock contention). This will cause non-monotone
insert_timestamps in the crds table (where time goes backward),
hindering the usability of insert_timestamps for other computations.

Hmm a bit confused about the ordering of events, so bear with me 😅

So for clarification, is the problem that currently, the local_message_pending_push_queue isn't necessarily ordered by the insert timestamps? I.e., an earlier entry in the vector could have a later timestamp, because each thread is taking its own wallclock timestamps on insert before grabbing the local_message_pending_push_queue lock?

For example, is it currently possible that if there is a vote for slot 1, then a vote for slot 2, that the latter vote would have an earlier insert timestamp? Does this require two threads inserting the votes concurrently?

Could we also add a test, maybe simulating a push for votes, then a push for epoch slots, that shows:

  1. The ordering is now consistent after the fix
  2. The ClusterInfo::get_votes and get_epoch_slots_since() now return the right ordering?

Copy link
Contributor Author

@behzadnouri behzadnouri left a comment

Choose a reason for hiding this comment

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

So for clarification, is the problem that currently, the local_message_pending_push_queue isn't necessarily ordered by the insert timestamps? I.e., an earlier entry in the vector could have a later timestamp, because each thread is taking its own wallclock timestamps on insert before grabbing the local_message_pending_push_queue lock?

The final goal is to ensure that when values are inserted into the gossip table their insert_timestamps are monotone. So it does not go backward. e.g. we insert a value in the crds table with insert_timestamp = 2 and then the next value is inserted with insert_timestamp = 1. This should be across all code paths which insert values into the crds table, not just pending-push messages.

This commit by itself is not enough to guarantee that. It only reduces scenarios where insert_timestamps may go backward. We also need #16806 to get merged, and probably more patches to rework the insert_timestamps as mentioned in the bottom of #16806 description.

now: u64,
) -> HashMap<Pubkey, Vec<CrdsValue>> {
self.process_push_messages(pending_push_messages);
self.process_push_messages(pending_push_messages, now);
Copy link
Contributor Author

Choose a reason for hiding this comment

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

I think it would be fine. The 2nd one will overwrite the 1st one since the vector is processed in order and that is consistent with how values are pushed to this queue.

@behzadnouri behzadnouri requested a review from carllin April 27, 2021 12:29
@behzadnouri behzadnouri merged commit b468ead into solana-labs:master Apr 28, 2021
@behzadnouri behzadnouri deleted the local-pending-push branch April 28, 2021 00:15
mergify bot pushed a commit that referenced this pull request Apr 28, 2021
local_message_pending_push_queue is recording timestamps at the time the
value is created, and uses that when the pending values are flushed:
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/cluster_info.rs#L321
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/crds_gossip.rs#L96-L102

which is then used as the insert_timestamp when inserting values in the
crds table:
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/crds_gossip_push.rs#L183

The flushing may happen 100ms after the values are created (or even
later if there is a lock contention). This will cause non-monotone
insert_timestamps in the crds table (where time goes backward),
hindering the usability of insert_timestamps for other computations.

For example both ClusterInfo::get_votes and get_epoch_slots_since rely
on monotone insert_timestamps when values are inserted into the table:
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/cluster_info.rs#L1197-L1215
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/cluster_info.rs#L1274-L1298

This commit removes timestamps from local_message_pending_push_queue and
uses current timestamp when flushing the queue.

(cherry picked from commit b468ead)
mergify bot added a commit that referenced this pull request Apr 28, 2021
#16896)

local_message_pending_push_queue is recording timestamps at the time the
value is created, and uses that when the pending values are flushed:
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/cluster_info.rs#L321
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/crds_gossip.rs#L96-L102

which is then used as the insert_timestamp when inserting values in the
crds table:
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/crds_gossip_push.rs#L183

The flushing may happen 100ms after the values are created (or even
later if there is a lock contention). This will cause non-monotone
insert_timestamps in the crds table (where time goes backward),
hindering the usability of insert_timestamps for other computations.

For example both ClusterInfo::get_votes and get_epoch_slots_since rely
on monotone insert_timestamps when values are inserted into the table:
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/cluster_info.rs#L1197-L1215
https://github.com/solana-labs/solana/blob/ec37a843a/core/src/cluster_info.rs#L1274-L1298

This commit removes timestamps from local_message_pending_push_queue and
uses current timestamp when flushing the queue.

(cherry picked from commit b468ead)

Co-authored-by: behzad nouri <behzadnouri@gmail.com>
@brooksprumo brooksprumo mentioned this pull request Aug 23, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants