Investigate subscriber too slow errors in pubsub

[masih]

Observed in passive testing on mainnet for filecoin/16 network:

{"level":"info","ts":"2024-11-28T21:17:37.595+1100","logger":"pubsub","caller":"go-libp2p-pubsub@v0.11.0/pubsub.go:981","msg":"Can't deliver message to subscription for topic /f3/granite/0.0.2/filecoin/16; subscriber too slow"}
{"level":"info","ts":"2024-11-28T21:17:37.595+1100","logger":"pubsub","caller":"go-libp2p-pubsub@v0.11.0/pubsub.go:981","msg":"Can't deliver message to subscription for topic /f3/granite/0.0.2/filecoin/16; subscriber too slow"}
{"level":"info","ts":"2024-11-28T21:17:37.595+1100","logger":"pubsub","caller":"go-libp2p-pubsub@v0.11.0/pubsub.go:981","msg":"Can't deliver message to subscription for topic /f3/granite/0.0.2/filecoin/16; subscriber too slow"}

This indicates that the processing loop is taking too long to process received messages.
ida metrics at the corresponding time interval in which this occured: https://grafana.f3.eng.filoz.org/d/edsu1k5s7gtfkb/f3-passive-testing?orgId=1&var-network=mainnet&var-instance=ida.f3.eng.filoz.org:80&from=1732789053994&to=1732789928949&tab=transform

[masih]

We should set Tracer in pubsub and log UndeliverableMessage; such messages end up in that tracer call.

[masih]

The buffer size of 20 here may be too small for large networks.

[masih]

With buffer sizes bumped to 512 both for internal buffer size and pubsub subscriber buffer size seem to have fixed the issue at network scale of 40%.

The true fix is to make the processing loop faster, or internally buffer messages in a more sophisticated way inside GPBFT (and indeally hook it up to validation/internal state to drop messages early if they are not processed yet , were valid when buffered, and became useless)

[masih]

There is a flurry of these messages every time we re-bootstrap a passive testing network.

I believe the cause could also be that the gpbft runner gets paused when manifest changes and resumes again close to bootstrap of the new manifest. The runner is where the consume loop of topic subscription lives. Meaning, when paused no messages from the previous network topic gets consumed, and hence the "queue full" error.

If on archioz we also only observe this error during rebootstrap then I believe this is a non-issue. Though will not hurt to bump the limits anyway.

[masih]

Observed subscriber too slow error flurry on ida just before instance 4 started in network filecoin/40.

[masih]

There was a bump in CPU/allocation around that time. The bump was abrupt: I cannot say for sure it was caused by split store. It does however overlap with BLS sig validation, which is expected at the end of an instance.

It does not seem to happen consistently though.

Increase of buffer sizes in the latest release should certainly help.

@Kubuxu also suggested adding artificial jitter in message broadcast which would also help but we should be careful with the jitter boundary relative to F3 instance alignment.

[Kubuxu]

@masih was ida at the time running with the buffer patch or not?

[masih]

running with the buffer patch or not?

No but archioz was

[masih]

OK looks like archioz is running the commit that doesn't have the buffer bump. And it did observer the subscriber too slow.

Interestingly, a lot more than ida did.

[masih]

New observation: On both ida and archioz when this happens committee fetch time is at its max: 2-3 seconds.

It seem likely that slow committee fetch can cause this. Which brings me to ask why get committee times are shooting up

[masih]

resolved by #779