Connection establishment time increase between tcp v9 and v10

[achingbrain]

To connect to another js-libp2p peer and send one byte takes 0.2s with @libp2p/[email protected] but 0.4s with @libp2p/[email protected].

An extra round-trip may have been added - it needs some investigation as to why.

https://observablehq.com/@libp2p-workspace/performance-dashboard?branch=04d78b7e02f35038bed154f5772cbeade2b87912

The relevant deps are:

Before

"@chainsafe/libp2p-noise": "^14.0.0"
"@chainsafe/libp2p-yamux": "^6.0.1"
"@libp2p/tcp": "^9.0.4"
"libp2p": "^1.0.5"

After

"@chainsafe/libp2p-noise": "^16.0.3"
"@chainsafe/libp2p-yamux": "^7.0.1"
"@libp2p/tcp": "^10.1.6"
"libp2p": "^2.8.0"

[dozyio]

Logs for v1 and v2 here https://gist.github.com/dozyio/e49942344c2c37badb48e23b465dcaa6
Simulated with a latency of 80ms between the peers

[dozyio]

Found the issue
v1 using multistream-select v5 doesn't do the protocol negotiation if there is single protocol, where as multistream-select v6 v5.1+ does, thus the extra round trips

v1

2025-04-11T23:19:08.495766804Z 2025-04-11T23:19:08.495Z libp2p:perf opened connection after 0 ms
2025-04-11T23:19:08.496012346Z 2025-04-11T23:19:08.495Z libp2p:connection:outbound:egs9y11744413548493 starting new stream for protocols [ '/perf/1.0.0' ]
2025-04-11T23:19:08.496101054Z 2025-04-11T23:19:08.496Z libp2p:yamux:trace new outgoing stream id=1
2025-04-11T23:19:08.496648763Z 2025-04-11T23:19:08.496Z libp2p:yamux:trace sending frame { type: 1, flag: 1, streamID: 1, length: 0 }
2025-04-11T23:19:08.496673304Z 2025-04-11T23:19:08.496Z libp2p:connection:outbound:egs9y11744413548493:trace started new stream 1 for protocols [ '/perf/1.0.0' ]
2025-04-11T23:19:08.496764221Z 2025-04-11T23:19:08.496Z libp2p:yamux:outbound:1 no abort signal was passed while trying to negotiate protocols [ '/perf/1.0.0' ] falling back to default timeout
2025-04-11T23:19:08.496826596Z 2025-04-11T23:19:08.496Z libp2p:yamux:outbound:1:trace selecting protocol from protocols [ '/perf/1.0.0' ]
2025-04-11T23:19:08.496989888Z 2025-04-11T23:19:08.496Z libp2p:yamux:outbound:1:trace sink reading from source
2025-04-11T23:19:08.496993513Z 2025-04-11T23:19:08.496Z libp2p:yamux:outbound:1 selected protocol /perf/1.0.0
2025-04-11T23:19:08.497620221Z 2025-04-11T23:19:08.497Z libp2p:perf opened stream after 2 ms

V2

2025-04-11T23:21:19.950918545Z 2025-04-11T23:21:19.950Z libp2p:perf opened connection after 0 ms
2025-04-11T23:21:19.951156754Z 2025-04-11T23:21:19.950Z libp2p:connection:outbound:941q7w1744413679941:trace starting new stream for protocols [ '/perf/1.0.0' ]
2025-04-11T23:21:19.951164712Z 2025-04-11T23:21:19.951Z libp2p:yamux:trace new outgoing stream id=1
2025-04-11T23:21:19.951976879Z 2025-04-11T23:21:19.951Z libp2p:yamux:trace sending frame { type: 1, flag: 1, streamID: 1, length: 0 }
2025-04-11T23:21:19.952093254Z 2025-04-11T23:21:19.951Z libp2p:connection:outbound:941q7w1744413679941:trace started new stream 1 for protocols [ '/perf/1.0.0' ]
2025-04-11T23:21:19.952611004Z 2025-04-11T23:21:19.952Z libp2p:yamux:outbound:1 no abort signal was passed while trying to negotiate protocols [ '/perf/1.0.0' ] falling back to default timeout
2025-04-11T23:21:19.952628462Z 2025-04-11T23:21:19.952Z libp2p:yamux:outbound:1:trace selecting protocol from protocols [ '/perf/1.0.0' ]
2025-04-11T23:21:19.952992587Z 2025-04-11T23:21:19.952Z libp2p:yamux:outbound:1:trace select: write ["/multistream/1.0.0", "/perf/1.0.0"]
2025-04-11T23:21:19.953150754Z 2025-04-11T23:21:19.953Z libp2p:yamux:outbound:1:trace sink reading from source
2025-04-11T23:21:19.953650170Z 2025-04-11T23:21:19.953Z libp2p:yamux:trace sending frame { type: 0, flag: 0, streamID: 1, length: 33 }
2025-04-11T23:21:19.953795754Z 2025-04-11T23:21:19.953Z libp2p:yamux:outbound:1:trace select: reading multistream-select header
2025-04-11T23:21:20.120068587Z 2025-04-11T23:21:20.119Z libp2p:yamux:trace received frame { type: 2, flag: 2, streamID: 0, length: 0 }
2025-04-11T23:21:20.120160379Z 2025-04-11T23:21:20.119Z libp2p:yamux:trace received ping response pingId=0
2025-04-11T23:21:20.132230796Z 2025-04-11T23:21:20.131Z libp2p:yamux:trace received frame { type: 1, flag: 2, streamID: 1, length: 33 }
2025-04-11T23:21:20.132395087Z 2025-04-11T23:21:20.132Z libp2p:yamux:outbound:1:trace stream received window update id=1
2025-04-11T23:21:20.133353629Z 2025-04-11T23:21:20.133Z libp2p:yamux:trace received frame { type: 0, flag: 0, streamID: 1, length: 20 }
2025-04-11T23:21:20.135205879Z 2025-04-11T23:21:20.133Z libp2p:yamux:outbound:1:trace stream received data id=1
2025-04-11T23:21:20.135237462Z 2025-04-11T23:21:20.134Z libp2p:yamux:trace sending frame { type: 1, flag: 0, streamID: 1, length: 262164 }
2025-04-11T23:21:20.136631254Z 2025-04-11T23:21:20.136Z libp2p:yamux:outbound:1:trace select: read "/multistream/1.0.0"
2025-04-11T23:21:20.136656962Z 2025-04-11T23:21:20.136Z libp2p:yamux:outbound:1:trace select: reading protocol response
2025-04-11T23:21:20.137001629Z 2025-04-11T23:21:20.136Z libp2p:yamux:trace received frame { type: 0, flag: 0, streamID: 1, length: 13 }
2025-04-11T23:21:20.137018587Z 2025-04-11T23:21:20.136Z libp2p:yamux:outbound:1:trace stream received data id=1
2025-04-11T23:21:20.137100254Z 2025-04-11T23:21:20.137Z libp2p:yamux:trace sending frame { type: 1, flag: 0, streamID: 1, length: 524301 }
2025-04-11T23:21:20.138407712Z 2025-04-11T23:21:20.138Z libp2p:yamux:outbound:1:trace select: read "/perf/1.0.0"
2025-04-11T23:21:20.138444837Z 2025-04-11T23:21:20.138Z libp2p:yamux:outbound:1:trace selected protocol /perf/1.0.0
2025-04-11T23:21:20.140917796Z 2025-04-11T23:21:20.140Z libp2p:perf opened stream after 190 ms

https://github.com/libp2p/js-libp2p/blob/main/packages/multistream-select/src/select.ts#L68
Removing && options.negotiateFully === false fixes the issue but probably not the best fix

V2 after change

2025-04-12T00:07:19.986409379Z 2025-04-12T00:07:19.986Z libp2p:perf opened connection after 0 ms
2025-04-12T00:07:19.986827254Z 2025-04-12T00:07:19.986Z libp2p:connection:outbound:161ho1744416439981:trace starting new stream for protocols [ '/perf/1.0.0' ]
2025-04-12T00:07:19.986866545Z 2025-04-12T00:07:19.986Z libp2p:yamux:trace new outgoing stream id=1
2025-04-12T00:07:19.987449420Z 2025-04-12T00:07:19.987Z libp2p:yamux:trace sending frame { type: 1, flag: 1, streamID: 1, length: 0 }
2025-04-12T00:07:19.987466170Z 2025-04-12T00:07:19.987Z libp2p:connection:outbound:161ho1744416439981:trace started new stream 1 for protocols [ '/perf/1.0.0' ]
2025-04-12T00:07:19.987493712Z 2025-04-12T00:07:19.987Z libp2p:yamux:outbound:1 no abort signal was passed while trying to negotiate protocols [ '/perf/1.0.0' ] falling back to default timeout
2025-04-12T00:07:19.987540837Z 2025-04-12T00:07:19.987Z libp2p:yamux:outbound:1:trace selecting protocol from protocols [ '/perf/1.0.0' ]
2025-04-12T00:07:19.987945254Z 2025-04-12T00:07:19.987Z libp2p:yamux:outbound:1:trace sink reading from source
2025-04-12T00:07:19.987949504Z 2025-04-12T00:07:19.987Z libp2p:yamux:outbound:1:trace selected protocol /perf/1.0.0
2025-04-12T00:07:19.988632212Z 2025-04-12T00:07:19.988Z libp2p:perf opened stream after 2 ms