Active streams affect yamux::connection::rtt
#5387
Comments
|
Did you make any configuration changes to yamux? |
|
Thank you for reporting @0x7CFE!
Please link or post your configuration. Which The latest That said, it does prioritize sending over receiving. Though especially on slow connections, I expect the socket to return Based on the logs above, I assume you are seeing the large rtt on the receiver side. In case you are using In case you are using |
No, everything is default. The only setting I changed was idle connection timeout: let swarm = {
// let pings = libp2p_ping::Behaviour::new(libp2p_ping::Config::new());
let tasks = cbor::Behaviour::new(
[(StreamProtocol::new("/grad/tasks/1"), ProtocolSupport::Full)],
request_response::Config::default(),
);
let state = libp2p_stream::Behaviour::new();
libp2p::SwarmBuilder::with_existing_identity(net_keypair)
.with_tokio()
// .with_quic()
.with_tcp(
tcp::Config::default(),
noise::Config::new,
yamux::Config::default,
)?
.with_behaviour(|_| MyBehaviour { tasks, state })?
.with_swarm_config(|c| c.with_idle_connection_timeout(Duration::from_secs(300)))
.build()
}; |
My
Yes, it's the receiver that sent ping ages ago.
Thanks for the hint, I will try to update and see what would happen. |
|
I did cargo I am sitting in a café with a really crappy internet (~300 Kb/s) and apparently pings are now moving faster. It could just be a TCP windowing fluke, but still, you can see that the first ping traveled for 87 seconds. At very the same time, the stream was transferring a megabyte chunk of data. After that hiccup, subsequent pings were delivered within a few seconds. It's way better than before, but still inconsistent. Could it be that stream granularity prevents multiplexer to schedule other packets somehow? |
Can you reproduce this behavior in other networks? What latency do you get with ICMP's ping? |
Yes, I saw similar behavior on other networks (see the issue description). The ping was a few hundred ms. |
|
Are you able to run with a patched Unstaged changes (1)
modified yamux/src/connection.rs
@@ -416,6 +416,33 @@ impl<T: AsyncRead + AsyncWrite + Unpin> Active<T> {
Poll::Pending => {}
}
+ if self.pending_read_frame.is_none() {
+ match self.socket.poll_next_unpin(cx) {
+ Poll::Ready(Some(frame)) => {
+ match self.on_frame(frame?)? {
+ Action::None => {}
+ Action::New(stream) => {
+ log::trace!("{}: new inbound {} of {}", self.id, stream, self);
+ return Poll::Ready(Ok(stream));
+ }
+ Action::Ping(f) => {
+ log::trace!("{}/{}: pong", self.id, f.header().stream_id());
+ self.pending_read_frame.replace(f.into());
+ }
+ Action::Terminate(f) => {
+ log::trace!("{}: sending term", self.id);
+ self.pending_read_frame.replace(f.into());
+ }
+ }
+ continue;
+ }
+ Poll::Ready(None) => {
+ return Poll::Ready(Err(ConnectionError::Closed));
+ }
+ Poll::Pending => {}
+ }
+ }
+
if self.pending_write_frame.is_none() {
match self.stream_receivers.poll_next_unpin(cx) {
Poll::Ready(Some((_, Some(StreamCommand::SendFrame(frame))))) => {
@@ -448,33 +475,6 @@ impl<T: AsyncRead + AsyncWrite + Unpin> Active<T> {
}
}
- if self.pending_read_frame.is_none() {
- match self.socket.poll_next_unpin(cx) {
- Poll::Ready(Some(frame)) => {
- match self.on_frame(frame?)? {
- Action::None => {}
- Action::New(stream) => {
- log::trace!("{}: new inbound {} of {}", self.id, stream, self);
- return Poll::Ready(Ok(stream));
- }
- Action::Ping(f) => {
- log::trace!("{}/{}: pong", self.id, f.header().stream_id());
- self.pending_read_frame.replace(f.into());
- }
- Action::Terminate(f) => {
- log::trace!("{}: sending term", self.id);
- self.pending_read_frame.replace(f.into());
- }
- }
- continue;
- }
- Poll::Ready(None) => {
- return Poll::Ready(Err(ConnectionError::Closed));
- }
- Poll::Pending => {}
- }
- }
-
// If we make it this far, at least one of the above must have registered a waker.
return Poll::Pending;
} |
|
Do I understand correctly, that you are using the same |
Will try when I have time. Probably this week.
Yes, both nodes run the same binary, so I'm pretty sure they both use the same version. |
Summary
I noticed that
yamux::connection::rttreports 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.406589082sPossible Solution
Check if stream API uses/obeys multiplexing. RTT as well as other control messages should probably have higher priority.
Version
Would you like to work on fixing this bug ?
Maybe
The text was updated successfully, but these errors were encountered: