Successive calls to readBytes() trigger a timeout.

[jfjlaros]

Hardware:

Board: ESP32 Dev Module
Core Installation version: 1.0.4, 1.0.5
IDE name: Arduino IDE
Flash Frequency: n.a.
PSRAM enabled: n.a.
Upload Speed: n.a.
Computer OS: Debian 10

Description:

Sucsessive calls to readBytes() trigger a timeout in de example below. Is there a way to avoid this, or is this perhaps a bug in one of the core libraries?

When calling readBytes() twice in succession, the second call takes a lot longer than the first one. This behaviour seems to be occurring only when using the WiFi interface, both the Bluetooth and the Serial interface are not affected. This behaviour seems to be specific to this setup, other WiFi modules are not affected.

Sketch:

#include <WiFi.h>

#include "config.h" // SSID, PASS and PORT.


/* Timing measurement functions. */
#define SLOTS 100

unsigned long _last[SLOTS];
size_t _index = 0;


void _set(void) {
  _last[_index] = millis();
  _index++;
}

void _delta(char* label) {
  _index--;
  char buf[80];
  sprintf(buf, "%04i %s", millis() - _last[_index], label);
  Serial.println(buf);
}
/* End timing measurement functions. */


WiFiServer server(PORT);


void setup(void) {
  Serial.begin(9600);
  WiFi.begin(SSID, PASS);

  while (WiFi.status() != WL_CONNECTED) {
    delay(500);
  }

  server.begin();
}

void loop(void) {
  WiFiClient client = server.available();

  if (client) {
    while (client.connected()) {
      if (client.available()) {
        uint8_t c;
        _set();
        client.readBytes(&c, sizeof(uint8_t));
        _delta("read 1");

        /* Offending snippet. */
        _set();
        client.readBytes(&c, sizeof(uint8_t));
        _delta("read 2");
        /* End offending snippet. */

        _set();
        client.write(c);
        _delta("write");
      }
    }
    client.stop();
  }
}

Host code:

from serial import serial_for_url
from time import time


# Timing measurement functions.
_last = []


def _ms():
    return int(round(time() * 1000))


def _set():
    _last.append(_ms())


def _delta(label):
    print('{:04d} {}'.format(_ms() - _last.pop(-1), label))
# End timing measurement functions.


def test_raw(calls):
    connection = serial_for_url("socket://192.168.21.53:1025")
    _set()
    for _ in range(calls):
        _set()
        connection.write(b'\x00')
        _delta("write 1")

        # Offending snippet.
        _set()
        connection.write(b'\x00')
        _delta("write 2")
        # End offending snippet.

        _set()
        connection.read()
        _delta("read")
    _delta("total")


test_raw(3);

Debug Messages:

When we run the code as is, we see the following output:

Arduino     | Host
------------+-------------
0000 read 1 | 0000 write 1
0244 read 2 | 0000 write 2
0001 write  | 0254 read
0000 read 1 | 0001 write 1
0248 read 2 | 0000 write 2
0002 write  | 0252 read
0000 read 1 | 0001 write 1
0242 read 2 | 0000 write 2
0001 write  | 0249 read
            | 0757 total

Notice that read 2 takes a long time as seen from the perspective of the Arduino, while read takes a long time as seen from the perspective of the host.

When the offending snippets are commented out, we see the following output:

Arduino     | Host 
------------+-------------
0000 read 1 | 0001 write 1
0001 write  | 0006 read
0000 read 1 | 0000 write 1
0001 write  | 0005 read
0000 read 1 | 0000 write 1
0001 write  | 0004 read
            | 0016 total

Which is expected behaviour.

[felmue]

Hello @jfjlaros

I am just guessing here, but I think the client.flush(); after the first read removes the data of the second write and then the second read runs into a timeout as nothing is there anymore to read.

From the description of WiFiClient.flush()

flush()

Discard any bytes that have been written to the client but not yet read.

Thanks
Felix

[jfjlaros]

Hi @felmue thank you for looking into this.

Sorry, the flush() call should not be present in the sketch, I updated the issue.

Without this line, the problem persists. I can also confirm that no data is discarded (with or without the flush() call).

[stale]

[STALE_SET] This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 14 days if no further activity occurs. Thank you for your contributions.

[jfjlaros]

Bump for stale bot. This issue is not resolved yet.

[stale]

[STALE_CLR] This issue has been removed from the stale queue. Please ensure activity to keep it openin the future.

[stale]

[STALE_SET] This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 14 days if no further activity occurs. Thank you for your contributions.

[jfjlaros]

Bump for stale bot. This issue is not resolved yet.

[stale]

[STALE_CLR] This issue has been removed from the stale queue. Please ensure activity to keep it openin the future.

[VojtechBartoska]

Hello @jfjlaros , sorry for late reply. Are you able to test your issue on development version 2.0.3-RC1 to check if this is still valid? You can take a look on Docs where is explained how to choose development release version in Arduino IDE.

[jfjlaros]

Hi @VojtechBartoska ,

I tested version 2.0.3-RC1, but I see no difference in behaviour.

[VojtechBartoska]

Hi, Thanks for testing. I'm adding it to the roadmap and we will take a look on this more.

[P-R-O-C-H-Y]

Hi, i have simulated your issue between 2 ESP32s. I have used your server code and rewrite the host for ESP32.

        /* Offending snippet. */
        _set();
        client.readBytes(&c, sizeof(uint8_t));
        _delta("read 2");
        /* End offending snippet. */

This part takes 0000-0001 ms, but you can read wrong data. You need to wait till the data are available for every read with
if (client.available()), than you will read right data every time. So there is no timeout issue, but the data to be available for reading (read num. 2) takes sometimes from 250-600ms. Gonna take deeper look if there is something to speed it up.

[P-R-O-C-H-Y]

@jfjlaros Your issue can be solved by calling client.setNoDelay(true); after successful client connection. Default value is FALSE.

And as I mentioned in comment above, always read only if client.available() is true.

[jfjlaros]

After some more experimenting, the solution seems to be to set the NODELAY option on the sending side instead of the receiving side in this particular case. Adding the following line to the Python code seems to do the trick:

connection._socket.setsockopt(IPPROTO_TCP, TCP_NODELAY, 1)

I suspect setNoDelay will be needed when the roles are reversed.

Thank you very much for pointing me in the right direction.