What happens when the network has latency and jitter?

[murphypei]

Hi,

I sent about 2Mb of data on a normal network(the client and server on different machines), it takes 36ms, and the RTT is about 3ms, which is in line with expectations.
But when I apply a simulated delay and jitter to the network card(the maximum delay of each UDP packet is 220ms). I found that it takes a very long time to complete a transmission(the RTT is still in line with expactiations). I have tested another quic library, it doesn't have such a severe delay in this case. So what is the reason? Is there anything that can be optimized for this case? Because without optimized, there is no way to achieve near real-time transmission when the network fluctuates slightly.

I tested on the Linux, the simulation command is:

tc qdisc add dev eth0 root netem delay 200ms 20ms

this command will delay packets with value from uniform distribution [160ms-220ms]

the MsQuic send command:

./secnetperf -test:tput -target:172.11.11.12 -upload:2764800 -cc:bbr -stats:1 -sstats:1 -encrypt:1 -iosize:2764800 -sendbuf:0

sent once on the normal network

[conn][0xaaaab8eca000] STATS: EcnCapable=0 RTT=2900 us SendTotalStreamBytes=2764800 SendTotalPackets=1947 SendSuspectedLostPackets=0 SendSpuriousLostPackets=0 SendCongestionCount=0 SendEcnCongestionCount=0 RecvTotalStreamBytes=0 RecvTotalPackets=58 RecvReorderedPackets=0 RecvDroppedPackets=0 RecvDuplicatePackets=0 RecvDecryptionFailures=0
Result: 2764800 bytes @ 599300 kbps (36.907 ms).
App Main returning status 0

send once on the delay and jitter network

[conn][0xaaaadce3a110] STATS: EcnCapable=0 RTT=198735 us SendTotalStreamBytes=3539087 SendTotalPackets=2492 SendSuspectedLostPackets=1276 SendSpuriousLostPackets=1276 SendCongestionCount=14 SendEcnCongestionCount=0 RecvTotalStreamBytes=0 RecvTotalPackets=58 RecvReorderedPackets=0 RecvDroppedPackets=0 RecvDuplicatePackets=0 RecvDecryptionFailures=0
Result: 2764800 bytes @ 5141 kbps (4301.725 ms).

send ten times on the normal network

[conn][0xaaaae3bea110] STATS: EcnCapable=0 RTT=3490 us SendTotalStreamBytes=27725436 SendTotalPackets=19375 SendSuspectedLostPackets=54 SendSpuriousLostPackets=0 SendCongestionCount=1 SendEcnCongestionCount=0 RecvTotalStreamBytes=0 RecvTotalPackets=443 RecvReorderedPackets=0 RecvDroppedPackets=0 RecvDuplicatePackets=0 RecvDecryptionFailures=0
Result: 27648000 bytes @ 448141 kbps (493.558 ms).

send ten times on the delay and jitter network

[conn][0xaaaaaddaa000] STATS: EcnCapable=0 RTT=195384 us SendTotalStreamBytes=38099243 SendTotalPackets=26656 SendSuspectedLostPackets=12998 SendSpuriousLostPackets=12998 SendCongestionCount=169 SendEcnCongestionCount=0 RecvTotalStreamBytes=0 RecvTotalPackets=465 RecvReorderedPackets=0 RecvDroppedPackets=0 RecvDuplicatePackets=0 ```ecvDecryptionFailures=0
Result: 27648000 bytes @ 15253 kbps (14500.576 ms).

[nibanks]

Could you share the stream stats, -sstats:1?

[murphypei]

I ran the testcase again to reproduce.

sent once on the normal network

Flow blocked timing:
SCHEDULING:             517 us
PACING:                 0 us
AMPLIFICATION_PROT:     0 us
CONGESTION_CONTROL:     12364 us
CONN_FLOW_CONTROL:      0 us
STREAM_ID_FLOW_CONTROL: 7385 us
STREAM_FLOW_CONTROL:    8586 us
APP:                    199 us
[conn][0xaaaae1d3a120] STATS: EcnCapable=0 RTT=2743 us SendTotalStreamBytes=2767668 SendTotalPackets=1943 SendSuspectedLostPackets=2 SendSpuriousLostPackets=0 SendCongestionCount=1 SendEcnCongestionCount=0 RecvTotalStreamBytes=0 RecvTotalPackets=32 RecvReorderedPackets=0 RecvDroppedPackets=0 RecvDuplicatePackets=0 RecvDecryptionFailures=0
Result: 2764800 bytes @ 454989 kbps (48.613 ms).
App Main returning status 0

send once on the delay and jitter network

Flow blocked timing:
SCHEDULING:             733 us
PACING:                 0 us
AMPLIFICATION_PROT:     0 us
CONGESTION_CONTROL:     2843886 us
CONN_FLOW_CONTROL:      0 us
STREAM_ID_FLOW_CONTROL: 219861 us
STREAM_FLOW_CONTROL:    219860 us
APP:                    197 us
[conn][0xaaaacb13a110] STATS: EcnCapable=0 RTT=191852 us SendTotalStreamBytes=3658899 SendTotalPackets=2575 SendSuspectedLostPackets=1221 SendSpuriousLostPackets=1220 SendCongestionCount=17 SendEcnCongestionCount=0 RecvTotalStreamBytes=0 RecvTotalPackets=64 RecvReorderedPackets=0 RecvDroppedPackets=0 RecvDuplicatePackets=0 RecvDecryptionFailures=0
Result: 2764800 bytes @ 6706 kbps (3298.268 ms).
App Main returning status 0

send ten times on the normal network

Flow blocked timing:
SCHEDULING:             10596 us
PACING:                 0 us
AMPLIFICATION_PROT:     0 us
CONGESTION_CONTROL:     16270 us
CONN_FLOW_CONTROL:      0 us
STREAM_ID_FLOW_CONTROL: 7406 us
STREAM_FLOW_CONTROL:    7405 us
APP:                    252687 us
[conn][0xaaaab047a000] STATS: EcnCapable=0 RTT=3534 us SendTotalStreamBytes=27736908 SendTotalPackets=19384 SendSuspectedLostPackets=62 SendSpuriousLostPackets=0 SendCongestionCount=2 SendEcnCongestionCount=0 RecvTotalStreamBytes=0 RecvTotalPackets=436 RecvReorderedPackets=0 RecvDroppedPackets=0 RecvDuplicatePackets=0 RecvDecryptionFailures=0
Result: 27648000 bytes @ 422657 kbps (523.317 ms).
App Main returning status 0

send ten times on the delay and jitter network

Flow blocked timing:
SCHEDULING:             8171 us
PACING:                 0 us
AMPLIFICATION_PROT:     0 us
CONGESTION_CONTROL:     10549631 us
CONN_FLOW_CONTROL:      0 us
STREAM_ID_FLOW_CONTROL: 202746 us
STREAM_FLOW_CONTROL:    202964 us
APP:                    1327513 us
[conn][0xaaaac65ba110] STATS: EcnCapable=0 RTT=198428 us SendTotalStreamBytes=37917319 SendTotalPackets=26508 SendSuspectedLostPackets=13249 SendSpuriousLostPackets=13249 SendCongestionCount=158 SendEcnCongestionCount=0 RecvTotalStreamBytes=0 RecvTotalPackets=442 RecvReorderedPackets=0 RecvDroppedPackets=0 RecvDuplicatePackets=0 RecvDecryptionFailures=0
Result: 27648000 bytes @ 18145 kbps (12189.212 ms).
App Main returning status 0

[nibanks]

cc @maolson-msft & @csujedihy

As far as I can tell, the huge delays, relative to RTT, cause congestion control to kick in, because loss detection suspects loss. You can tell this by:

SendTotalPackets=2575 SendSuspectedLostPackets=1221 SendSpuriousLostPackets=1220

A HUGE number of packets are seen as suspected lost, though on the positive side, we do figure out they weren't actually lost ("spurious lost packets").

Bottom line, I'm not sure what we can do here. Adding up to ~200 ms of delay on the network, when the RTT is only ~4 ms is hard to overcome. Perhaps we could have logic to dynamically disable RACK logic?

@murphypei if you'd like to experiment, try commenting out this block in loss_detection.c to see if it helps at all (not sure it will though):

            } else if (Packet->PacketNumber < LossDetection->LargestAck &&
                        CxPlatTimeAtOrBefore32(Packet->SentTime + TimeReorderThreshold, TimeNow)) {
                if (!NonretransmittableHandshakePacket) {
                    QuicTraceLogVerbose(
                        PacketTxLostRack,
                        "[%c][TX][%llu] Lost: RACK %u ms",
                        PtkConnPre(Connection),
                        Packet->PacketNumber,
                        CxPlatTimeDiff32(Packet->SentTime, TimeNow));
                    QuicTraceEvent(
                        ConnPacketLost,
                        "[conn][%p][TX][%llu] %hhu Lost: %hhu",
                        Connection,
                        Packet->PacketNumber,
                        QuicPacketTraceType(Packet),
                        QUIC_TRACE_PACKET_LOSS_RACK);
                }

[murphypei]

Thanks very much for your reply. @nibanks

I commnet out the code block, but it dosen't help.

Adding up to ~200 ms of delay on the network, when the RTT is only ~4 ms is hard to overcome

Btw, I don't know if my description is misleading. What I added is the delay and jitter of all packets sent out by the network. The RTT also increased to ~200ms. This is the scenario that occurs on most networks.

[murphypei]

Hi, could you please give me more suggestions about this problem or is there any other test I need to do to judge the problem? @nibanks

[maolson-msft]

Hmm, so the issue is caused by jitter as small as 20ms. At first I wondered whether the jitter simulator was causing reordering (some naive implementations of jitter simulation could do this when the latency goes from high to low) and triggering RACK, but in the connection stats you've shown, RecvReorderedPackets is always 0, so that isn't it.

What's the largest value of jitter for which the problem doesn't occur? (By turning it off you've tested 0ms of jitter; how about 5ms? 10ms?)

[maolson-msft]

Also, if you're still able to repro with a smaller base latency (like say 40ms), please use that instead of the large 200ms to reduce the number of "weird things" in the repro.

[murphypei]

Hmm, so the issue is caused by jitter as small as 20ms. At first I wondered whether the jitter simulator was causing reordering (some naive implementations of jitter simulation could do this when the latency goes from high to low) and triggering RACK, but in the connection stats you've shown, RecvReorderedPackets is always 0, so that isn't it.

What's the largest value of jitter for which the problem doesn't occur? (By turning it off you've tested 0ms of jitter; how about 5ms? 10ms?)

@maolson-msft I'm very sorry, there seems to be a problem with the delay experiment done before. I tested the delay and jitter of network again.

It seems that both delay and jitter can cause severe network congestion. The yellow cell I have tested many times to confirm that the value is correct, not accidental, but I still don't know why they are so abnormally large.

On the other hand, I have tested sending camera frame to the server and recording the delay of the camera. Just a jitter of 50ms or a delay of 100ms will cause an actual delay of about a few seconds, which I think is very unexpected.

If I immediately turn off the delay or jitter of the network, the delay of the camera image will not be fixed, but it will return to normal after about a few minutes.

[murphypei]

@maolson-msft I wonder if the sent data of client has been accumulated and sent slowly without being discarded. When will the sent data be discarded or fail to be sent? What parameters can I modify to test this situation?

[Wizmann]

Hi Murphy, I think the problem may be related to the overhead of QUIC connection establishment, and the BBR may not be able to accurately probe the bandwidth since the workload is small.

I suggest we try to use the -t option for secnetperf.exe to run the test for a longer time (say, 100 secs). We can also increase the InitialWindowPackets to let QUIC use the bandwidth more aggressively (unfortunately, secnetperf.exe does not support that yet…).

Another option is that you can try to change the default TCP congestion control to BBR, and use the TCP mode of secnetperf.exe to see if the problem is related to QUIC or the implementation of BBR in MsQuic.