swarm: optimize compute of locally supported protocols

[thomaseizinger]

For context, see this discussion: #3840.

This issue captures the idea mentioned in #3840 (reply in thread) as a concrete task to work on.

What we want to achieve is a consistent view of our locally supported protocols by the ConnectionHandler. Every state change in the ConnectionHandler may change the supported protocols (i.e. what is returned from listen_protocol).

As the linked discussion shows, computing this on every poll iteration is quite expensive. Skipping the computation on some iterations may risk that the view is outdated. The key requirement for the optimization is thus that we must ensure that if we return Poll::Pending from the task AND our view is potentially stale to eventually recompute it.

The concrete suggestion in the linked issue is:

• Introduce a flag that tracks whether our view of the supported protocols is potentially outdated: maybe_outdated.
  • This flag must flip to false every time we update the supported protocols.
  • It must flip to true on every iteration where we decide to skip the computation.
• Introduce a timestamp that tracks, when we last updated our view of the supported protocols.
• If we updated it within the last 5 seconds, don't update it again.
• If the end up returning Poll::Pending and maybe_outdated is set to true, register a timer to wake us up in 5 seconds.

In addition, I'd suggest that we also compute the difference to our supported protocols upon every inbound stream. We need to collect all protocols anyway at this point so we might as well use that data efficiently!

I believe that this algorithm has the following properties:

• Short, consecutive wake-ups of the Connection don't end up re-computing the supported protocols.
• The state is eventually consistent by ensuring a wake-up and recomputation in case we suspend the connection with a potentially stale view.
• The connection stays suspended and does not wake up unnecessarily in case we have an up-to-date view of the supported protocols.

[mxinden]

@thomaseizinger thank you for writing this up. Can you add a summary on why compute of locally supported protocols is slow, i.e. needs to be optimized?

[thomaseizinger]

@thomaseizinger thank you for writing this up. Can you add a summary on why compute of locally supported protocols is slow, i.e. needs to be optimized?

Is the flamegraph in #3840 not enough? I don't want to re-iterate the entire discussion but only wanted to track one particular action item in an issue here so it can be picked up by someone.

[alindima]

I propose a fix here: #4291

I believe my changes perform functionally the same as the outlined algorithm above, but they're simpler.
Please correct me if I'm wrong

[mxinden]

@thomaseizinger thank you for writing this up. Can you add a summary on why compute of locally supported protocols is slow, i.e. needs to be optimized?

Is the flamegraph in #3840 not enough? I don't want to re-iterate the entire discussion but only wanted to track one particular action item in an issue here so it can be picked up by someone.

The flamegraph shows that gather_supported_protocols is compute heavy in a particular setup, namely the one taken the flamegraph off. What is not clear to me is:

• Why is this expensive? I am surprised comparing a low number (< 100) of short strings (<1kb) is expensive.
• How many protocols does the setup of the flamegraph compare? We need to build an intuition of how much is too much.
• Does Substrate use mostly 'static &str or dynamically created owned Strings?
• How often is Connection::poll woken up? Is some ConnectionHandler in the chain triggering a lot of wake-ups?
• Do we see this issue in other setups?
• What are alternative solutions? E.g. is the call to to_owned expensive? Can we do with references instead? What if the protocol is already a StreamProtocol?
  

  rust-libp2p/swarm/src/connection.rs

  Lines 443 to 450 in f95f39f

  	fn gather_supported_protocols(handler: &impl ConnectionHandler) -> HashSet<StreamProtocol> {
  	handler
  	.listen_protocol()
  	.upgrade()
  	.protocol_info()
  	.filter_map(|i| StreamProtocol::try_from_owned(i.as_ref().to_owned()).ok())
  	.collect()
  	}

In my eyes we are fixing the symptom before understanding the root cause. In addition I consider simply introducing a timer, to call the expensive part less, a hack. Can we do better? How do we determine the ideal duration of the timer? Is the complexity worth it? Can this be done simpler?

I know answering all of this is a lot of work and I appreciate the time you spend on this @alindima and @thomaseizinger.

[alindima]

I don't think it's only about how expensive gather_supported_protocols is, but more about the fact that it's being called very frequently (which basically does not let the connection to ever return Poll::Pending) on a node that has a lot of connections (200).
Based on the flamegraph, the majority of the time is not even spent comparing the two sets, but simply gathering the new set, in Iterator methods, allocating, cloning and constructing the data structures.

I agree that having a timer is a hack, but it looked like it was the only proposed solution deemed acceptable.

Some of the questions here are still important, I'll see what I can do about them

[mxinden]

@alindima friendly ping. Does this issue still exist for Polkadot? Can you follow up on these questions from above?

How many protocols does the setup of the flamegraph compare? We need to build an intuition of how much is too much.

Does Substrate use mostly 'static &str or dynamically created owned Strings?

How often is Connection::poll woken up? Is some ConnectionHandler in the chain triggering a lot of wake-ups? If I recall correctly, Parity tracks the task wake-ups in a Prometheus histogram.

Shall we do some synchronous debugging on this issue together? I am happy to do a call this or next week.

---

I tried to reproduce the issue using https://github.com/mxinden/kademlia-exporter/ establishing a couple thousand connections to the IPFS network. Note I don't think it is a good comparison to Polkadot, given that it has a lot of connections, a lot of connection churn, only minimal data send per connection and only supports the protocols below:

Protocols:
        - /ipfs/id/1.0.0
        - /ipfs/kad/1.0.0
        - /ipfs/id/push/1.0.0
        - /ipfs/ping/1.0.0

For what it is worth, I don't see significant time spend in code region discussed here.

rust-libp2p/swarm/src/connection.rs

Lines 451 to 452 in c8b5f49

	let new_protocols = gather_supported_protocols(handler);
	let changes = ProtocolsChange::from_full_sets(supported_protocols, &new_protocols);

I see 0.34% spend in gather_supported_protocols and 0.12% in from_full_sets.

Attaching the flamegraph for the sake of completeness. Again, I don't think it is representative.

[thomaseizinger]

Once we have #4282, we should be able to gather more precise data about where the time is spent, how often the connection is being woken etc.

[alindima]

sorry, I haven't yet managed to get the time to invest in this further. It's definitely still an issue for polkadot, but we think we have bigger fish to fry currently in terms of network overhead.

I view this as a performance regression, but even without it, the CPU consumption is very high

[thomaseizinger]

I just discovered another reason why we have a lot of allocations here:

rust-libp2p/swarm/src/connection.rs

Line 462 in 22f70e1

.filter_map(|i| StreamProtocol::try_from_owned(i.as_ref().to_owned()).ok())

The contract between the upgrade and the connection is currently AsRef<str> which means it doesn't matter that the underlying upgrade is a StreamUpgrade. By calling as_ref(), we are always just viewing the str and then re-allocating to an owned String ...