Skip to content

telemetry: Count and report the number of duplicate proposals and MsgDigestSkipTag messages received#4605

Merged
onetechnical merged 2 commits intoalgorand:masterfrom
cce:duplicate-filter-message-count
Sep 30, 2022
Merged

telemetry: Count and report the number of duplicate proposals and MsgDigestSkipTag messages received#4605
onetechnical merged 2 commits intoalgorand:masterfrom
cce:duplicate-filter-message-count

Conversation

@cce
Copy link
Copy Markdown
Contributor

@cce cce commented Sep 29, 2022

Summary

Message filtering is used to reduce the number of duplicate large messages (>5000 bytes) sent between peers. After a large message is received, the node sends a filter message (protocol tag MsgDigestSkipTag) containing the message's hash to all its peers, telling them not to send them any messages with this hash. However this does not prevent a node from receiving the same large message concurrently from several peers, since it must fully receive the first large message before broadcasting the filter message.

This counts the number of duplicate filter messages received by a peer. Nodes do not track their outgoing filter messages, but receiving nodes must track the hashes, and so this wires up a counter to messageFilter.CheckDigest which "checks if the given digest already in the collection, and returns true if it was there before the call."

This also adds to agreement two new counters that count the number of times a duplicate payloadPresent event occurs, meaning the same proposal payload was received by agreement and sent to the proposalStore. There are two cases counted, for before and after proposal validation is complete.

Test Plan

Telemetry only — existing tests should pass.

@codecov
Copy link
Copy Markdown

codecov Bot commented Sep 29, 2022

Codecov Report

Merging #4605 (d4587bc) into master (42b9533) will decrease coverage by 0.00%.
The diff coverage is 55.55%.

@@            Coverage Diff             @@
##           master    #4605      +/-   ##
==========================================
- Coverage   54.10%   54.10%   -0.01%     
==========================================
  Files         401      401              
  Lines       51642    51655      +13     
==========================================
+ Hits        27942    27949       +7     
- Misses      21345    21348       +3     
- Partials     2355     2358       +3     
Impacted Files Coverage Δ
agreement/proposal.go 71.96% <ø> (ø)
network/wsNetwork.go 64.57% <0.00%> (-0.07%) ⬇️
network/wsPeer.go 65.50% <25.00%> (-0.53%) ⬇️
agreement/actions.go 71.42% <50.00%> (-0.20%) ⬇️
agreement/demux.go 90.68% <100.00%> (+0.13%) ⬆️
agreement/events.go 61.62% <100.00%> (+0.45%) ⬆️
agreement/proposalStore.go 100.00% <100.00%> (ø)
crypto/merkletrie/trie.go 66.42% <0.00%> (-2.19%) ⬇️
crypto/merkletrie/node.go 91.62% <0.00%> (-1.87%) ⬇️
... and 3 more

📣 We’re building smart automated test selection to slash your CI/CD build times. Learn more

// MessageDelay is the avarage relative message delay. Not being used for incoming connection.
MessageDelay int64 `json:",omitempty"`
// DuplicateFilterCount is the number of times this peer has sent us a message hash to filter that it had already sent before.
DuplicateFilterCount int64
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

when are we resetting it?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

This will be reset when the peer connection is closed — the counters that get sent to telemetry today are monotonically increasing, so it is the job of the analyzer to graph the rate at whatever granularity they can choose.. But for this particular event you would also need to spot the DisconnectPeer event between PeerConnections events to know when the reset occurred.

Copy link
Copy Markdown
Contributor

@winder winder Sep 30, 2022

Choose a reason for hiding this comment

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

The PeerConnectionDetails seems like a weird spot to put this. We connect once so how would there ever be duplicate messages?

Nevermind, I seem to have mistaken this for a different peer connection event which is sent once when someone connects.

Copy link
Copy Markdown
Contributor Author

@cce cce Sep 30, 2022

Choose a reason for hiding this comment

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

The idea is for this counter to be maintained for each wsPeer (as well as globally as a metrics.Counter), and reported here along with other per-peer stats like MessageDelay

Comment thread network/wsPeer.go
// Count that this peer has sent us duplicate filter messages: this means it received the same
// large message concurrently from several peers, and then sent the filter message to us after
// each large message finished transferring.
duplicateNetworkFilterReceivedTotal.Inc(nil)
Copy link
Copy Markdown

Choose a reason for hiding this comment

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

What is this existing duplicateNetworkFilterReceivedTotal? I wonder if that existing metric would have been useful.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

This is a top level metric across all peers, so that you don't have to look at the PeerConnections events and parse it out of there to get a quick measure of how often this is happening in the network, and also makes it available to Prometheus like our other counters.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

I added duplicateNetworkFilterReceivedTotal ... do you mean one of the other existing metrics?

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

was referring to outgoingNetworkMessageFilteredOutTotal sorry

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

also DuplicateNetworkMessageReceivedTotal

Copy link
Copy Markdown
Contributor Author

@cce cce Sep 30, 2022

Choose a reason for hiding this comment

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

yeah I found duplicateNetworkMessageReceivedTotal while writing this — it is counting the number of times you receive a "de-dupe-safe" tag message more than once, where dedupSafe() is defined as vote (AV) and transaction (TX) messages. These message types are both smaller than the 5000-byte limit used for the filtering I'm counting with proposals and already have their own counter, so my new counter is very similar but covers >5000-byte "skipped" messages like proposals.

outgoingNetworkMessageFilteredOutTotal is counting the number of times the filter successfully worked in preventing a duplicate proposal from being sent to a peer, so this is complementary to my new counter which is basically counting the number of times it didn't work. (Because the peer did not send the skip/filter message in time before the payload started sending)

@cce cce changed the title telemetry: Count and report the number of duplicate MsgDigestSkipTag messages received telemetry: Count and report the number of duplicate proposals and MsgDigestSkipTag messages received Sep 29, 2022
@cce cce requested review from brianolson and winder September 29, 2022 17:57
Copy link
Copy Markdown
Contributor

@winder winder left a comment

Choose a reason for hiding this comment

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

The metrics/telemetry integration looks correct.

Copy link
Copy Markdown
Contributor

@brianolson brianolson left a comment

Choose a reason for hiding this comment

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

LGTM

@onetechnical onetechnical merged commit b4fecd5 into algorand:master Sep 30, 2022
@cce cce deleted the duplicate-filter-message-count branch March 1, 2023 17:02
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants