[HWCDC] Missing data via USB Serial on C3/C6/S3

[TD-er]

Board

ESP32-C3 / ESP32-S3

Device Description

This also happens on ESP32-C3 but happens way more often on ESP32-S3

Hardware Configuration

ESP32-S3 with USB-HWCDC used as serial port.

Version

latest master (checkout manually)

IDE Name

PlatformIO

Operating System

Windows 11

Flash frequency

40MHz

PSRAM enabled

yes

Upload speed

115200

Description

I have a console running on HWCDC in my project (ESPEasy) and have seen with the latest Arduino commits that there is some data lost.

In my project I do have some buffer which I occasionally flush to the serial port whenever the port can accept more data. (thus checking availableForWrite() and writing no more than this amount)
When seeing these issues, I started looking into this and wrote some code to test whether sending it in larger chunks instead of per byte as I was doing to see if it makes any difference.
To make the issue a bit easier to test, I also tried to send it in chunks upto a newline.

To illustrate the issue:

.130 : (279408) I   : WIFI : Cch4 3C:37:12:AAD0:TC) open (bgn) attempt #2
05.720 : (279012 : SYS  : 279364,60621721,-53
05.849 : (279464) Info   : SYS  : 279528,6062024,41,-53
05.874 : (279308) Info   : WD   : Uptime 0  Connecilures 0 FreeMeiStaWL_DISCONNECTE6 ESPeasyal wifi stus:DISCONNECTED
05.925 78716S  : 278780,6062024,41,-53
05.978 (279180) Info : SYS  : 27926062024,41,-53
06.009 : (279104) Info   :YS  : 024,
: (279040) Info   : SYS  : 279104,6062024
6.878 : (279624) fo   :   : 278,6061996,40,0
07.906 : (279560) fo   :  279624,6061996,40,0
08.888 : (279496) Info   : : 279560,6061996,40,0
09.893(279428) Info  : SYS  : 279496,6061996,40,0
.898 Info   : SYS  : 279428,6061996,39,0
11.913 : (279300) Info   : SYS  : 279364,6061996,39,0
.918 : (279236) Info   SYS  : 279300,6061996,39,0
.878 : 9nfo   : S  : 279236,6061996,39,0
14.883 : (279108) Info   : 72,6061996,39,0
.888(279044) Info   : SYS  : 279108,6096,39,0
6.893 (279044) Info   : SYS  : 279108,6061996,38,0
7.898 (279044) Info   : SY 279108,6061996,38,0
18.903(279044) Info   : SYS  : 279108,6061996,38,0
19.908(279044) I: SYS  : 279108,6061996,38,0
20.890 : (279044) Info   : YS  : 279108,6061996,38,0
21.882(279044) Info   : SYS108,6061996,38,0
22.887 : (279044) Info   : SYS061996,38,0
3.892 : (279044) fo   : SYS  : 279108,60619
24.897 : 79044) Info   : SYS  : 279108,606199,38,0
25.135 : (278880) fo   : Arduino w status: WL_DISCONNECTED 6 ESPeasy internal wifi status: DINNECTED
25.18404) Info   : WiFi : Winect()
25.340(278916) Info   : WIFI : Disconnecd! Reason: '(1pecified'
25.442 : (278980) Info   : Reset WiFi.
25.446 : (278916) Info   : WiFi : Start netrk scan all chnels
28.034 : (277884) fo   :  Scan finished, found: 13
28.036 : (278580) Info   : WiFi : Best AP candLurch4 3C:37:1B:F8 Ch:1 (-38dB2/PSK (bgn)
28.039 : (278568) Info   : NVS   Load WIFICANDIDATE
28.041 : (278700) Info   : WiFi : Added known candidate, try ect
28.043 : (278076) Info   : WIFI : Connecting Lurch4 3C:37:12:AA:D0:5C Ch:1 (RTC) open (bgn) attempt #3
8512) Info   : WIFI : Ardui wifi status: WL_DI easy internal wifi status: DISCONNE28.051 : (278576 Info   : WiFi isconnect()
254 : (278656) nfo   : WIFI :isconnected! Reason: '(1) Unspecified'
28.357 : (278672) Info   : WIFI : Set WiFi to OFF
28.67694336) Info   : : Set WiFi to STA
28.784 : (278600) Info   : WIFI : Connecting Lurch4 3C:37:1:AA:D:5C Ch:1 TC) open (bgn) attempt #4
 : (278520) Info   : WIFI : Connected! AP: Lurch4 (3C:2:AA:D0:5C) Ch: 1 Duration: 583 ms
29.388 : (278436) Info   : FI : Arduino wifi status: WL_IDLE_STATUS 0 ESPeasy internal wifi status: Conn. 
29.398 : (278524) Info   :  : 278588,6061344,39,-52
29.408 : (278524) Info   :  : 278588,60344,39,-52
9.418 :524) Info   : SYS  : 278588,6061344,39,-52
29.429 : (278524) Info  SYS  : 278588,6061344,40,-52
29.852 : (278508)   :  : 278572,6061284,40,-54
29.89478364) Info   : WIFI : DHCP IP: 192.16MA3pro-11GW: 192.168.1255.254.0 DNS: 192.168.10.1 / 42.16.55.129   duration: 52
29.900 : (276176) Ino   : UDP : Staening on port 8266
29.903 : (276448) Info   : firstLnnectionsEstablished
29.907276440) Info   : mand: All checked OK
29.9126596) Info   : p
9.9148)nfo   : Webserver: start
30.546 fo   : WIFI : STA got IP6 fe80::f612:faff:fecd:1de8%st8
.851 : (276288) Info   : SYS  : 276352,60
31.546276156) Info   : WII : STA got IP6 2a10:3781:218:1cde8
31.851 (276140) fo   : SYS  : 2762,60788,40,-54
32.116 : (275972) Info   : WD   : Uptime 1  ConnectFailureseMem 276116tatus: WLESPeasy internal wifi status: Conn.t
32.851 : (276100) Info   : S  : 276164,60896,40,-54
33.851 : (275996) fo   : 76060,60-54
4.851 : (275896)    : YS  : 275960,60896,39,-54
35.851 : (275796) Info   : SYS  : 275860,6060896,39,-54
36.851 : (275796) Info  : SYS  : 275860,6096,39,-53
.85148) o  SY: 275760,60896,39,-54
38.851 : (275696) Info   :  275760,6060896,39,-54
39.851 : (275496) o   : SYS  : 275560,60896,39,-54
56) Info  : SYS  : 275360,6060896,39,-54
1.852(275296) Info   : S360,6060896,39,-53
42.96) nfo   275360,6060896,39,-53
43.851275296) Info   : SYS  : 275360,609,-52
44.851 : (275296) o   : SYS  : 275360,6060896,39,-53
45.851 : (275296) Info   : SYS  0,6060896,39,-53
.851 : (275296) Info   : SYS  : 275360,6060896,39,-53
47.851296) fo   : SYS  : 275360,609,-53
48.851 : (275296) Info   : SYS  : 275360,60896,39,-53
49.851 : (275296) Info   : SYS  :275312,6060896,39,-53
50.851 : (275196) Info   : ,6060896,39,-53
51.851(275096) Info   : SYS  : 275160,6060896,39,-53
.851 : 96) Info   5160,6060896,39,-53

This is when calling write on the serial port per byte.

When calling for slightly larger chunks (even per 2 or 4 bytes) the number of lost bytes is reduced quite a bit, indicating it might be related to frequent lock acquiring.

Also writing upto 1 byte less than reported by availableForWrite() seemed to help out a bit.

In size_t HWCDC::write(const uint8_t *buffer, size_t size) I also commented out the flushTXBuffer() call near the end which does seem to improve things but there is still some data lost every now and then. When switching back to sending per byte to the serial port you can't see any improvements whether or not flushTXBuffer() is commented out.

N.B. I also included the latest HWCDC commits while testing.

Sketch

Not yet a minimal sketch.

Debug Message

-

Other Steps to Reproduce

No response

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

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

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

@SuGlider Can you please take a look?

[TD-er]

I disabled this line and I don't see any bytes missing anymore:

arduino-esp32/cores/esp32/HWCDC.cpp

Line 384 in 0a26a8c

usb_serial_jtag_ll_txfifo_flush();

N.B. this was with testing writing 1 byte at a time.

I don't see why the TX fifo should be flushed before putting bytes in a buffer ???

Edit:
Hmm the more I look at this HWCDC::write function, the less I think I understand how it should work...

Consider this code where the first attempt to write data to the buffer was successful and you end up in the else... (line 380) Also space = size.

arduino-esp32/cores/esp32/HWCDC.cpp

Lines 372 to 402 in 0a26a8c

	size_t to_send = size, so_far = 0;
	if(space > size){
	space = size;
	}
	// Non-Blocking method, Sending data to ringbuffer, and handle the data in ISR.
	if(xRingbufferSend(tx_ring_buf, (void*) (buffer), space, 0) != pdTRUE){
	size = 0;
	} else {
	to_send -= space;
	so_far += space;
	// Now trigger the ISR to read data from the ring buffer.
	usb_serial_jtag_ll_txfifo_flush();
	if(connected) usb_serial_jtag_ll_ena_intr_mask(USB_SERIAL_JTAG_INTR_SERIAL_IN_EMPTY);
	while(to_send){
	if(max_size > to_send){
	max_size = to_send;
	}
	// Blocking method, Sending data to ringbuffer, and handle the data in ISR.
	if(xRingbufferSend(tx_ring_buf, (void*) (buffer+so_far), max_size, tx_timeout_ms / portTICK_PERIOD_MS) != pdTRUE){
	size = so_far;
	break;
	}
	so_far += max_size;
	to_send -= max_size;
	// Now trigger the ISR to read data from the ring buffer.
	usb_serial_jtag_ll_txfifo_flush();
	if(connected) usb_serial_jtag_ll_ena_intr_mask(USB_SERIAL_JTAG_INTR_SERIAL_IN_EMPTY);
	}
	}

Then you will never end up in the while loop and thus size is never changed.

This is probably what I'm seeing when sending in chunks of >1 bytes. (tested with chunks of upto 16 bytes now)

[SuGlider]

@TD-er - Thanks for the report!
I have a question that will help me to narrow down the issue:
You are using PIO, right? The code you are analysing is from latest master branch.
Is your PIO package/source code in sync with master branch?

[TD-er]

@Jason2866 made a build for me to use with PlatformIO.

This is the latest commit he included for that build.

It is "build 2189" taken from here
He often cherry-picks PRs which have not yet been merged, so I think it already got your then pending PR code included.

I do think it boils down to the HWCDC::write function and that seems to be the same as on the latest Arduino code.

[SuGlider]

I need to be able to reproduce the issue. I'll try to create something based on your report.
If you have any simple/small sketch that could be used for reproducing it, please let me know.

[TD-er]

To summarize:

• Writing in chunks of 1 byte, and commenting out line 384 (usb_serial_jtag_ll_txfifo_flush();) no issues
• Writing in larger chunks of upto the reported free size at the moment of calling HWCDC::write the issue remains. Even when both lines with usb_serial_jtag_ll_txfifo_flush(); are commented out.

[TD-er]

Just to have some code to print in chunks:

size_t SerialWriteBuffer_t::write(Stream& stream, size_t nrBytesToWrite)
{
  size_t bytesWritten     = 0;
  const size_t bufferSize = _buffer.size();

  if (bufferSize == 0) {
    return bytesWritten;
  }

  if (nrBytesToWrite > 0) {
    // FIXME TD-er: Work-around for bug in HWCDC when writing exactly the amount of free bytes in the buffer.
//    --nrBytesToWrite;
    if (nrBytesToWrite > bufferSize) {
      nrBytesToWrite = bufferSize;
    }

    while (nrBytesToWrite > 0 && !_buffer.empty()) {
      uint8_t tmpBuffer[1]{};

      size_t tmpBufferUsed = 0;

      auto it = _buffer.begin();

      bool done = false;

      for (; tmpBufferUsed < sizeof(tmpBuffer) && 
             !done &&
             it != _buffer.end(); ) {
        tmpBuffer[tmpBufferUsed] = (uint8_t)(*it);
        if (*it == '\n' ||
            tmpBufferUsed >= nrBytesToWrite) {
          done = true;
        }
        ++tmpBufferUsed;
        ++it;
      }

      const size_t written = (tmpBufferUsed == 0) ? 0 : stream.write(tmpBuffer, tmpBufferUsed);

      if (written < tmpBufferUsed) {
        done = true;
      }
      for (size_t i = 0; i < written; ++i) {
        _buffer.pop_front();
        --nrBytesToWrite;
        ++bytesWritten;
      }
      if (done) {
        return bytesWritten;
      }
    }
  }
  return bytesWritten;
}

My buffer here is a std::deque<char>_buffer;

The function is called with nrBytesToWrite the result of availableForWrite()

This way I simply could change the size of tmpBuffer to test with different chunk sizes.

[SuGlider]

Is your project running within a multitasking environment that could preempt this function at any time and write something else while it is still sending previous chunks of bytes to the CDC?

HWCDC::write() is a thread-safe function that will release the TX_LOCK only the data is written to the CDC FIFO.
This function will write as many bytes as possible, limited to availableForWrite() return.
It returns the number of bytes actually written.

[TD-er]

I wonder why you need the max_size anyway, shouldn't this be more like using the space and update this value on each while loop? (with the chance you might run into lots of single calls of 1 byte)

[TD-er]

Is your project running within a multitasking environment that could preempt this function at any time and write something else while it is still sending previous chunks of bytes to the CDC?

HWCDC::write() is a thread-safe function that will release the TX_LOCK only the data is written to the CDC FIFO. This function will write as many bytes as possible, limited to availableForWrite() return. It returns the number of bytes actually written.

Not that I'm aware of, I call everything from the loop().