Tracking down that darn "delayed ACK" (200ms) bug...

[nouser2013]

Greetings advanced dev's, since I'm working on a Windows machine, I'm really mad about the ESP not sending more than one packet before waiting for an ACK. Here's what I observe with different clients on Windows:

• Small data (200 bytes), webbrowser: if CONTENT_LENGTH matches, connection is closed by instantly browser. Overall TX time: 10-15ms.
• Large data (~8000 bytes), web browser: each completely filled packet is ack'd after 200ms. Overall TX time: ~1s (sic!)
• if it's my own client (python etc.) I can set the timeout accordingly and teardown the connection earlier for one packet, but with more packets same as webbrowser. I don't have any influence.

Then, I tried playing with the options in lwipopts.h. In theory, if the TCP_SND_BUF buffer is at least twice the size of TCP_MSS, the stack would send exactly this amount of data (because it has it in memory for retransmission) until RX window at the receiver (initially set to ~8k by Windows) is full. So, 1460 * 4 = 5840 (4 being set in the opts file) which fits perfectly into Windows' initial RX window. Long story short: as configured it should work.

Still, the ESP would send only one packet before waiting for an ACK. Then, I decreased TCP_MSS in the lwipopts.h to 128, just to see if I can see this in Wireshark. Oh wonder, I cannot:

Same thing with TCP_CALCULATE_EFF_SEND_MSS set to 0 by the way.

I tried to force the values by #defineing those directly at the top of my sketch before any includes. Same result.

So, could it be that those limits are hardcoded in the SDK liblwip.a library file? Can one of the dev's include lwIP's source in the github release in order to have a) the latest version and be) have it recompiled with new options?

Want to back this issue? Post a bounty on it! We accept bounties via Bountysource.

[igrr]

These defines need to be set when building LWIP, of course. Note that for
SDK 1.5.1 we don't have LwIP source available, as Espressif has released it
only for 1.5.

On Fri, Feb 5, 2016, 05:52 nouser2013 notifications@github.com wrote:

Greetings advanced dev's, since I'm working on a Windows machine, I'm
really mad about the ESP not sending more than one packet before waiting
for an ACK Here's what I observe with different clients on Windows:

• Small data (200 bytes), webbrowser: if CONTENT_LENGTH matches,
  connection is closed by instantly browser Overall TX time: 10-15ms
• Large data (~8000 bytes), web browser: each completely filled packet
  is ack'd after 200ms Overall TX time: ~1s (sic!)
• if it's my own client (python etc) I can set the timeout accordingly
  and teardown the connection earlier for one packet, but with more packets
  same as webbrowser I don't have any influence

Then, I tried playing with the options in lwipoptsh
https://githubcom/esp8266/Arduino/blob/master/libraries/ESP8266WiFi/src/include/lwipoptsh
In theory, if the TCP_SND_BUF buffer is at least twice the size of TCP_MSS,
the stack would send exactly this amount of data (because it has it in
memory for retransmission) until RX window at the receiver (initially set
to ~8k by Windows) is full So, 1460 * 4 = 5840 (4 being set in the opts
file) which fits perfectly into Windows' initial RX window Long story
short: as configured it should work

Still, the ESP would send only one packet before waiting for an ACK Then,
I decreased TCP_MSS in the lwipoptsh to 128, just to see if I can see
this in Wireshark Oh wonder, I cannot:
[image: image]
https://camo.githubusercontent.com/2cd5efdeeb729e3ff47c58e96bdc233f789426cc/68747470733a2f2f636c6f756467697468756275736572636f6e74656e74636f6d2f6173736574732f363632343033322f31323833363538312f39663534366339362d636262612d313165352d383736322d656565363736303834363239706e67
Same thing with TCP_CALCULATE_EFF_SEND_MSS set to 0 by the way

I tried to force the values by #defineing those directly at the top of my
sketch before any includes Same result

So, could it be that those limits are hardcoded in the SDK liblwipa
library file? Can one of the dev's include lwIP's source in the github
release in order to have a) the latest version and be) have it recompiled
with new options?

—
Reply to this email directly or view it on GitHub
#1577.

[Links2004]

which side has the delay?
windows has a 200ms delay for acks.
see:
https://support.microsoft.com/en-us/kb/823764 (Method 3)
https://support.microsoft.com/en-us/kb/328890

[nouser2013]

Exactly, I can only circumgo this by sending at least 2 packets. And if TCP_SND_BUF is at least 2 * TCP_MSS, the stack has enough RAM to store both full sized packets for retransmission should the ACK from the remote not arrive. And in the supplied lwipopts.h the TCP_SND_BUF is set to 2 * TCP_MSS.

So, in theory, there should be no problem with windows, since lwip is configured to send TCP_SND_BUF data completely (if it fits into Receiver=Windows RX buffer) before waiting for ACK. And Windows, receiving those two (or even more) data packets will send the ACK right away after the second packet.

What I don't know of course is which setting is in the supplied liblwip.a; even if they claim in the source to have TCP_SND_BUF to 2*TCP_MSS, we still cannot be sure. The *.a may be from a different build, may not have been updated or similar.

Does anybodoy have a Windows machine an can confirm the behaviour (packet ping-pong with 200ms delay)? It may be my setup after all.

[Links2004]

can confirm the windows delay of 200ms.
have changed the registry long time ago.
but the sync TCP that the webserver uses will sure run in this "problem".

[nouser2013]

Alright, I've tested extensively over the last 2 days.

1. the liblwip.a file definitely has a TCP_SND_BUF size of 2 * TCP_MSS = 2 * 1460 = 2920. I found out by simply outputting the size_t room in clientcontext::write().
2. The current write-mechanism definitely does not make use of this buffer size. Instead, the WiFiClient::write() only ever writes up to 1460 bytes to ClientContext::write(), which, in turn, waits for ACKs and interrupts the delay(5000) inside its write() from within the err_t _sent() callback. So, half of the buffer always remains empty.
3. It doesn't make a difference whether the tcp_output() is called. I'm guessing that lwip uses Nagle as well to determine when to send a packet. In theory, if you disable NAGLE, every tcp_write() should result in a TCP packet sent immediately.
4. I experimented with the PSH flag, but it does not seem to influence Windows' delayed ACK behaviour.
5. At least with all webbrowsers on Windows I tested, if they received the expected CONTENT_LENGTH bytes, they'll close the connection, thus forcing windows to send the ACK/FIN packet right away.
6. I still have trouble with small responses: Header goes in one ~250 byte packet, delayed ACK, JSON body goes into 10 byte packet, ACK/FIN. Overall response time: 250ms. If I manually put everything into one single packet (by removing web server and just sending on a simple WiFiServer/WiFiClient implementation), response time drops to 10ms for the same request!

So, in order to improve performance, I did the following to ClientContext.h:

size_t write(const char* data, size_t size) {
    if(!_pcb) {
        DEBUGV(":wr !_pcb\r\n");
        return 0;
    }

    if(size == 0) return 0;

    size_t room;
    // Wait for room in send buffer. Before this makes it to
    // master, definitely add a wait to determin from "outside"
    // how much data can be written!
    while (true) {
        room = tcp_sndbuf(_pcb);
        if (room<size) { delay(1); } else { break; }
    }
    size_t will_send=size;  // = (room < size) ? room : size;
    err_t err = tcp_write(_pcb, data, will_send, TCP_WRITE_FLAG_MORE); // No Copy, set PSH-Flag
    if(err != ERR_OK) {
        DEBUGV(":wr !ERR_OK\r\n");
        return 0;
    }

    _size_sent = will_send;
    DEBUGV(":wr\r\n");
    tcp_output( _pcb );
    // Let LWIP handle the sending completely!
    //_send_waiting = true;
    //delay(5000); // max send timeout
    //_send_waiting = false;
    DEBUGV(":ww\r\n");
    return will_send - _size_sent;
}

err_t _sent(tcp_pcb* pcb, uint16_t len) {
  DEBUGV(":sent %d\r\n", len);
  //_size_sent -= len;
  //if(_size_sent == 0 && _send_waiting) esp_schedule();
  return ERR_OK;
}

With this, I get the following nice Wireshark for 5k WiFiClient::write_P()...

...and 17 bytes JSON WiFiClient::write():

Unfortunately, forcing the output with tcp_output() superseeds Nagles algorithm, Browser receives http header only and waits for data, windows ACKs after 200ms and Webserver then sends the body. ~230ms response time for 17 bytes.

If you comment out the tcp_output(), the 17 bytes are fine (Nagle kicks in):

Now: ~50ms response time for 17 bytes. As I said, with a custom C string functions based parser I can get this down to 10ms.

But for some reason, the write_P() behaves much worse:

We may think about write paradigm. I say if you put your data to LWIP stack and LWIP accepts the data via tcp_write() without returning an error, its not the application's problem anymore.

The dirty hack would be to still use tcp_output but force the ESP Webserver to break with convention and send header and body in one go. This would seem to do the trick...

[igrr]

Did you check the pull request related to WiFiClient refactoring?
WiFiClient will now send up to TCP_SND_BUF.

On Sun, Feb 7, 2016, 18:49 nouser2013 notifications@github.com wrote:

Alright, I've tested extensively over the last 2 days.

1. the liblwip.a file definitely has a TCP_SND_BUF size of 2 * TCP_MSS
   = 2 * 1460 = 2920. I found out by simply outputting the size_t room
   in clientcontext::write().
2. The current write-mechanism definitely does not make use of this
   buffer size. Instead, the WiFiClient::write() only ever writes up to
   1460 bytes to ClientContext::write(), which, in turn, waits for ACKs
   and interrupts the delay(5000) inside its write() from within the err_t
   _sent() callback. So, half of the buffer always remains empty.
3. It doesn't make a difference whether the tcp_output() is called.
   I'm guessing that lwip uses Nagle as well to determine when to send a
   packet. In theory, if you disable NAGLE, every tcp_write() should result in
   a TCP packet sent immediately.
4. I experimented with the PSH flag, but it does not seem to influence
   Windows' delayed ACK behaviour.
5. At least with all webbrowsers on Windows I tested, if they received
   the expected CONTENT_LENGTH bytes, they'll close the connection, thus
   forcing windows to send the ACK/FIN packet right away.
6. I still have trouble with small responses: Header goes in one ~250
   byte packet, delayed ACK, JSON body goes into 10 byte packet, ACK/FIN.
   Overall response time: 250ms. If I manually put everything into one single
   packet (by removing web server and just sending on a simple
   WiFiServer/WiFiClient implementation), response time drops to 10ms
   for the same request!

So, in order to improve performance, I did the following to
ClientContext.h:

size_t write(const char* data, size_t size) {
if(!_pcb) {
DEBUGV(":wr !_pcb\r\n");
return 0;
}

if(size == 0) return 0;

size_t room;
// Wait for room in send buffer. Before this makes it to
// master, definitely add a wait to determin from "outside"
// how much data can be written!
while (true) {
    room = tcp_sndbuf(_pcb);
    if (room<size) { delay(1); } else { break; }
}
size_t will_send=size;  // = (room < size) ? room : size;
err_t err = tcp_write(_pcb, data, will_send, TCP_WRITE_FLAG_MORE); // No Copy, set PSH-Flag
if(err != ERR_OK) {
    DEBUGV(":wr !ERR_OK\r\n");
    return 0;
}

_size_sent = will_send;
DEBUGV(":wr\r\n");
tcp_output( _pcb );
// Let LWIP handle the sending completely!
//_send_waiting = true;
//delay(5000); // max send timeout
//_send_waiting = false;
DEBUGV(":ww\r\n");
return will_send - _size_sent;

}

err_t _sent(tcp_pcb* pcb, uint16_t len) {
DEBUGV(":sent %d\r\n", len);
//_size_sent -= len;
//if(_size_sent == 0 && _send_waiting) esp_schedule();
return ERR_OK;
}

With this, I get the following nice Wireshark for 5k WiFiClient::write_P()
...
[image: image]
https://cloud.githubusercontent.com/assets/6624032/12873264/ee3a9786-cdb8-11e5-95be-1aa3ac4022f0.png

...and 17 bytes JSON WiFiClient::write():
[image: image]
https://cloud.githubusercontent.com/assets/6624032/12873281/422fd554-cdb9-11e5-9b29-c1e28336303e.png
Unfortunately, forcing the output with tcp_output() superseeds Nagles
algorithm, Browser receives http header only and waits for data, windows
ACKs after 200ms and Webserver then sends the body. ~230ms response time
for 17 bytes.

If you comment out the tcp_output(), the 17 bytes are fine (Nagle kicks
in):
[image: image]
https://cloud.githubusercontent.com/assets/6624032/12873321/f6cbf9ac-cdb9-11e5-9517-a13fd67d32f5.png
Now: ~50ms response time for 17 bytes. As I said, with a custom C string
functions based parser I can get this down to 10ms.

But for some reason, the write_P() behaves much worse:
[image: image]
https://cloud.githubusercontent.com/assets/6624032/12873319/da9be8f0-cdb9-11e5-80a0-4544476a84bf.png

We may think about write paradigm. I say if you put your data to LWIP
stack and LWIP accepts the data via tcp_write() without returning an
error, its not the application's problem anymore.

The dirty hack would be to still use tcp_output but force the ESP
Webserver to break with convention and send header and body in one go. This
would seem to do the trick...

—
Reply to this email directly or view it on GitHub
#1577 (comment).

[nouser2013]

I just did, switched to the branch and pulled "as-is". Better, but not optimal.

5k transcript:

That the http response header is in one single packet I can understand, but why does Nagle not kick in? Also, look at the last two packets, 1514 and 404 should have been sent in one rush? Do I need to change something in the application source code?

17bytes transscript:

Again, shouldn't Nagle kick in here?

[igrr]

Sorry, what do you mean by "Nagle kicks in"? We call tcp_output after each
write, which forces any pending data to be sent, so why should Nagle work
here?

On Sun, Feb 7, 2016, 19:30 nouser2013 notifications@github.com wrote:

I just did, switched to the branch and pulled "as-is". Better, but not
optimal.

5k transcript:
[image: image]
https://cloud.githubusercontent.com/assets/6624032/12873538/13d35c7e-cdc0-11e5-8e44-bc3a57a1dd0b.png

That the http response header is in one single packet I can understand,
but why does Nagle not kick in? Also, look at the last two packets, 1514
and 404 should have been sent in one rush? Do I need to change something in
the application source code?

17bytes transscript:
[image: image]
https://cloud.githubusercontent.com/assets/6624032/12873542/239cfa84-cdc0-11e5-9b00-3d165fc81c38.png
Again, shouldn't Nagle kick in here?

—
Reply to this email directly or view it on GitHub
#1577 (comment).

[nouser2013]

well, kinda my point. Why is the setNoDelay() function exposed, then? It's rendered effectively useless with the forced sending, is it not? Shouldn't we let lwip handle sending completely?

[igrr]

OK, that's the question of semantics. WiFiClient::write should return the
number of bytes delivered, so there is no way to aggregate data from
multiple WiFiClient::write calls into a single packet.
I understand that this creates performance issues. I'll take a look if we
can relax this requirement without breaking too much code. For instance I
know that people have WiFiClient::write calls at the end of functions where
WiFiClient is a local variable. Currently WiFiClient destructor may call
tcp_abort, so the data from the final write may not be sent yet if we don't
wait for it to be ACKed. Changing WiFiClient::write semantics can
potentially break a lot of things, and I'm not sure that increased
performance is worth that. But I will take a look, thanks for pointing this
out.

On Sun, Feb 7, 2016, 20:00 nouser2013 notifications@github.com wrote:

well, kinda my point. Why is the setNoDelay() function exposed, then?
It's rendered effectively useless with the forced sending, is it not?
Shouldn't we let lwip handle sending completely?

—
Reply to this email directly or view it on GitHub
#1577 (comment).

[drmpf]

The problem of breaking that type of code could be avoided by providing a buffered wrapper for WiFiClient that the user can use if they want.

[nouser2013]

A tiny update here: I am using latest GIT code and still it's not behaving as expected. @igrr , would it be a compromise to intoduce a WiFiClient::confirmReception() method or, semantically more correct WiFiClient::waitForResult() and otherwise remove all the strategy code again (doesn't seem to work anyway)?

Then I could enable Nagle, fill the buffer with a lot of tiny writes, LWIP sends large packets and I either get blocked by the WiFiClient::write() call for as long as there is no room in the buffer, or I get blocked by the new function as long as there is no ACK from the other side. WiFiClient::confirmReception() could at the same time return an (LWIP-) error code.

Regarding the destructor issue: You could make that configurable, meaning option 1="abort on destroy", 2="block until result (ACK/NACK)", where of course one could no react to anymore, but hence the new function to cope with that.

I haven't had coffee yet so this may be complete misthinking :)

[igrr]

I haven't yet merged the "strategies" branch (and will not merge it in the current state anyway), so I don't think there is anything that needs to be "removed" from the latest git code:)
I'm thinking about the way to introduce a "switch" between blocking and non-blocking mode. Having a getter and setter is a poor option, but I have an idea how to make this distinction type-safe.

All these changes are currently on hold though. I'm working on an automated test system which is needed to ensure these "optimizations" do not introduce regressions in existing code.

[cnlohr]

Did anyone ever find a solution to this with the standard SDK? I can't seem to send a null-push using their stack, it's like they specifically detect it and are like "nope, you're not allowed to fix that". TCP null-pushs are the best solution I've found to get around this for situations where you need an ack immediately from Windows, and they work quite well!

https://github.com/cnlohr/avrcraft/blob/master/ipcore/tcp.c line 451 - basically just creates an empty TCP psh packet and Windows says "aaha, I'll IMMEDIATELY respond!" When I try anything with the ESP Open SDK, it refuses to send anything at all.