Bug 240311

This is probably related to the fix implemented for https://bugs.webkit.org/show_bug.cgi?id=235707.

Context:

The M-Lab team maintains a WebSocket-based network measurement client, https://speed.measurementlab.net/ (and elsewhere) which measures the maximum TCP throughput of the user’s Internet connection. The upload throughput measurement sends repeated messages over a WebSocket connection for 10 seconds. It uses bufferedAmount to monitor the backlog of untransmitted data. The goal is to always have some data ready and waiting to be transmitted but not so much data that the buffer overflows or takes too long to drain at the end of the test.


Overview:

We are testing the patch above, which makes the update of bufferedAmount synchronous, on the latest (version 144) Safari Technology Preview, and it looks like it might have introduced a significant regression. On some machines (more details below) bufferedAmount stops being updated after just a few writes, so our client stops sending data. Is it possible that bufferedAmount is not being decremented correctly in all the possible places in the code, or the data isn't actually sent over the network anymore for some reason?


Additional details:

The testing was done with the the code at https://github.com/m-lab/ndt7-js/blob/main/src/ndt7-upload-worker.js#L78 with added debugging logs around sock.send():

console.log("desired buffer: " + desiredBuffer + " - bufferedAmount: " + sock.bufferedAmount);
if (sock.bufferedAmount < desiredBuffer) {
         console.log("Sending " + data.length + " bytes");
         sock.send(data);
         console.log("Sent");
         total += data.length;
}

The very first calls to send() work normally. After flushing the buffer at least once (I can see bufferedAmount going down to zero), bufferedAmount reaches the desiredBuffer and then it’s never decremented again for the whole duration of the measurement -- 10 seconds. From the logs attached you can also see that NumBytes (total number of bytes sent) stays at 64KB and does not increase anymore.

This code works as intended on Safari stable (except for the sporadic crashes that caused us to report the original bug linked above) and every other major browser.

This new issue affects the speedtest at https://speed.measurementlab.net and Google's own speedtest client in search pages (OneBox), both based on websockets and the ndt7 protocol. Both of them report extremely low upload rates due to no new data being sent after the initial few milliseconds, matching what we observed in our testing. We believe that including that change as-is in the next Safari release will cause problems to all the integrations of the ndt7 speedtest protocol and everyone else relying on bufferedAmount to measure the backlog.

We have noticed differences in behavior depending on the hardware this was tested on:

2019 iMac 8-Core Intel i9, 64GB ram, MacOS Monterey: Works as intended
2019 MacBook Pro 8-core Intel i9 16GB ram, MacOS Monterey: Works as intended
2018 MacBook Pro 4-core Intel i7 16GB ram, MacOS Big Sur: Never works, stops sending after a few milliseconds as described above
2020 M1 MacBook Air, 16GB ram, MacOS Monterey: Works as intended when the tab running the measurement is in the foreground, stops sending when the tab is in the background. This is the most puzzling finding, but it could be replicated very consistently

Each test was run on a different network connection. Link speed does not seem to make a difference. Running the sender loop on the main thread vs a dedicated Web Worker does not seem to make any difference either.


Console logs, with comments added, collected on the 2018 MacBook Pro running Safari Technology Preview 144:

[Log] Upload started 
[Log] desired buffer: 57344 - bufferedAmount: 0 

First calls to send():

[Log] Sending 8192 bytes 
[Log] Sent 
[Log] desired buffer: 57344 - bufferedAmount: 8192 
[Log] Sending 8192 bytes 
[Log] Sent 
[Log] desired buffer: 57344 - bufferedAmount: 16384 
[Log] Sending 8192 bytes 
[Log] Sent 
[Log] desired buffer: 57344 - bufferedAmount: 24576 
[Log] Sending 8192 bytes 
[Log] Sent 
[Log] desired buffer: 57344 - bufferedAmount: 32768 
[Log] Sending 8192 bytes 
[Log] Sent 
[Log] desired buffer: 57344 - bufferedAmount: 40960 
[Log] Sending 8192 bytes 
[Log] Sent 
[Log] desired buffer: 57344 - bufferedAmount: 49152 
[Log] Sending 8192 bytes 
[Log] Sent 
[Log] desired buffer: 57344 - bufferedAmount: 57344 

bufferedAmount is decremented for the first time here:

[Log] desired buffer: 57344 - bufferedAmount: 24600 
[Log] Sending 8192 bytes 
[Log] Sent 
[Log] desired buffer: 57344 - bufferedAmount: 0 

After this point, bufferedAmount is not decremented anymore, as if no data is being sent over the network:

[Log] Sending 8192 bytes 
[Log] Sent 
[Log] desired buffer: 57344 - bufferedAmount: 8192 
[Log] Sending 8192 bytes 
[Log] Sent 
[Log] desired buffer: 57344 - bufferedAmount: 16384 
[Log] Sending 8192 bytes 
[Log] Sent 
[Log] desired buffer: 57344 - bufferedAmount: 24576 
[Log] Sending 8192 bytes 
[Log] Sent 
[Log] desired buffer: 57344 - bufferedAmount: 32768 
[Log] Sending 8192 bytes 
[Log] Sent 
[Log] desired buffer: 57344 - bufferedAmount: 40960 
[Log] Sending 8192 bytes 
[Log] Sent 
[Log] desired buffer: 57344 - bufferedAmount: 49152 
[Log] Sending 8192 bytes 
[Log] Sent 
[Log] desired buffer: 57344 - bufferedAmount: 57344 

From here on the client stops sending, since bufferedAmount == desiredBuffer. As a result, no new send() happens until the end of the 10-second measurement interval. What follows are just periodic measurement results which continue to decrease since no new data is sent:

[Log] Server-side measurement:  \'96 \{ConnectionInfo: \{Client: "<redacted>:52361", Server: "149.20.5.88:443", UUID: "<redacted>"\}, BBRInfo: Object, TCPInfo: Object\} 
\{ConnectionInfo: \{Client: "<redacted>:52361", Server: "149.20.5.88:443", UUID: "<redacted>"\}, BBRInfo: Object, TCPInfo: Object\}Object\
[Log] desired buffer: 57344 - bufferedAmount: 57344 
[Log] Client-side measurement:  \'96 \{ElapsedTime: 0.253, NumBytes: 65536, MeanClientMbps: 2.072284584980237\} 
[Log] desired buffer: 57344 - bufferedAmount: 57344 
[Log] Client-side measurement:  \'96 \{ElapsedTime: 0.507, NumBytes: 65536, MeanClientMbps: 1.0340986193293884\} 
[Log] desired buffer: 57344 - bufferedAmount: 57344 
[Log] Server-side measurement:  \'96 \{ConnectionInfo: \{Client: "<redacted>:52361", Server: "149.20.5.88:443", UUID: "<redacted>"\}, BBRInfo: Object, TCPInfo: Object\} 
\{ConnectionInfo: \{Client: "<redacted>:52361", Server: "149.20.5.88:443", UUID: "<redacted>"\}, BBRInfo: Object, TCPInfo: Object\}Object\
[Log] desired buffer: 57344 - bufferedAmount: 57344 
[Log] Client-side measurement:  \'96 \{ElapsedTime: 0.759, NumBytes: 65536, MeanClientMbps: 0.6907615283267456\} 
[Log] desired buffer: 57344 - bufferedAmount: 57344 
[Log] Server-side measurement:  \'96 \{ConnectionInfo: \{Client: "<redacted>:52361", Server: "149.20.5.88:443", UUID: "<redacted>"\}, BBRInfo: Object, TCPInfo: Object\} 

(... snip ...)