Performance issue on internet

[stormshield-damiend]

This is similar to what discussed in #2153 .

Here are some tests we made on the following setup :

• Two VMs in two different datacenters in the cloud
• Latency between them is around 10ms (ping)
• Network driver is virtio_net with generic-segmentation-offload: on, generic-receive-offload: on and tx-udp-segmentation: off [fixed] (from ethtool)
• We test uploading from one VM to the other

First here is the result of an iperf3 test between the two VMs (TCP non ciphered)

[ ID] Interval           Transfer     Bitrate         Retr
[  5]   0.00-10.00  sec  1.12 GBytes   958 Mbits/sec  1102             sender
[  5]   0.00-10.01  sec  1.11 GBytes   955 Mbits/sec                  receiver

This matches the expected line rate between the two VMs.

We then use secnetperf from msquic project (UDP with encryption) https://github.com/microsoft/msquic/tree/main/src/perf

Result: Upload 1298923520 bytes @ 913880 kbps (11370.619 ms).

We are close to the line rate.

We then used quinn/perf client and server (UDP with encryption)

Overall stats:
RPS: 37.25 (373 requests in 10.01s)

Stream metrics:

      │ Upload Duration │ Download Duration | FBL        | Upload Throughput | Download Throughput
──────┼─────────────────┼───────────────────┼────────────┼───────────────────┼────────────────────
 AVG  │         26.71ms │           57.00µs │    57.00µs │       323.99 Mb/s │          0.00 Mb/s
 P0   │         18.21ms │            1.00µs │     1.00µs │        99.09 Mb/s │          0.00 Mb/s
 P10  │         22.98ms │            2.00µs │     2.00µs │       287.31 Mb/s │          0.00 Mb/s
 P50  │         25.30ms │           47.00µs │    47.00µs │       331.87 Mb/s │          0.00 Mb/s
 P90  │         29.20ms │          124.00µs │   124.00µs │       365.43 Mb/s │          0.00 Mb/s
 P100 │         84.67ms │          398.00µs │   398.00µs │       460.59 Mb/s │          0.00 Mb/s

We are around half the line rate.

If we disable crypto using --no-protection

Overall stats:
RPS: 38.84 (389 requests in 10.02s)

Stream metrics:

      │ Upload Duration │ Download Duration | FBL        | Upload Throughput | Download Throughput
──────┼─────────────────┼───────────────────┼────────────┼───────────────────┼────────────────────
 AVG  │         25.58ms │           76.00µs │    76.00µs │       337.91 Mb/s │          0.00 Mb/s
 P0   │         15.38ms │            1.00µs │     1.00µs │       100.66 Mb/s │          0.00 Mb/s
 P10  │         21.22ms │            5.00µs │     4.00µs │       283.64 Mb/s │          0.00 Mb/s
 P50  │         24.70ms │           70.00µs │    70.00µs │       339.74 Mb/s │          0.00 Mb/s
 P90  │         29.60ms │          143.00µs │   143.00µs │       395.84 Mb/s │          0.00 Mb/s
 P100 │         83.33ms │          578.00µs │   578.00µs │       545.26 Mb/s │          0.00 Mb/s

We get a bit better but are still far from the line rate

I can dedicate some work time to work on this issue, if you have any insight feel free to comment.

[stormshield-damiend]

Secnetperf socket parameters (from ss -um) : skmem:(r0,rb425984,t0,tb212992,f4096,w0,o0,bl0,d0)
Quinn perf socket parameters (from ss -lnpum) : skmem:(r0,rb425984,t0,tb425984,f4096,w0,o0,bl0,d0)

So this does not seem related to socket recv / send buffer size.

[djc]

Thanks for digging into performance like this!

What packet loss are you observing on this link? What congestion controller are you using? Are you CPU bound or I/O bound? Could allocations/buffering be a relevant constraint here?

[stormshield-damiend]

No problem.

I will measure packet loss or print what quinn / secnetperf sees.

Congestion controller is default for quinn so Cubic, msquic/secnetperf support both (cubic is default) , i will do a measurement for cc=bbr.

For the cpu usage during the test :
quinn : client around 15% / server around 35%
secnetperf: client around 25% / server around 55%

I can try with other allocators (tikv-jemalloc / mimalloc / ...) and look at what allocator is using msquic/secnetperf as default.

[stormshield-damiend]

Msquic/secnetperf with cc=bbr : Result: Upload 1760428032 bytes @ 1365141 kbps (10316.459 ms). So it is faster than default which is cc=cubic.

[stormshield-damiend]

Connection stats for quinn/perf (upload)

• Client side

Overall stats:
RPS: 34.96 (350 requests in 10.01s)

Stream metrics:

      │ Upload Duration │ Download Duration | FBL        | Upload Throughput | Download Throughput
──────┼─────────────────┼───────────────────┼────────────┼───────────────────┼────────────────────
 AVG  │         28.44ms │           69.00µs │    69.00µs │       309.47 Mb/s │          0.00 Mb/s
 P0   │         17.28ms │            1.00µs │     1.00µs │       100.01 Mb/s │          0.00 Mb/s
 P10  │         21.62ms │            2.00µs │     2.00µs │       231.21 Mb/s │          0.00 Mb/s
 P50  │         26.90ms │           69.00µs │    69.00µs │       311.95 Mb/s │          0.00 Mb/s
 P90  │         36.00ms │          140.00µs │   140.00µs │       388.24 Mb/s │          0.00 Mb/s
 P100 │         83.90ms │          320.00µs │   320.00µs │       485.49 Mb/s │          0.00 Mb/s

ConnectionStats { 
udp_tx: UdpStats { datagrams: 260483, bytes: 376892168, ios: 28741 },

udp_rx: UdpStats { datagrams: 9150, bytes: 376861, ios: 9151 },

frame_tx: FrameStats { ACK: 1055, ACK_FREQUENCY: 0, CONNECTION_CLOSE: 0, CRYPTO: 2, DATA_BLOCKED: 0, DATAGRAM: 0, HANDSHAKE_DONE: 0, IMMEDIATE_ACK: 4, MAX_DATA: 0, MAX_STREAM_DATA: 0, MAX_STREAMS_BIDI: 0, MAX_STREAMS_UNI: 0, NEW_CONNECTION_ID: 5, NEW_TOKEN: 0, PATH_CHALLENGE: 0, PATH_RESPONSE: 0, PING: 4, RESET_STREAM: 0, RETIRE_CONNECTION_ID: 0, STREAM_DATA_BLOCKED: 0, STREAMS_BLOCKED_BIDI: 0, STREAMS_BLOCKED_UNI: 0, STOP_SENDING: 0, STREAM: 259755 },

frame_rx: FrameStats { ACK: 7949, ACK_FREQUENCY: 0, CONNECTION_CLOSE: 0, CRYPTO: 3, DATA_BLOCKED: 0, DATAGRAM: 0, HANDSHAKE_DONE: 1, IMMEDIATE_ACK: 4, MAX_DATA: 0, MAX_STREAM_DATA: 1680, MAX_STREAMS_BIDI: 26, MAX_STREAMS_UNI: 0, NEW_CONNECTION_ID: 4, NEW_TOKEN: 2, PATH_CHALLENGE: 0, PATH_RESPONSE: 0, PING: 4, RESET_STREAM: 0, RETIRE_CONNECTION_ID: 1, STREAM_DATA_BLOCKED: 0, STREAMS_BLOCKED_BIDI: 0, STREAMS_BLOCKED_UNI: 0, STOP_SENDING: 0, STREAM: 350 }, 

path: PathStats { rtt: 10.027276ms, cwnd: 687939, congestion_events: 4, lost_packets: 24, lost_bytes: 34848, sent_packets: 260484, sent_plpmtud_probes: 4, lost_plpmtud_probes: 0, black_holes_detected: 0, current_mtu: 1452 }
 }

• Server Side

ConnectionStats {
udp_tx: UdpStats { datagrams: 9303, bytes: 383096, ios: 9303 },

udp_rx: UdpStats { datagrams: 265194, bytes: 383699307, ios: 265195 },

frame_tx: FrameStats { ACK: 8079, ACK_FREQUENCY: 0, CONNECTION_CLOSE: 0, CRYPTO: 3, DATA_BLOCKED: 0, DATAGRAM: 0, HANDSHAKE_DONE: 1, IMMEDIATE_ACK: 4, MAX_DATA: 0, MAX_STREAM_DATA: 1710, MAX_STREAMS_BIDI: 27, MAX_STREAMS_UNI: 0, NEW_CONNECTION_ID: 4, NEW_TOKEN: 2, PATH_CHALLENGE: 0, PATH_RESPONSE: 0, PING: 4, RESET_STREAM: 0, RETIRE_CONNECTION_ID: 1, STREAM_DATA_BLOCKED: 0, STREAMS_BLOCKED_BIDI: 0, STREAMS_BLOCKED_UNI: 0, STOP_SENDING: 0, STREAM: 357 },

frame_rx: FrameStats { ACK: 1075, ACK_FREQUENCY: 0, CONNECTION_CLOSE: 1, CRYPTO: 2, DATA_BLOCKED: 0, DATAGRAM: 0, HANDSHAKE_DONE: 0, IMMEDIATE_ACK: 4, MAX_DATA: 0, MAX_STREAM_DATA: 0, MAX_STREAMS_BIDI: 0, MAX_STREAMS_UNI: 0, NEW_CONNECTION_ID: 5, NEW_TOKEN: 0, PATH_CHALLENGE: 0, PATH_RESPONSE: 0, PING: 4, RESET_STREAM: 0, RETIRE_CONNECTION_ID: 0, STREAM_DATA_BLOCKED: 0, STREAMS_BLOCKED_BIDI: 0, STREAMS_BLOCKED_UNI: 0, STOP_SENDING: 0, STREAM: 264447 },

path: PathStats { rtt: 9.62579ms, cwnd: 12000, congestion_events: 0, lost_packets: 0, lost_bytes: 0, sent_packets: 9303, sent_plpmtud_probes: 4, lost_plpmtud_probes: 0, black_holes_detected: 0, current_mtu: 1452 }
 }

From client to server 4 congestions events / 24 lost packets / 34848 bytes.

[Ralith]

It looks like you're comparing connection-level stats in iperf3/secnetperf to stream-level stats in Quinn. You also don't seem to be using the default perf configuration. What is the exact command line you're passing to the perf client? If you're using any stream concurrency, then the per-stream throughput will be much lower than the connection-level throughput, because multiple streams are running concurrently. If you aren't using any stream concurrency, then the pipeline is stalling as each "request" waits for a response from the server before the next is issued (see perf client behavior). Judging by sent_packets * current_mtu, the latter seems most likely. At 350 requests * 10ms round trip (minimum), that's accounting for more than a third of your total runtime.

If you want to run a simple "blast bytes down the stream as fast as possible" benchmark, you should set a very large upload and/or download size so you don't spend time significant time waiting for responses, or confuse matters with concurrent streams.

[stormshield-damiend]

Hi,
when setting a high value for upload or download in perf client, too high to be reached before the duration, no stats are displayed. We made a quick patch using a CancellationToken to have all futures stop correctly but it is not finished for now.

Anyway here is the upload performance for a 10sec upload using a single stream :

Here is the arguments given to perf_client : --duration 10 --download-size 0 --upload-size 1048576000 --conn-stats

Client

ConnectionStats {
udp_tx: UdpStats { datagrams: 292333, bytes: 424455184, ios: 35585 },

udp_rx: UdpStats { datagrams: 15306, bytes: 632183, ios: 15307 },

frame_tx: FrameStats { ACK: 1469, ACK_FREQUENCY: 0, CONNECTION_CLOSE: 0, CRYPTO: 2, DATA_BLOCKED: 0, DATAGRAM: 0, HANDSHAKE_DONE: 0, IMMEDIATE_ACK: 4, MAX_DATA: 0, MAX_STREAM_DATA: 0, MAX_STREAMS_BIDI: 0, MAX_STREAMS_UNI: 0, NEW_CONNECTION_ID: 5, NEW_TOKEN: 0, PATH_CHALLENGE: 0, PATH_RESPONSE: 0, PING: 4, RESET_STREAM: 0, RETIRE_CONNECTION_ID: 0, STREAM_DATA_BLOCKED: 0, STREAMS_BLOCKED_BIDI: 0, STREAMS_BLOCKED_UNI: 0, STOP_SENDING: 0, STREAM: 292327 },

frame_rx: FrameStats { ACK: 14252, ACK_FREQUENCY: 0, CONNECTION_CLOSE: 0, CRYPTO: 3, DATA_BLOCKED: 0, DATAGRAM: 0, HANDSHAKE_DONE: 1, IMMEDIATE_ACK: 4, MAX_DATA: 0, MAX_STREAM_DATA: 2267, MAX_STREAMS_BIDI: 0, MAX_STREAMS_UNI: 0, NEW_CONNECTION_ID: 4, NEW_TOKEN: 2, PATH_CHALLENGE: 0, PATH_RESPONSE: 0, PING: 4, RESET_STREAM: 0, RETIRE_CONNECTION_ID: 1, STREAM_DATA_BLOCKED: 0, STREAMS_BLOCKED_BIDI: 0, STREAMS_BLOCKED_UNI: 0, STOP_SENDING: 0, STREAM: 0 },

path: PathStats { rtt: 9.547958ms, cwnd: 355389, congestion_events: 11, lost_packets: 490, lost_bytes: 711480, sent_packets: 292334, sent_plpmtud_probes: 4, lost_plpmtud_probes: 0, black_holes_detected: 0, current_mtu: 1452 } 
}

2025-06-10T15:28:37.184412Z  INFO perf_client: shutting down (timeout)
2025-06-10T15:28:37.185629Z  WARN perf_client: request: leaving
2025-06-10T15:28:37.217222Z  INFO perf_client: stream client bidirectional stream 0 uploaded 421527552 (bytes) elapsed 10.233532888 (secs) throughput 329.53 Mb/s

Here are the corresponding stats for the server side :

ConnectionStats {
udp_tx: UdpStats { datagrams: 15708, bytes: 648697, ios: 15708 },

udp_rx: UdpStats { datagrams: 297263, bytes: 431609556, ios: 297264 },

frame_tx: FrameStats { ACK: 14637, ACK_FREQUENCY: 0, CONNECTION_CLOSE: 0, CRYPTO: 3, DATA_BLOCKED: 0, DATAGRAM: 0, HANDSHAKE_DONE: 1, IMMEDIATE_ACK: 4, MAX_DATA: 0, MAX_STREAM_DATA: 2312, MAX_STREAMS_BIDI: 0, MAX_STREAMS_UNI: 0, NEW_CONNECTION_ID: 4, NEW_TOKEN: 2, PATH_CHALLENGE: 0, PATH_RESPONSE: 0, PING: 4, RESET_STREAM: 0, RETIRE_CONNECTION_ID: 1, STREAM_DATA_BLOCKED: 0, STREAMS_BLOCKED_BIDI: 0, STREAMS_BLOCKED_UNI: 0, STOP_SENDING: 0, STREAM: 1 },

frame_rx: FrameStats { ACK: 1505, ACK_FREQUENCY: 0, CONNECTION_CLOSE: 0, CRYPTO: 2, DATA_BLOCKED: 0, DATAGRAM: 0, HANDSHAKE_DONE: 0, IMMEDIATE_ACK: 4, MAX_DATA: 0, MAX_STREAM_DATA: 0, MAX_STREAMS_BIDI: 0, MAX_STREAMS_UNI: 0, NEW_CONNECTION_ID: 5, NEW_TOKEN: 0, PATH_CHALLENGE: 0, PATH_RESPONSE: 0, PING: 4, RESET_STREAM: 0, RETIRE_CONNECTION_ID: 0, STREAM_DATA_BLOCKED: 0, STREAMS_BLOCKED_BIDI: 0, STREAMS_BLOCKED_UNI: 0, STOP_SENDING: 0, STREAM: 297256 },

path: PathStats { rtt: 9.824697ms, cwnd: 12000, congestion_events: 0, lost_packets: 0, lost_bytes: 0, sent_packets: 15709, sent_plpmtud_probes: 4, lost_plpmtud_probes: 0, black_holes_detected: 0, current_mtu: 1452 } }

Next move is to look at TransportConfiguration and compare it to secnetperf (i already spotted they use a far more aggressive ack delay value than the default one from quinn).

[Ralith]

Thanks for the update! I'm surprised that getting rid of the pipeline bubbles had so little effect. Maybe the original per-stream statistics were already excluding that well enough.

Another area to compare between implementations is congestion controller configuration. A larger initial congestion window, for example, can dramatically improve initial performance on high-bandwidth links.

Given the low quinn CPU usage you report, especially compared to secnetperf's, it seems clear that the bottleneck is quinn choosing not to send more data, which suggests an issue in pacing, congestion control, or flow control. In particular, our Cubic implementation is fairly naive (e.g. we haven't implemented HyStart++), so there may be low hanging fruit there. Computing the proportion of time spent working vs. waiting for pacing vs. waiting for congestion control budget vs. waiting for flow control budget might also help.

[stormshield-damiend]

If you want to take a look at msquic setting, they are all documented here https://github.com/microsoft/msquic/blob/main/docs/api/QUIC_SETTINGS.md

[stormshield-damiend]

As discussed on discord here is a plot of the evolution of the congestion window during a 600 sec upload test (i just used --conn-stats to extract and plot the value

This does not look good.

Throughput was 349.77 Mb/s.

[stormshield-damiend]

By the way this confirm that quinn perf is blocked by congestion controller

2025-06-24T07:22:51.816788Z TRACE drive{id=0}: quinn_proto::connection: blocked by congestion control
2025-06-24T07:22:51.817842Z TRACE drive{id=0}:send{space=Data pn=15567}: quinn_proto::connection: blocked by congestion control
2025-06-24T07:22:51.817857Z TRACE drive{id=0}: quinn_proto::connection: blocked by congestion control
2025-06-24T07:22:51.818487Z TRACE drive{id=0}:send{space=Data pn=15574}: quinn_proto::connection: blocked by congestion control
2025-06-24T07:22:51.818516Z TRACE drive{id=0}: quinn_proto::connection: blocked by congestion control

[Ralith]

Well, that confirms it was blocked at two specific points in time. We really need to chart/aggregate state over time to draw meaningful conclusions -- for example, compare time spent waiting for congestion budget to time spent waiting for pacing or flow control. Even that's subtle because we should usually be blocked on congestion control -- just not so much that we can't achieve the expected throughput.

Regardless, from @stormshield-fabs's data, I think we can reasonably conclude that the congestion controller is doing something wrong, perhaps growing too slowly. A good next step might be trying to reproduce the bad behavior in a narrow unit test, and if that fails, isolating what's different between the unit test scenario and the real-world slow workload.

[stormshield-damiend]

MR around this topic (for reference) :
#2278
#2289