Description
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.
Metadata
Metadata
Assignees
Type
Projects
Status
Activity
P-R-O-C-H-Y commentedon Mar 15, 2024
@SuGlider Can you please take a look?
TD-er commentedon Mar 15, 2024
I disabled this line and I don't see any bytes missing anymore:
arduino-esp32/cores/esp32/HWCDC.cpp
Line 384 in 0a26a8c
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
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 commentedon Mar 15, 2024
@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 commentedon Mar 15, 2024
@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 commentedon Mar 15, 2024
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 commentedon Mar 15, 2024
To summarize:
usb_serial_jtag_ll_txfifo_flush();
) no issuesHWCDC::write
the issue remains. Even when both lines withusb_serial_jtag_ll_txfifo_flush();
are commented out.TD-er commentedon Mar 15, 2024
Just to have some code to print in chunks:
My buffer here is a
std::deque<char>_buffer;
The function is called with
nrBytesToWrite
the result ofavailableForWrite()
This way I simply could change the size of
tmpBuffer
to test with different chunk sizes.SuGlider commentedon Mar 15, 2024
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 commentedon Mar 15, 2024
I wonder why you need the
max_size
anyway, shouldn't this be more like using thespace
and update this value on each while loop? (with the chance you might run into lots of single calls of 1 byte)TD-er commentedon Mar 15, 2024
Not that I'm aware of, I call everything from the
loop()
.91 remaining items