litep2p: investigate potential GRANDPA issues

[sandreim]

During the recent Kusama finality stall GRANDPA stopped finalizing. We suspect that it happened because of the very high load and connectivity issues. However, approval voting which is more resource intensive performed better as approval voting stalled long after GRANDPA.

I think it is worthy to investigate logs if the new litep2p stack has had a positive or negative impact.

CC @paritytech/networking

[lexnv]

I've updated our internal networking dashboards to capture grandpa metrics: https://grafana.teleport.parity.io/goto/CNIrPeBHg?orgId=1

CPU Usage

During the incident, Kusama validators were under heavy load causing the following components of interest to consume more CPU:

• litep2p network backend consumption went from ~1.5 CPUs to roughly ~5 CPUs
• grandpa consumption went from ~0.3 CPUs to ~0.9
• other components started to consume more CPU as well: "approval-voting-parallel-db", "erasure-task", "dispute-coordonator-subsystem", "approval-voting-parallel-1"
• litep2p took the first place at CPU consumption, followed by the above components, followed by grandpa on the 6th place

During the incident, we can observe gaps in the collection of metrics, indicating that the instance was heavily under load.

Grandpa Metrics

The network has produced more inbound notifications on the grandpa protocol, while our overloaded validators have produced less outbound notifications.

• the inbound notifications almost doubled, from ~5k to ~10k with a peek of ~15k notifications received
• the higher number of notification has caused grandpa to slow while completing rounds and as a result the node produced less outbound traffic

We could take a closer look at grandpa under load and determine indeed if the bottleneck comes from the import methods:

• import_prevote and import_precommit
• both of them eventually call into find_ghost(), which could further be optimized for long ranges of blocks (see this comment)

The load can be observed from the grandpa round number, which suggests rounds don't complete as often as before:

The following represent the other grandpa metrics extracted from our nodes. The number of prevotes and precommits drops sharply, probably because validators take more time to complete rounds.

Next Steps

From the current investigation, I did not find any data suggesting that litep2p has negatively impacted grandpa. The CPU usage gained from litep2p should have helped grandpa a bit.

During the incident, the litep2p dropped 2 req-resp substreams under heavy load, which we could look into next with low priority:

• req-resp/bug: Received substream event but no active substream litep2p#398
• in response to that issue, have started a long running test to stress out the substream implementation, however several days have not reproduce the problem:[DNM] Long running substream testing litep2p#401

Grandpa was created before the async stabilization in rust. Therefore, it might be possible that a context waker is not properly saved or woken up, or there is something wrong with the poll implementation.

• Refactor to async / await finality-grandpa#124
• Replace our homemade Buffered with the one from futures-preview finality-grandpa#82 grandpa has quite a few places where it had to reimplement logic we take for granted now
• there is also the small possibility that, because of a missed context.wake() call, the grandpa functioned by relying on timers to advance the voting rounds and therefore unblock the async task.
  I'll need to understand grandpa a bit better and have a closer look at the poll implementation to eliminate these possibilities.

I will try to reproduce this with zombinet and report back any findings (most probably this will bring value by the CPU profiling, rather than actually stalling grandpa locally). In the meanwhile, the parachain team tries to reproduce it on a live net and I'll keep in touch with them 🙏

[alexggh]

Managed to reproduce this issue here on versi https://grafana.teleport.parity.io/goto/5FdWPGYHR?orgId=1, with many nodes disputing every candidate.

[lexnv]

Dashboards: https://grafana.teleport.parity.io/goto/YjP1nnLHR?orgId=1 look similar to the Kusama incident

[alexggh]

Found a case on a validator where grandpa does not want to vote anymore:

https://grafana.teleport.parity.io/goto/ea80HkENg?orgId=1

[alexggh]

Not sure why by the grandpa round seems to not advance past Constructing prevote for round 2, this is a different failure mode from #8830, because finality_target seems to be responding in 50ms and another one: https://grafana.teleport.parity.io/goto/-K-zC3YHR?orgId=1

[alexggh]

Not sure why by the grandpa round seems to not advance past Constructing prevote for round 2, this is a different failure mode from #8830, because finality_target seems to be responding in 50ms and another one: https://grafana.teleport.parity.io/goto/-K-zC3YHR?orgId=1

https://grafana.teleport.parity.io/goto/fWJT4eYNR?orgId=1, something seem to be off with the grandpa gossip engine because those nodes are not receiving any grandpa messages, see the value of substrate_network_gossip_registered_messages_total

On a 400 network there are 4 nodes like that under load, also 2 of them are running libp2p, so probably not something caused by litep2p.