No real-time serial.read() possible

[OekoSolveMG]

Board

M5 Stack Core 1 / 2

Device Description

M5 Stack Core 1 / 2 with the LAN Module with W5500

Hardware Configuration

Pinmap M5 Core 2
Pinmap Lan module

Version

v2.0.3

IDE Name

PlatformIO

Operating System

Windows 10

Flash frequency

40 MHz

PSRAM enabled

no

Upload speed

115200

Description

Low baudrate (9600) causes the serial.read() command to fail and not read bytes on the Modbus. Might there be some interfering code that runs in timed cycles with a very high priority that could creates issues for the serial.read().

The failed read seen above happens every 6th read.

Complete message:

The third line is a pin that gets toggled to high before serial.read() and to low after seral.read().

Sketch

// Allocate initial receive buffer size: 1 block of BUFBLOCKSIZE bytes
  const uint16_t BUFBLOCKSIZE(512);
  uint8_t *buffer = new uint8_t[BUFBLOCKSIZE];
  ModbusMessage rv;

  // Index into buffer
  register uint16_t bufferPtr = 0;
  // Byte read
  register int b; 

  // State machine states, RTU mode
  enum STATES : uint8_t { WAIT_DATA = 0, IN_PACKET, DATA_READ, FINISHED };

  // State machine states, ASCII mode
  enum ASTATES : uint8_t { A_WAIT_DATA = 0, A_DATA, A_WAIT_LEAD_OUT, A_FINISHED };

  register uint8_t state;

  // Timeout tracker
  unsigned long TimeOut = millis();

  // RTU mode?
  if (!ASCIImode) {
    // Yes.
    state = WAIT_DATA;
    // interval tracker 
    lastMicros = micros();
  
    while (state != FINISHED) {
      switch (state) {
      // WAIT_DATA: await first data byte, but watch timeout
      case WAIT_DATA:
        // Blindly try to read a byte
        b = serial.read();
        // Did we get one?
        if (b >= 0) {
          // Yes. Note the time.
          lastMicros = micros();
          // Do we need to skip it, if it is zero?
          if (b > 0 || !skipLeadingZeroBytes) {
            // No, we can go process it regularly
            state = IN_PACKET;
          } 
        } else {
          // No, we had no byte. Just check the timeout period
          if (millis() - TimeOut >= timeout) {
            rv.push_back(TIMEOUT);
            state = FINISHED;
          }
          delay(1);
        }
        break;
      // IN_PACKET: read data until a gap of at least _interval time passed without another byte arriving
      case IN_PACKET:
        // Are we past the interval gap without another byte?
        if (micros() - lastMicros >= interval) {
          // Yes, terminate reading
          LOG_V("%ldus without data\n", micros() - lastMicros);
          state = DATA_READ;
        } else {
          // No, still in reading sequence
          // Did we get a byte?
          if (b >= 0) {
            // Yes, collect it
            buffer[bufferPtr++] = b;
            // Mark time of last byte
            lastMicros = micros();
            // Buffer full?
            if (bufferPtr >= BUFBLOCKSIZE) {
              // Yes. Something fishy here - bail out!
              rv.push_back(PACKET_LENGTH_ERROR);
              state = FINISHED;
              break;
            }
          }
          // Buffer has space left - try to read another byte
          b = serial.read();
        }
        break;
      // DATA_READ: successfully gathered some data. Prepare return object.
      case DATA_READ:
        // Did we get a sensible buffer length?
        HEXDUMP_D("Raw buffer received", buffer, bufferPtr);
        tmp_copy.assign(buffer, buffer + bufferPtr);

        if (bufferPtr >= 4)
        {
          // Yes. Check CRC
          if (!validCRC(buffer, bufferPtr)) {
            // Ooops. CRC is wrong.
            rv.push_back(CRC_ERROR);
            tmp_failed = true;
          } else {
            // CRC was fine, Now allocate response object without the CRC
            for (uint16_t i = 0; i < bufferPtr - 2; ++i) {
              rv.push_back(buffer[i]);
            }
          }
        } else {
          // No, packet was too short for anything usable. Return error
          rv.push_back(PACKET_LENGTH_ERROR);
          tmp_failed = true;
        }
        state = FINISHED;
        break;
      // FINISHED: we are done, clean up.
      case FINISHED:
        // CLear serial buffer in case something is left trailing
        // May happen with servers too slow!
        while (serial.available()) serial.read();
        break;
      }
    }
  }
  // Deallocate buffer
  delete[] buffer;

  return rv;

Debug Message

[244292][E-MB][DUMP] (.pio/libdeps/m5stack-core-esp32/eModbus/src/RTUutils.cpp:497) - Size: [23], Content: [02 5E EA 06 00 00 08 00 50 0F 71 0C A8 00 01 00 01 00 64 00 03 2B A9 ]
[244300][MB][E] (lib/modbus/ModbusMaster.cpp:304) - Error: (E2) - (CRC check error).

[269243][E-MB][DUMP] (.pio/libdeps/m5stack-core-esp32/eModbus/src/RTUutils.cpp:497) - Size: [18], Content: [01 03 3E 00 71 02 7B 00 04 01 3C 00 00 00 00 02 79 01 ]
[269248][MB][E] (lib/modbus/ModbusMaster.cpp:304) - Error: (E2) - (CRC check error).

[269292][E-MB][DUMP] (.pio/libdeps/m5stack-core-esp32/eModbus/src/RTUutils.cpp:497) - Size: [23], Content: [F9 4C 9F 00 00 00 08 00 50 0F 71 0C A8 00 01 00 01 00 64 00 03 33 EA ]
[269298][MB][E] (lib/modbus/ModbusMaster.cpp:304) - Error: (E2) - (CRC check error).

[294243][E-MB][DUMP] (.pio/libdeps/m5stack-core-esp32/eModbus/src/RTUutils.cpp:497) - Size: [18], Content: [01 03 3E 00 71 02 7C 00 04 01 3C 00 00 00 00 02 79 01 ]
[294248][MB][E] (lib/modbus/ModbusMaster.cpp:304) - Error: (E2) - (CRC check error).

[294293][E-MB][DUMP] (.pio/libdeps/m5stack-core-esp32/eModbus/src/RTUutils.cpp:497) - Size: [22], Content: [01 EA 06 00 00 08 00 50 0F 71 0C A8 00 01 00 01 00 64 00 03 49 01 ]
[294299][MB][E] (lib/modbus/ModbusMaster.cpp:304) - Error: (E2) - (CRC check error).

[319242][E-MB][DUMP] (.pio/libdeps/m5stack-core-esp32/eModbus/src/RTUutils.cpp:497) - Size: [18], Content: [01 03 3E 00 71 02 7C 00 04 01 3C 00 00 00 00 02 79 00 ]
[319247][MB][E] (lib/modbus/ModbusMaster.cpp:304) - Error: (E2) - (CRC check error).

[319292][E-MB][DUMP] (.pio/libdeps/m5stack-core-esp32/eModbus/src/RTUutils.cpp:497) - Size: [23], Content: [FF 4C 9F 00 00 00 08 00 50 0F 71 0C A8 00 01 00 01 00 64 00 03 8C 91 ]
[319297][MB][E] (lib/modbus/ModbusMaster.cpp:304) - Error: (E2) - (CRC check error).

[339351][E-MB][DUMP] (.pio/libdeps/m5stack-core-esp32/eModbus/src/RTUutils.cpp:497) - Size: [3], Content: [D3 12 FF ]
[339353][MB][E] (lib/modbus/ModbusMaster.cpp:304) - Error: (E5) - (Packet length error).

[344233][E-MB][DUMP] (.pio/libdeps/m5stack-core-esp32/eModbus/src/RTUutils.cpp:497) - Size: [7], Content: [01 03 3E 00 71 02 7C ]
[344235][MB][E] (lib/modbus/ModbusMaster.cpp:304) - Error: (E2) - (CRC check error).

[344294][E-MB][DUMP] (.pio/libdeps/m5stack-core-esp32/eModbus/src/RTUutils.cpp:497) - Size: [35], Content: [7A 00 00 02 B9 00 00 0B D6 27 28 02 79 4C 9F 00 00 00 08 00 50 0F 71 0C A8 00 01 00 01 
00 64 00 03 A2 09 ]
[344303][MB][E] (lib/modbus/ModbusMaster.cpp:304) - Error: (E2) - (CRC check error).

[364269][E-MB][DUMP] (.pio/libdeps/m5stack-core-esp32/eModbus/src/RTUutils.cpp:497) - Size: [42], Content: [01 03 3E 00 71 02 7B 00 04 01 3D 00 00 00 00 02 79 01 01 00 78 FF FF 00 00 02 72 00 01 
00 01 01 84 00 00 02 B9 00 00 0B D6 27 ]
[364281][MB][E] (lib/modbus/ModbusMaster.cpp:304) - Error: (E2) - (CRC check error).

[389244][E-MB][DUMP] (.pio/libdeps/m5stack-core-esp32/eModbus/src/RTUutils.cpp:497) - Size: [19], Content: [01 03 3E 00 71 02 7C 00 04 01 3C 00 00 00 00 02 79 01 00 ]
[389249][MB][E] (lib/modbus/ModbusMaster.cpp:304) - Error: (E2) - (CRC check error).

[389295][E-MB][DUMP] (.pio/libdeps/m5stack-core-esp32/eModbus/src/RTUutils.cpp:497) - Size: [20], Content: [06 00 00 08 00 50 0F 71 0C A8 00 01 00 01 00 64 00 03 D2 F8 ]
[389300][MB][E] (lib/modbus/ModbusMaster.cpp:304) - Error: (E2) - (CRC check error).

Other Steps to Reproduce

See issue on the eModbus library about the same problem. Conclusion was that it might be a problem with the Base library. (eModbus/eModbus#198)

The same issue happens on both Core 1 and Core 2 as well as with a custom adapter for modbus or the WAN 5500 module.

I have checked existing issues, online documentation and the Troubleshooting Guide

• I confirm I have checked existing issues, online documentation and Troubleshooting guide.

[VojtechBartoska]

Hello @OekoSolveMG, thanks for your precise issue report. Is there any reason for you to run your code on Arduino v.2.0.2? I will suggest to retest your code on v2.0.3, there were some changes made on Serial.

[OekoSolveMG]

Thanks a lot for the fast response as written above, I wanted to try it but it seems that it hasn't been included in platformio yet. I'll definetly try it once it is available tough.

[bertmelis]

Thanks a lot for the fast response as written above, I wanted to try it but it seems that it hasn't been included in platformio yet. I'll definetly try it once it is available tough.

You're sure about that? I have 2.0.3 on VSCode/Platformio:

[OekoSolveMG]

You're sure about that? I have 2.0.3 on VSCode/Platformio:

Nvm seems I have the newest version as well, was confused because at least in the release note the corresponding espressif32 version is written to be 4.4.1 and not 4.4.0 (see https://github.com/espressif/arduino-esp32/releases/tag/2.0.3).

Resolving m5stack-core-esp32 environment packages...        
Platform espressif32 @ 4.4.0 (required: espressif32 @ 4.4.0)
├── framework-arduinoespressif32 @ 3.20003.220626 (required: platformio/framework-arduinoespressif32 @ ~3.20003.0)
├── framework-espidf @ 3.40302.0 (required: platformio/framework-espidf @ ~3.40302.0)

[Miq1]

So it looks like the issue is persisting despite the recent changes to the Serial handling.

[SuGlider]

@OekoSolveMG

Could you please try this solution:

// Necessary include for testing the fix
#include "driver/uart.h"


void setup() {
  // for example, start Serial - UART0
  Serial.begin(115200);

  // right after starting UART0, add this code:
  uart_intr_config_t uart_intr = {
      .intr_enable_mask = (0x1<<0) | (0x8<<0),  // UART_INTR_RXFIFO_FULL | UART_INTR_RXFIFO_TOUT,
      .rx_timeout_thresh = 1,
      .txfifo_empty_intr_thresh = 10,
      .rxfifo_full_thresh = 112,
  };
  uart_intr_config((uart_port_t) 0, &uart_intr);  // Zero is the UART number for Arduino Serial
}

I think that adding this fix may make UART RX faster and "real time".
Please try it in the same testing environment used to this issue and let me know.

Thanks!

[OekoSolveMG]

The pin seems to be toggling differently now. The read doesn't seem to start until the message has been sent completly. Will let it run over night and see if the issue doesn't occur anymore but the LA result looks different (Especially relevenat is the third line that toggles to HIGH before serial.read and toggle to low after serial.read.

LA result with changes above:

Old LA result with no changes:

[OekoSolveMG]

Let it run for a while now and the error happened again but this time it was different. This time it didn't insert the next request into the first one, but it seems like it still couldn't successfully read all the data from the message.

It still only seems to read part of the first response and then stops.

Logoutput:

Size: [24], Content: [01 03 3E 00 71 02 7B 00 04 00 ED 00 00 00 00 02 79 00 FF 00 7A 00 00 00 ]

Marked until which part of the message was read:

[SuGlider]

We have done a few updates to UART in the new Arduino Core 2.0.5 version.
There are new functions that may help your applications in getting "real-time serial.read()":

• void onReceive(OnReceiveCb function, bool onlyOnTimeout = false);
onReceive() will setup a callback that will be called whenever an UART interruption occurs (UART_INTR_RXFIFO_FULL or
  UART_INTR_RXFIFO_TOUT). This means that it is possible to set up a callback that will be executed as soon as data is
  received.
  UART_INTR_RXFIFO_FULL interrupt triggers at UART_FULL_THRESH_DEFAULT bytes received (defined as 120 bytes by
  default in IDF). This default value of 120 can be changed using setRxFIFOFull() with a value from 1 to 127.
  UART_INTR_RXFIFO_TOUT interrupt triggers at UART_TOUT_THRESH_DEFAULT symbols passed without any reception
  (defined as 2 symbols by default). This can also be changed with setRxTimeout()

  onlyOnTimeout parameter will define how onReceive will behave:
  true -- The callback will only be called when RX Timeout happens.
  Whole stream of bytes will be ready for being read on the callback function at once.
  This option may lead to Rx Overflow depending on the Rx Buffer Size and number of bytes received
  in the streaming
  Default: false -- The callback will be called when FIFO reaches RXFIFO_FULL bytes and also on RX Timeout.
  The stream of incommig bytes will be "split" into blocks of minimum RXFIFO_FULL bytes on each callback.
  This option avoids any sort of Rx Overflow, but leaves the UART packet reassembling work
  to the Application.

• void onReceiveError(OnReceiveErrorCb function);
onReceiveError() will be called on error events (see hardwareSerial_error_t) and it will also call the onReceive() callback in
  case some was defined. By this, it is possible to read data using onReceive() callback when a BREAK is sent to UART, for
  instance.

• void setRxTimeout(uint8_t symbols_timeout);
setRxTimeout() sets the timeout after which onReceive callback will be called (after receiving data, it waits for this time of UART rx inactivity to call the callback fnc)
  param symbols_timeout defines a timeout threshold in uart symbol periods.
  Setting 0 (zero) symbol timeout disables the callback call by timeout.
  Maximum timeout setting is calculacted automatically by IDF. If set above the maximum, it is ignored and an error is printed on Serial0 (check console).
  For example symbols_timeout=1 defines a timeout equal to transmission time of one symbol (~11 bit) on current baudrate.
  For a baudrate of 9600, SERIAL_8N1 (10 bit symbol) and symbols_timeout = 3, the timeout would be 3 / (9600 / 10) = 3.125 ms

• void setRxFIFOFull(uint8_t fifoBytes);
setRxFIFOFull() will set the number of bytes that will trigger UART_INTR_RXFIFO_FULL interrupt and fill up RxRingBuffer
  This affects some functions such as Serial::available() and Serial.read() because, in a UART flow of receiving data,
  Serial internal RxRingBuffer will be filled only after these number of bytes arrive or a RX Timeout happens.
  This parameter can be set to a low value, such as 1 in order to receive byte by byte, but it will also consume more
  CPU time as the ISR will be activated often.

[Miq1]

Excellent, thanks! I already deployed the setRxFIFOFull(() method to get the ISR trigger for each single byte and it works well for me.

[VojtechBartoska]

Please help testing this under 2.0.5 for feedback collection.

Next step is to create examples and update Documentation.

[SuGlider]

I have tested the changes from PR #6930 that adds HardwareSerial::setRxFIFOFull(uint8_t fifoBytes) API.
It solves this issue for sure. It allows Arduino to read byte by byte from UART as it is received.

The testing was done receiving 125 bytes to UART RX from an external device at 9600 baud.

Default Arduino 2.0.5 Behavior (after just using Serial.begin(9600)):

It will wait to receive 120 bytes before Serial.read() gets any data. The FIFO full default value is 120, thus filling up the Arduino Queue will happen after UART FIFO reaches 120 bytes.
Arduino gets 120 bytes in 126 ms. Each byte has about 10 bits (8 + parity bit + stop bit).
Therefore, it takes 1/9600 * 120 * 10 ~ 125ms for Arduino to read this first chunk of data...
And the remaining 5 bytes in 6 ms after previous event. About 1/900 * 6 * 10 = 6.25ms, in a second chunk of data.

This is not the Real Time desired behaviour.

Using setRxFIFOFull(1) to make each byte to be copied to the Arduino internal HardwareSerial buffer as soon as it gets to the UART:

It will get byte by byte the Serial.read() will get 1 byte every 1 ms at 9600 baud.
The time is 1/9600 x 10 ~1ms, per byte transmited.

This is exactly the Real Time requested behaviour on this issue.

In order to make it work just use this code snippet:

  Serial.begin(9600);
  Serial.setRxFIFOFull(1);