Active streams affect `yamux::connection::rtt`

Summary

I noticed that yamux::connection::rtt reports roundtrip times up to 70 seconds when stream is active, especially on slower connections.

When stream stops transferring data, rtt drops to normal values of few hundred ms.

Expected behavior

I expect that streams should make no difference and RTT messages should fly freely nevertheless.

Actual behavior

PONG message can be delayed up to 1 minute even if the channel itself is 12 Mbit/s and real latency is around 250 ms.

Relevant log output

2024-05-14T16:35:29.026725Z DEBUG new_established_connection{remote_addr=/ip4/65.109.94.118/tcp/9000/p2p/12D3KooWGaXrPiY8TbiNvLHXEvS8P9yFJF5gUoLEahzXWdk9if9y id=1 peer=12D3KooWGaXrPiY8TbiNvLHXEvS8P9yFJF5gUoLEahzXWdk9if9y}:Connection::poll: yamux::connection::rtt: sending ping 3710280974    
2024-05-14T16:35:31.799514Z  INFO p2p::protocol: Received 63.2% of state data (47185920 of 74680770) ...    
2024-05-14T16:35:35.369081Z  INFO p2p::protocol: Received 64.6% of state data (48234496 of 74680770) ...    
2024-05-14T16:35:35.562127Z DEBUG p2p::service: Timer tick    
2024-05-14T16:35:38.503010Z  INFO p2p::protocol: Received 66.0% of state data (49283072 of 74680770) ...    
2024-05-14T16:35:42.043910Z  INFO p2p::protocol: Received 67.4% of state data (50331648 of 74680770) ...    
2024-05-14T16:35:45.555739Z  INFO p2p::protocol: Received 68.8% of state data (51380224 of 74680770) ...    
2024-05-14T16:35:45.555755Z DEBUG yamux::connection::stream::flow_control: old window_max: 32 mb, new window_max: 64 mb    
2024-05-14T16:35:45.562532Z DEBUG p2p::service: Timer tick    
2024-05-14T16:35:49.110664Z  INFO p2p::protocol: Received 70.2% of state data (52428800 of 74680770) ...    
2024-05-14T16:35:53.237703Z  INFO p2p::protocol: Received 71.6% of state data (53477376 of 74680770) ...    
2024-05-14T16:35:55.562952Z DEBUG p2p::service: Timer tick    
2024-05-14T16:35:57.297695Z  INFO p2p::protocol: Received 73.0% of state data (54525952 of 74680770) ...    
2024-05-14T16:36:00.752351Z  INFO p2p::protocol: Received 74.4% of state data (55574528 of 74680770) ...    
2024-05-14T16:36:04.265680Z  INFO p2p::protocol: Received 75.8% of state data (56623104 of 74680770) ...    
2024-05-14T16:36:05.562676Z DEBUG p2p::service: Timer tick    
2024-05-14T16:36:07.709742Z  INFO p2p::protocol: Received 77.2% of state data (57671680 of 74680770) ...    
2024-05-14T16:36:10.735264Z  INFO p2p::protocol: Received 78.6% of state data (58720256 of 74680770) ...    
2024-05-14T16:36:15.066334Z  INFO p2p::protocol: Received 80.0% of state data (59768832 of 74680770) ...    
2024-05-14T16:36:15.562633Z DEBUG p2p::service: Timer tick    
2024-05-14T16:36:19.116259Z  INFO p2p::protocol: Received 81.4% of state data (60817408 of 74680770) ...    
2024-05-14T16:36:22.563326Z  INFO p2p::protocol: Received 82.8% of state data (61865984 of 74680770) ...    
2024-05-14T16:36:25.562763Z DEBUG p2p::service: Timer tick    
2024-05-14T16:36:25.720506Z  INFO p2p::protocol: Received 84.2% of state data (62914560 of 74680770) ...    
2024-05-14T16:36:28.427539Z  INFO p2p::protocol: Received 85.6% of state data (63963136 of 74680770) ...    
2024-05-14T16:36:31.106017Z  INFO p2p::protocol: Received 87.1% of state data (65011712 of 74680770) ...    
2024-05-14T16:36:34.106333Z  INFO p2p::protocol: Received 88.5% of state data (66060288 of 74680770) ...    
2024-05-14T16:36:35.562594Z DEBUG p2p::service: Timer tick    
2024-05-14T16:36:38.267050Z  INFO p2p::protocol: Received 89.9% of state data (67108864 of 74680770) ...    
2024-05-14T16:36:42.433313Z DEBUG new_established_connection{remote_addr=/ip4/65.109.94.118/tcp/9000/p2p/12D3KooWGaXrPiY8TbiNvLHXEvS8P9yFJF5gUoLEahzXWdk9if9y id=1 peer=12D3KooWGaXrPiY8TbiNvLHXEvS8P9yFJF5gUoLEahzXWdk9if9y}:Connection::poll: yamux::connection::rtt: received pong 3710280974, estimated round-trip-time 73.406589082s    

Possible Solution

Check if stream API uses/obeys multiplexing. RTT as well as other control messages should probably have higher priority.

Version

libp2p = { version = "0.53.2", features = [
    "tokio",
    "quic",
    "dns",
    "kad",
    "mdns",
    "noise",
    "macros",
    "tcp",
    "websocket",
    "yamux",
    "request-response",
    "cbor",
    "serde",
] }
libp2p-swarm = "0.44.1"
libp2p-stream = "0.1.0-alpha"

Would you like to work on fixing this bug ?

Maybe

Start by reproducing the delayed PONG while an active stream transfers data, then inspect the yamux::connection::rtt and stream scheduling paths referenced in the logs. Compare RTT behavior with and without the stream; done when control messages are not delayed by active stream traffic and the regression is covered by a test.