Chrome Browser and Quic_client Performance

[Bruno Cordero Rangel]

Hi,

when downloading a single text object of 8MB, hosted in a quic_server app on the same LAN, we're getting very different results in terms of download performance when using Chrome web browser instead of quic_client. 

On a first approach, just taking a look at throughputs for both cases, we can see big differences on the maximum throughput achieved and how long it takes for the connection close procedure to happen.

However, a 5MB file seems to be downloaded OK:

In the 8MB web site, we run out of credit and we got blocked (only when using Chrome); but still there's no reason for a 5 seconds pause in the transmission (according to the IETF formulas).

Why are we suffering this heavy delay (~5 secs. ) until the client sends again a MAX_DATA update in the 8MB scenario? Shouldn't quic_client experiment the same behavior? Mem./CPU usage is correct on all the scenarios.

Thanks a lot!

[Ian Swett]

Chrome has a much larger initial flow control window than quic_client, so this is a bit surprising, but I believe it's around 6MB, so that makes me think that there's an issue when the response is larger than the initial flow control window.

Can you file a Chromium bug and include any extra information you have?  I'd be very interested in when the server sends BLOCKED and the client sends MAX_DATA.

--
You received this message because you are subscribed to the Google Groups "QUIC Prototype Protocol Discussion group" group.
To unsubscribe from this group and stop receiving emails from it, send an email to proto-quic+...@chromium.org.
To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/proto-quic/98e65f11-a7e0-480b-ae06-5418f71deb41n%40chromium.org.

[Aleix Boixader Coma]

Hello Ian,

Let me show you some more graphics about the same iterations that my collegue Bruno was talking about, we will be attaching the log files and wireshark files that we have. Sorry if it is a little bit difficult to see.

With this graph we are showing information of the server logs. We have decided to plot the congestion window size and also the remaining flow credit, whose values have been found by parsing the numbers that follow the text that appears on the legend: "congestion window: " and "shortens write length to ".

Additionally there are 3 kinds of vertical lines, which are:

• blue: start of the connection ("new connection") and end of the connection ("fin: 1")
• pink: receiving of a WINDOW_UPDATE/MAX_DATA ("max data: ")
• green: sending BLOCK_FRAME ("is flow control blocked")

On the left plot, we can see that around second 5 the download is stopped by a flow control blockage, as the green line and the decreasing remaining credit show. After that, there are no messages until more than 5 seconds later, where it receives again MAX_DATA frames and the download restarts. At the end of this segment, the fin packet is sent (it's bearly visible as it's overlapped by a MAX_DATA frame) and after another 8 seconds we receive another MAX_DATA (around the 20 seconds mark).

On the other hand, the behaviour on the quic_client with the same download size is totally different, where we don't see any flow control blockage and neither a strong decrease in available credit. This client is capable of downloading the 8M file in only 2 seconds, which would be approximately the same in chrome89 if it didn't suffer from the flow control blockage.

Does this additional information give any more clues on what may be happening? Otherwise, we will open a Chromium bug ticket with all this information.

Thanks for your kind help,

Aleix Boixader.

PS: We were not able to decrypt wireshark traces of quic_client.

PS2: Files were too big to be attached, so here's a link to them: https://drive.google.com/file/d/12a4paGPgnH_XZ7vE3KefW_uw37XlAn_5/view?usp=sharing

[Aleix Boixader Coma]

Hi,

Meanwhile, we have created a bug ticket here: https://bugs.chromium.org/p/chromium/issues/detail?id=1189178

Best regards,

Aleix Boixader

[Ian Swett]

Thanks for filing a bug.

On Fri, Mar 12, 2021 at 9:56 AM Aleix Boixader Coma <aleix.b...@i2cat.net> wrote:

Hello Ian,

Let me show you some more graphics about the same iterations that my collegue Bruno was talking about, we will be attaching the log files and wireshark files that we have. Sorry if it is a little bit difficult to see.

With this graph we are showing information of the server logs. We have decided to plot the congestion window size and also the remaining flow credit, whose values have been found by parsing the numbers that follow the text that appears on the legend: "congestion window: " and "shortens write length to ".

Additionally there are 3 kinds of vertical lines, which are:

• blue: start of the connection ("new connection") and end of the connection ("fin: 1")
• pink: receiving of a WINDOW_UPDATE/MAX_DATA ("max data: ")
• green: sending BLOCK_FRAME ("is flow control blocked")

On the left plot, we can see that around second 5 the download is stopped by a flow control blockage, as the green line and the decreasing remaining credit show. After that, there are no messages until more than 5 seconds later, where it receives again MAX_DATA frames and the download restarts. At the end of this segment, the fin packet is sent (it's bearly visible as it's overlapped by a MAX_DATA frame) and after another 8 seconds we receive another MAX_DATA (around the 20 seconds mark).

On the other hand, the behaviour on the quic_client with the same download size is totally different, where we don't see any flow control blockage and neither a strong decrease in available credit. This client is capable of downloading the 8M file in only 2 seconds, which would be approximately the same in chrome89 if it didn't suffer from the flow control blockage.

Does this additional information give any more clues on what may be happening? Otherwise, we will open a Chromium bug ticket with all this information.

It does help a lot, but I'm still a bit unsure as to why flow control updates aren't being sent by Chrome:

 1) When the available flow control is low.

 2) When the BLOCKED frame is received.

One observation on the BLOCKED frame is that according to Wireshark, the server is sending a "Stream Data Limit" of 0, but IETF QUIC draft29 appears to be the negotiated version, indicating that a non-0 value should be sent.

Are you seeing a similar flow control issue with downloading larger files(ie: the Google drive attachment you sent above) from Google servers?  I didn't observe any pauses or BLOCKED frames when downloading that file you shared with me, which makes me believe there may be an issue that's difficult to reproduce?  ie: maybe a test with no packet loss?

Frame 5426: 68 bytes on wire (544 bits), 68 bytes captured (544 bits) on interface unknown, id 0
Ethernet II, Src: HewlettP_40:94:e5 (ec:b1:d7:40:94:e5), Dst: D-Link_f1:9f:58 (00:15:e9:f1:9f:58)
Internet Protocol Version 4, Src: 192.168.2.253, Dst: 192.168.2.86
User Datagram Protocol, Src Port: 6121, Dst Port: 54393
QUIC IETF
    QUIC Connection information
    [Packet Length: 26]
    QUIC Short Header PKN=4755
        0... .... = Header Form: Short Header (0)
        .1.. .... = Fixed Bit: True
        ..0. .... = Spin Bit: False
        ...0 0... = Reserved: 0
        .... .0.. = Key Phase Bit: False
        .... ..01 = Packet Number Length: 2 bytes (1)
        Packet Number: 4755
        Protected Payload: b13235ce4a263acad2e41886d214d863bd77bdf8d2297f
    STREAM_DATA_BLOCKED id=0
        Frame Type: STREAM_DATA_BLOCKED (0x0000000000000015)
        Stream ID: 0
        Stream Data Limit: 0
    PADDING Length: 4
        Frame Type: PADDING (0x0000000000000000)
        [Padding Length: 4]e 

The netlog does not include the offset of the blocked frame, so I can't tell if it is actually 0, but if it is, that sounds like a server bug.

One possibility for why no flow control updates are sent is that Chrome is not reading from the buffer very often?  But over 5 seconds is quite a long time, so that sounds odd.

t= 1774 [st= 1771]    QUIC_SESSION_PACKET_RECEIVED
                      --> peer_address = "192.168.2.253:6121"
                      --> self_address = "192.168.2.86:54393"
                      --> size = 26
t= 1774 [st= 1771]    QUIC_SESSION_UNAUTHENTICATED_PACKET_HEADER_RECEIVED
                      --> connection_id = "319eaa09be62d55c"
                      --> header_format = "IETF_QUIC_SHORT_HEADER_PACKET"
                      --> packet_number = 4756
t= 1774 [st= 1771]    QUIC_SESSION_PACKET_AUTHENTICATED
t= 1774 [st= 1771]    QUIC_SESSION_ACK_FRAME_RECEIVED
                      --> delta_time_largest_observed_us = 456
                      --> largest_observed = 630
                      --> missing_packets = []
                      --> received_packet_times = []
                      --> smallest_observed = 609
t= 1774 [st= 1771]    QUIC_SESSION_PADDING_FRAME_RECEIVED
                      --> num_padding_bytes = 1
t= 8466 [st= 8463]    QUIC_SESSION_WINDOW_UPDATE_FRAME_SENT
                      --> byte_offset = 9437205
                      --> stream_id = 0

[Aleix Boixader Coma]

Hi Ian,

We have tried downloads of 10, 20 and 30 (the Google drive download is 33MB), and they show the same behaviour, even worse. Here are the results in terms of troughput.

Regarding the Google Drive download, we have tested the same but the download is performed under HTTP2/TCP besides using the flags to enable quic and force h3-29. How did you do it to force the download with QUIC?

Regarding the packet loss, none of our tests suffer any packet loss at all because we are performing the tests on a LAN scenario. Additionally, we have confirmed by trying to find a "LOSS_RETRANSMISSION" frame in the server logs.

It seems that if it is a quic_server bug, it is also a quic_client bug, because they seem to understand each other. Here some more throughput results, this time with quic_client as client.

From our prespective, this seems that either both quic_server and quic_client have something off, and thereby they understand each other and everything goes well, or that Google Chrome has some unexpected behaviour.

In case this was a quic toy problem, do you know how should we proceed?

Thank you very much,

Aleix Boixader.

[Aleix Boixader Coma]

Hi,

Sorry, looks like the images are not available, I attach them.

Aleix Boixader.