Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

bufferedAmount property is broken #492

Closed
feross opened this issue May 6, 2015 · 27 comments
Closed

bufferedAmount property is broken #492

feross opened this issue May 6, 2015 · 27 comments

Comments

@feross
Copy link

feross commented May 6, 2015

The bufferedAmount property doesn't work correctly.

This code:

var WebSocket = require('ws')

var socket = new WebSocket('wss://echo.websocket.org')

socket.onopen = function () {
  socket.send('abc')
  console.log('bufferedAmount after send: ' + socket.bufferedAmount)
}

socket.onmessage = function () {
  console.log('bufferedAmount after onmessage: ' + socket.bufferedAmount)
}

setInterval(function () {
  console.log('bufferedAmount on interval: ' + socket.bufferedAmount)
}, 1000)

Prints:

bufferedAmount after send: 10
bufferedAmount after onmessage: 1
bufferedAmount on interval: 1
bufferedAmount on interval: 1
bufferedAmount on interval: 1
bufferedAmount on interval: 1
bufferedAmount on interval: 1
bufferedAmount on interval: 1
bufferedAmount on interval: 1
...

In Chrome and Firefox, on the other hand, this is what gets output:

bufferedAmount after send: 3
bufferedAmount after onmessage: 0
bufferedAmount on interval: 0
bufferedAmount on interval: 0
bufferedAmount on interval: 0
bufferedAmount on interval: 0
bufferedAmount on interval: 0
bufferedAmount on interval: 0
...

Without a functioning bufferedAmount property, it's not possible to use the code I've written to implement backpressure in the browser on the server as well.

cc @mafintosh @maxogden

feross added a commit to feross/simple-websocket that referenced this issue May 6, 2015
Fixes #4

No backpressure in node. The `ws` module has a buggy `bufferedAmount`
property.
See: websockets/ws#492
@metabench
Copy link

metabench commented Mar 26, 2018

Is get bufferedAmount still not working?

If so, would someone please help me with the code that would detect if the receive buffer is full, or how full it is.

Currently I am trying to get a connection working where the server is quickly sending large amounts of data in separate paged messages, and I need to have client-side detection of receive buffer size used and size available (or at least it would be very useful, as it may be better than some other workarounds).

@gooderist
Copy link

If I understand the issue correctly, bufferedAmount was reporting +1 size even on an empty buffer. This was a fixed in node v8.8.0 (issue #15005)

If that was the issue, then yes, bufferedAmount is correctly reporting zero now after the onmessage. Although, I am still at a loss as to why it took 10 bytes (18 as of v10.8.0) to contain 3 ascii characters. I would love to find out if anyone knows.

@lpinca
Copy link
Member

lpinca commented Aug 10, 2018

In ws bufferedAmount is similar to https://developer.mozilla.org/en-US/docs/Web/API/WebSocket/bufferedAmount but not exactly the same. It is the sum of https://nodejs.org/api/net.html#net_socket_buffersize plus the byte size of any buffer in the Sender queue when permessage-deflate is enabled.

The data in the socket buffer (socket.bufferSize) is already framed, so what you get is not the byte size of the original messages but the byte size of the WebSocket frames corresponding to those message.

10 bytes for a message of 3 ASCII seem a bit too much though. The WebSocket frame size for a message of 3 bytes should be 5 or 7 bytes depending on whether it was masked or not (sent by the server or the client). Perhaps the payload is compressed?

@lpinca
Copy link
Member

lpinca commented Aug 10, 2018

Actually the mask is 4 bytes so the WebSocket frame for a 3 bytes message is 5 or 9 bytes depending on whether the payload is masked or not. The extra byte probably comes from the issue linked above.

@gooderist
Copy link

Thanks, it makes sense that the mask is accounting for some of the extra bytes. However, on latest (v10.8.0) I'm seeing 18 bytes. And on LTS 8.11.3, I'm getting 78 bytes!!

@lpinca
Copy link
Member

lpinca commented Aug 10, 2018

I don't know, maybe that's the result of multiple buffered frames (minus the bytes that are written)? Check with plain HTTP first.

@corwin-of-amber
Copy link

With 7.3.0, I can see that the property does go down to zero when all the data has been sent.
However, if I send a lot of data (few MB), I see the bufferedAmount going up by 8 bytes every ~1 sec, then immediately drops to 0 when the send is complete, with no intermediate values. I would expect to see some value between 0 and the total number of bytes sent, esp. since it evidently takes a few seconds to complete the transmission.

@BTOdell
Copy link

BTOdell commented Jun 22, 2020

The bufferedAmount property is not updated after send call when sending over localhost (or a sufficiently fast network).

Code:

public sendData(data: Data): void {
    const sendNumber = this.sendNumber++;
    console.log("[" + sendNumber + "]");
    console.log("Byte length: " + Buffer.byteLength(data));
    const beforeBufferedAmount: number = this.socket.bufferedAmount;
    console.log("Before buffered amount: " + beforeBufferedAmount);
    this.socket.send(data, () => {
        console.log("[" + sendNumber + "] Sent!");
    });
    const afterBufferedAmount: number = this.socket.bufferedAmount;
    console.log("After buffered amount: " + afterBufferedAmount);
    const deltaBufferedAmount: number = afterBufferedAmount - beforeBufferedAmount;
    console.log("Delta buffered amount: " + deltaBufferedAmount);
    console.log();
}

Output:

[1]
Byte length: 56
Before buffered amount: 0
After buffered amount: 0
Delta buffered amount: 0

[1] Sent!
[2]
Byte length: 14978
Before buffered amount: 0
After buffered amount: 0
Delta buffered amount: 0

[2] Sent!
[3]
Byte length: 89814
Before buffered amount: 0
After buffered amount: 0
Delta buffered amount: 0

[3] Sent!

I would expect the buffered amount to be the byte length of the data sent across the wire (including websocket frame bytes).

It seems like the send function is able to send the data synchronously without buffering the data at all, but this removes the ability to use this property to find how much data will be sent over the wire (before using any kind of compression).

@corwin-of-amber
Copy link

Thanks @BTOdell, this is similar to what I'm seeing, I am sending packets locally between two devices in my home WiFi. I do see it drop to zero eventually, in one go, after waiting long enough. I couldn't pinpoint the phase when this happens.

@lpinca
Copy link
Member

lpinca commented Jun 23, 2020

@BTOdell that is expected. It is inconsistent with the browser bufferedAmount but we rely on https://nodejs.org/api/net.html#net_socket_buffersize and if the data is written immediately socket.bufferSize is zero. Also ws bufferedAmount already takes into account the frame headers bytes. The browser bufferedAmount only counts the payload bytes.

@BTOdell
Copy link

BTOdell commented Jun 24, 2020

@lpinca I see. Thanks for the explanation.
Are there any timing guarantees for when the send callback is invoked (after the data is sent, obviously)?
But could it be used to compute a true bufferedAmount value without the synchronous behavior of net_socket_buffersize?
Could the send callback also be used to estimate bandwidth speed (bytes/second)? Is the callback timing reliable enough?

@lpinca
Copy link
Member

lpinca commented Jun 24, 2020

The callbacks are called in order and the timing is reliable so yes it should be possible. I think one issue with a bufferedAmount value calculated in this way is that it does not work well when compression is used.

@corwin-of-amber
Copy link

Actually I read it wrong: what I was seeing is not that bufferedAmount remains zero, but that after send it is the total number of sent bytes, but it does not decrease as bytes are being sent.

@lpinca
Copy link
Member

lpinca commented Jun 25, 2020

@corwin-of-amber that happens if the connection gets closed and you keep calling ws.send();

@corwin-of-amber
Copy link

Thanks for your reply @lpinca but this is not what happens: the packets are being sent. I am sending an entire file through the WebSocket and it is received, eventually, by the host. When all packets have been received, and only then, the bufferedAmount drops to zero, instantly, instead of decreasing gradually as packets are dequeued.

@BTOdell
Copy link

BTOdell commented Jun 26, 2020

I'm seeing some strange behavior with the send callback when I push a lot of data through the WebSocket. The callback is being greatly delayed and resulting in incorrect bandwidth calculations:

...
Preferred bandwidth: 3169605.3591230097
Preferred bandwidth: 3169593.8181918594
Preferred bandwidth: 3169599.1982574225
Preferred bandwidth: 3169603.647373312
 - record [true]: 524921 / 18.0740 = 29042.8472
Available bandwidth [new]: 29042.84723119306
 - record [true]: 55 / 0.0001 = 725651.1069
 - record [true]: 524921 / 18.0740 = 29042.8472
Available bandwidth [new]: 29045.768468703976
 - record [true]: 55 / 0.0000 = 2360312.4195
 - record [true]: 55 / 0.0001 = 725651.1069
 - record [true]: 524921 / 18.0740 = 29042.8472
Available bandwidth [new]: 29048.77404675688
 - record [true]: 55 / 0.0000 = 2125275.3198
 - record [true]: 55 / 0.0000 = 2360312.4195
 - record [true]: 55 / 0.0001 = 725651.1069
 - record [true]: 524921 / 18.0740 = 29042.8472
Available bandwidth [new]: 29051.7754748758
...

"Preferred bandwidth" is printed each time new data is sent by my application. The number is a moving average bandwidth calculation in bytes per second.
"Available bandwidth" is printed when the send callback is invoked, and I add a record to a queue with byte length and delta time (since last send callback). I use this queue to compute a moving average (over last 10 seconds).

You can see from the first "available bandwidth" print out, that the delta time (since the last sent packet) was over 18 seconds.
The packet is ~525KB so this results in a send rate of ~29KB per second. I know for a fact that my network connection is not that slow...

The send callbacks are all being executed periodically in batches. Looking further down in the logs you can see another large packet:

...
 - record [true]: 55 / 0.0001 = 725651.1069
 - record [true]: 524921 / 18.0740 = 29042.8472
Available bandwidth [new]: 29113.1523934154
 - record [true]: 931004 / 0.0001 = 6734206148.2821
 - record [true]: 55 / 0.0001 = 424444.9418
 - record [true]: 55 / 0.0001 = 422579.5794
 - record [true]: 55 / 0.0001 = 435064.6269
 - record [true]: 55 / 0.0001 = 471390.8602
 - record [true]: 55 / 0.0001 = 475778.5467
 - record [true]: 55 / 0.0001 = 508872.8928
 - record [true]: 55 / 0.0001 = 531442.0438
 - record [true]: 55 / 0.0001 = 576858.5333
 - record [true]: 55 / 0.0001 = 633764.6774
 - record [true]: 55 / 0.0001 = 617242.3855
 - record [true]: 55 / 0.0001 = 690902.6958
 - record [true]: 56 / 0.0001 = 748833.2910
 - record [true]: 56 / 0.0001 = 846036.4702
 - record [true]: 56 / 0.0001 = 816898.1211
 - record [true]: 56 / 0.0001 = 914987.8274
 - record [true]: 55 / 0.0001 = 989315.3937
 - record [true]: 55 / 0.0001 = 1097300.6404
 - record [true]: 55 / 0.0000 = 1266697.3745
 - record [true]: 55 / 0.0000 = 1357220.4126
 - record [true]: 55 / 0.0000 = 1652098.1647
 - record [true]: 55 / 0.0000 = 1751759.7223
 - record [true]: 55 / 0.0000 = 2125275.3198
 - record [true]: 55 / 0.0000 = 2360312.4195
 - record [true]: 55 / 0.0001 = 725651.1069
 - record [true]: 524921 / 18.0740 = 29042.8472
Available bandwidth [new]: 80617.93980663936
...

This time the packet is ~931KB but it only takes a fraction of a millisecond, resulting in a calculated speed of 6.7GB/s! I don't think my network is that fast either!

It's clear the send callbacks are not being executed in real-time. I'm not sure if this is a bug or if it's just a result of the nature of the Node.js IO model.

@BTOdell
Copy link

BTOdell commented Jun 26, 2020

Also, if what @lpinca said is true regarding the bufferedAmount property, then how is this a valid test case?
https://github.com/websockets/ws/blob/master/test/websocket.test.js#L189

'foo' could be sent immediately and then the tests fail.

@lpinca
Copy link
Member

lpinca commented Jun 26, 2020

@BTOdell

That test uses compression so the message is not sent immediately.

The send callbacks are all being executed periodically in batches.

Yes that is expected because net.socket() uses writable._writev(chunks, callback) if supported so multiple chunks are sent at the same time, and callbacks of those sends are invoked at the same time.

I'm not sure if this is a bug or if it's just a result of the nature of the Node.js IO model.

That's how Node.js net.Socket() works.

@corwin-of-amber

That probably happens becuase the the entire file is buffered in memory.

@BTOdell
Copy link

BTOdell commented Jun 26, 2020

Another strange bufferedAmount behavior is that it's sometimes much greater than the actual length of the data that I've sent:

Old pending size: 0
Sending data of length: 55
New pending size: 55
Calculated send rate: undefined
Sent data of length: 55
New pending size: 0
Old pending size: 0
Sending data of length: 67070
New pending size: 67070
Calculated send rate: undefined
Old pending size: 67070
Sending data of length: 65978
New pending size: 133048
Pending bytes (133048) - bufferedAmount (200148) = -67100
Calculated send rate: 0
Old pending size: 133048
Sending data of length: 55
New pending size: 133103
Pending bytes (133103) - bufferedAmount (200205) = -67102
Calculated send rate: 0
Old pending size: 133103
Sending data of length: 66025
New pending size: 199128
Pending bytes (199128) - bufferedAmount (266240) = -67112

I track the "pending" size by adding a byte length to a FIFO queue before I send the data over the WebSocket, and I remove it from the queue when I get the callback. I'm calculating the data length using Buffer.byteLength(...). And, yes, I know this won't be exactly the number of bytes sent across the wire because it's not accounting for the WebSocket frame header.

I read through the source code of ws and looked at all the corresponding Node.js documentation for the various functions it calls. I originally suspected that maybe ws was duplicating the buffer somehow or accidentally encoding my binary buffer as utf8 text. I still have no idea what could be happening.

I am using the buffer npm module instead of the Node.js builtin Buffer. The buffer is created in shared code (needs to work in both browser and Node.js), so I can't easily change it to use the Node.js builtin Buffer. Maybe ws is failing to detect that I'm passing a buffer so it's converting it to a string and then re-encoding it as utf8?

@lpinca
Copy link
Member

lpinca commented Jun 26, 2020

Maybe ws is failing to detect that I'm passing a buffer so it's converting it to a string and then re-encoding it as utf8?

I don't think so because the buffer module is designed to work seamlessly with Node.js unless you use the require('buffer/').Buffer form.

const Buf = require('buffer').Buffer;

console.log(Buffer.isBuffer(Buf.from('Hello'))); // Prints true.

Are you using compression? The frame header length on the client ranges from 6 to 14 bytes depending on the payload length.

@BTOdell
Copy link

BTOdell commented Jun 26, 2020

No, I don't have the perMessageDeflate option defined. It should default to disabled for incoming connections, right?

I'm using TypeScript to import the buffer module:

import {Buffer} from "buffer";

but I imagine it converts to something like this in JavaScript:

const {Buffer} = require("buffer");

Will that import form work with Node.js? You said it'll work seamlessly unless I use the require('buffer/').Buffer form, but then gave an example of that form working...

@lpinca
Copy link
Member

lpinca commented Jun 26, 2020

On the client permssage-deflate is enabled by default, if it is enabled on the server it will used. By default only messages whose size is > 1024 bytes will be compressed.

Try to use a plain net.Socket() without ws and see if you get the same behavior.

@BTOdell
Copy link

BTOdell commented Jun 26, 2020

How would I do that if I'm connecting to the server from a browser? Browsers can't initiate direct TCP connections.

I'll think of a way how to debug this better tomorrow.

@lpinca
Copy link
Member

lpinca commented Jun 26, 2020

Test it from Node.js, ws only works on Node.js anyway.

@BTOdell
Copy link

BTOdell commented Jun 27, 2020

I modified the sendFrame function in ws to print out exactly the size of the buffer that it's sending to the net.Socket:

sendFrame(list, cb) {
  if (list.length === 2) {
    this._socket.cork();
    this._socket.write(list[0]);
    this._socket.write(list[1], cb);
    console.log("Write(2): " + list[0].length + " + " + list[1].length);
    this._socket.uncork();
  } else {
    this._socket.write(list[0], cb);
    console.log("Write(1): " + list[0].length);
  }
}

and this is the output:

Old pending size: 0
Sending data of length: 55
Write(2): 2 + 55
New pending size: 55
Pending bytes (55) - bufferedAmount (0) = 55
Calculated send rate: undefined

Sent data of length: 55
New pending size: 0

Old pending size: 0
Sending data of length: 87937
Write(2): 10 + 87937
New pending size: 87937
Pending bytes (87937) - bufferedAmount (175894) = -87957
Calculated send rate: 0

Old pending size: 87937
Sending data of length: 58330
Write(2): 4 + 58330
New pending size: 146267
Pending bytes (146267) - bufferedAmount (234228) = -87961
Calculated send rate: 0

Sent data of length: 87937
New pending size: 58330

...

So, the ws library seems to be working fine. Maybe there is a bug in Node.js v14?
I've been looking closely over the bufferSize documentation: https://nodejs.org/api/net.html#net_socket_buffersize
This property shows the number of characters buffered for writing. The buffer may contain strings whose length after encoding is not yet known. So this number is only an approximation of the number of bytes in the buffer.

@BTOdell
Copy link

BTOdell commented Jun 27, 2020

I tracked down the implementation of the bufferSize property: https://github.com/nodejs/node/blob/master/lib/net.js#L544
and I printed out the value of writableLength to isolate the value of this[kLastWriteQueueSize]:

Old pending size: 0
Sending data of length: 56205
New pending size: 56205
Pending bytes (56205) - bufferedAmount (112418) = -56213
writableLength: 56209

Half of 112418 is 56209, so it looks like one of those values is not being updated at the right time/order and results in duplicated byte counts. I think I'll open a bug report for Node...

@lpinca
Copy link
Member

lpinca commented Jun 27, 2020

When not using permessage-deflate, ws.bufferedAmount is just an alias for socket.bufferSize and this is why I suggested to run your tests against a plain net.Server and net.Socket. Also try to see if behavior is the same on older versions of Node.js. It might be a regression.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

6 participants