ESP32C3M1: Serial.print() calls when not connected to USB cause delays.

[mahboud]

Board

ESP32C3M1

Device Description

Custom board:

Hardware Configuration

GPIO 18 & 19 are connected to USB. USB is used to program the device and to monitor Serial.print output.

Version

v2.0.3

IDE Name

Arduino

Operating System

MacOS 10.15.7

Flash frequency

40Mhz

PSRAM enabled

yes

Upload speed

115200

Description

USB is used to program the device and to monitor Serial.print output. However, when the device is unplugged, and the Serial.print() lines are left in the code, they cause delays of a second or so. Plugging back in will make the delays go away. If I remove the Serial.print() lines, it makes the delays disappear too.

Sketch

#include <Wire.h>
#include <Adafruit_NeoPixel.h>

#define LED_PIN 6
#define NEOPIXEL_PIN LED_PIN
Adafruit_NeoPixel pixels(1, NEOPIXEL_PIN, NEO_GRB + NEO_KHZ800);

void setup() {
  // put your setup code here, to run once:
  Serial.begin(115200);

}

void loop() {
  // put your main code here, to run repeatedly:

  pixels.begin();  // INITIALIZE NeoPixel strip object (REQUIRED)
  
  Serial.print("Red... ");
  // drawMessage("Test Red LED");
  pixels.setPixelColor(0, pixels.Color(64, 0, 0));
  pixels.show();
  delay(500);

    Serial.print("Green... ");
// drawMessage("Test Green LED");
  pixels.setPixelColor(0, pixels.Color(0, 64, 0));
  pixels.show();
  delay(500);

    Serial.print("Blue... ");
// drawMessage("Test Blue LED");
  pixels.setPixelColor(0, pixels.Color(0, 0, 64));
  pixels.show();
  delay(500);
  
    Serial.print("White... ");
// drawMessage("Test Whitish LED");
  pixels.setPixelColor(0, pixels.Color(64, 64, 64));
  pixels.show();
  delay(500);

  Serial.print("Off... ");
  pixels.clear();
  pixels.show();
  delay(500);
  Serial.println("Done. Looping");
}```

Debug Message

There is no debug or error message.

Other Steps to Reproduce

Run the sketch. While the device is plugged into a computer with Arduino, the lights flash faster. When you unplug the USB cable the lights slow down.

With more or longer Serial.print output, the delay can be more than a second.

That same code above is running on the two boards in this video. When you plug the USB in, you can see that the flash rate increases on the one plugged in.

IMG_7923.mov

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

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

[SuGlider]

Issue confirmed.

I Can see the issue using a ESP32-C3 DevKitM-1 v1.0.
I connected both USB CDC and UART ports to the PC.
Arduino IDE iis configured with USB CDC On Boot: "Enabled"
It's possible to see the output of Serial0 in the UART.

Note:

I see that the issue occurs even with the USB plugged in, but the IDE Monitor is on the UART port instrad of on the CDC, as we can see in the UART output. When the USB CDC Port isn't open, the issue occurs, independently is the USB is plugged or not.
The time spent on a loop goes from 2.5 seconds to 3.9 seconds after a few interactions.

If the skecth is uploaded with USB CDC On Boot: "Disabled", the issue doesn't happen, and the loop takes always 2.5 seconds.

This makes it clear that USB CDC has some issue when its buffer gets full and it is still closed or unplugged.

This is the sketch used:

#include <Wire.h>
#include <Adafruit_NeoPixel.h>

#define LED_PIN 8   //6
#define NEOPIXEL_PIN LED_PIN
Adafruit_NeoPixel pixels(1, NEOPIXEL_PIN, NEO_GRB + NEO_KHZ800);

void setup() {
  // put your setup code here, to run once:
  Serial.begin(115200);
  Serial0.begin(115200);

}

void loop() {
  // put your main code here, to run repeatedly:

  pixels.begin();  // INITIALIZE NeoPixel strip object (REQUIRED)

  uint32_t now = millis();

  Serial.print("Red... ");
  // drawMessage("Test Red LED");
  pixels.setPixelColor(0, pixels.Color(64, 0, 0));
  pixels.show();
  delay(500);

  Serial.print("Green... ");
  // drawMessage("Test Green LED");
  pixels.setPixelColor(0, pixels.Color(0, 64, 0));
  pixels.show();
  delay(500);

  Serial.print("Blue... ");
  // drawMessage("Test Blue LED");
  pixels.setPixelColor(0, pixels.Color(0, 0, 64));
  pixels.show();
  delay(500);

  Serial.print("White... ");
  // drawMessage("Test Whitish LED");
  pixels.setPixelColor(0, pixels.Color(64, 64, 64));
  pixels.show();
  delay(500);

  Serial.print("Off... ");
  pixels.clear();
  pixels.show();
  delay(500);
  Serial.println("Done. Looping");

  Serial0.printf("\n========================\nLoop time = %d\n", millis()-now);
}

UART OUPUT:

ESP-ROM:esp32c3-api1-20210207
Build:Feb  7 2021
rst:0x1 (POWERON),boot:0xc (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DOUT, clock div:1
load:0x3fcd6100,len:0x38c
load:0x403ce000,len:0x6ac
load:0x403d0000,len:0x24e4
SHA-256 comparison failed:
Calculated: 536dfe3b000041806b8028e5cb5125cd46736c37326abcaa489747c6c6fe4906
Expected: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
Attempting to boot anyway...
entry 0x403ce000

========================
Loop time = 2508

========================
Loop time = 2501

========================
Loop time = 2501

========================
Loop time = 2501

========================
Loop time = 2901

========================
Loop time = 3901

========================
Loop time = 3901

========================
Loop time = 3901

========================
Loop time = 3901

[markxoe]

The delay comes from the timeout here (I think)

To (temporarily) solve the problem we could use a check whether the USB is connected or not before every write to the USB...

To fix it even more temporarily you could use Serial.setTxTimeoutMs(10); to lower the blocking time

[egnor]

What do we think a good solution would be?

In my own code I attempted using

if (Serial) Serial.printf("blah blah\n");

which I thought would prevent the timeout (with the possible exception of a print in progress during disconnect, and/or log statements I have no control over). Reading HWCDC.cpp, it does seem like operator bool() is supposed to return whether the port is connected-- it returns initial_empty, which is set to true when the ESP-to-host buffer is empty and writable, and set to false when there's a bus reset. However, this didn't work... maybe those conditions don't exactly align with USB connected/disconnected (and the CDC device being opened/closed by the host).

In general doing a good race-free job of quickly skipping writes when nothing is reading them (but blocking when something is) seems a bit tricky?

[mahboud]

On Sep 6, 2022, at 10:32 PM, Daniel Egnor ***@***.***> wrote: In general doing a good race-free job of quickly skipping writes when nothing is reading them (but blocking when something is) seems a bit tricky?

I noticed this issue right away with my C3Mini custom board. I've never noticed it with any other ESP32 or Arduino. I assume that there is a fix that works for all those. My problem is that I can easily prevent the calling of Serial.print() in my code. But I have little control over all the libraries that do a lot of printing directly. This makes my program run quickly when attached to a Serial Monitor and over a minute slower, when not attached.

[egnor]

Anything with an offboard USB-serial converter won't have the problem, and something like the SAMD51 will be a completely different driver stack. As far as I can tell, all ESP32s which use the hardware USB-CDC implementation (as opposed to software USB -- but see #6762 (comment)) will use the same code and presumably have the same problem?

I actually recall having a similar problem with the SAMD51 and fixing it with judicious if (Serial) ... around my prints, which worked in that case (unlike with the ESP32).

My problem is that I can easily prevent the calling of Serial.print() in my code. But I have little control over all the libraries that do a lot of printing directly. This makes my program run quickly when attached to a Serial Monitor and over a minute slower, when not attached.

Agreed, the ESP32 ecosystem encourages subsystem logging. Which normally I enjoy! But not here. Would something like esp_log_level_set("*", ESP_LOG_ERROR); reduce the log chatter?

[SuGlider]

There is no API to know that the C3 is plugged or not to the USB.

It must be implemented in order to solve this issue.

[egnor]

There is no API to know that the C3 is plugged or not to the USB.
You mean at the ESP-IDF level? Or even the hardware register level? Bah. It looks like the code is sort of hoping that a "transmit empty" interrupt implies that USB is connected, and a "reset" event implies that it is disconnected, but... that doesn't seem to be actually reliable.

My ideal general-purpose console interface (as opposed to using a serial port for structured data transfer) would do this:

• use a relatively generous buffer size (2kb?)
• NEVER block a write call for I/O (whether or not USB is connected)
• If the buffer fills up, discard entire lines at a time (somehow) rather than taking fragments of a line
• After the buffer fills up and there is room again, add a print saying how many lines were dropped (*** 5 lines lost to console overflow ***)

The first two can be achieved with the existing interface, the others would require some work or a wrapper of some kind.

[SuGlider]

@mahboud @markxoe @egnor

I found a very simple As @markxoe said, the solution that solves the issue with the example Sketch used to demonstrate it:

void setup() {
  // put your setup code here, to run once:
  Serial.begin(115200);
  Serial.setTxTimeoutMs(0);   // <<<====== solves this issue of delay
}

[SuGlider]

At this point in time, Arduino only can tell when USB is just plugged and also replugged by using Events.
But it can't tell when USB is unplugged, once it was plugged first.

This limitation is in Hardware Level and for its register. Therefore, IDF can't help.

[egnor]

@SuGlider

Serial.setTxTimeoutMs(0); // <<<====== solves this issue of delay

That's indeed my current workaround but it's not great in a lot of cases because if the buffer fills during normal operation it drops everything. If you happen to have a burst of printout, it gets truncated, which can be very confusing to see in the output. (Also if two threads try to use the port at the same time-- more common than one might think due to logging from worker threads-- it completely skips the second write, since the timeout applies to mutex acquisition as well as buffer writing.)

This limitation is in Hardware Level and for its register. Therefore, IDF can't help.

[edit] I see. From the technical reference:

I actually think a reasonable timeout on USB buffer retrieval (which could be fairly short) would be more effective than a timeout on FIFO insertion. The USB-level timeout would detect port disconnect/closure/backpressure fairly quickly, at which point all FIFO data could be discarded until the buffer is finally emptied or the port reconnected.

FIFO level timeouts have the problem that they trigger either on USB disconnect/closure/backpressure or the FIFO filling from a burst write, even if USB is working perfectly. FIFO level timeouts also need to re-timeout for every write operation. FIFO level timeouts also have no obvious correct timeout level, since it depends on how much is being written.

There might still be some issues coming up with the appropriate USB-level timeout, but it would certainly be an improvement.

(Obviously, implementing this would be a bunch of work, so I'm not complaining that it's not top priority... and indeed a drop-everything timeout works for most general-console-logging cases... I still want my "*** X lines lost ***" message but I also want a pony and world peace so what/ever!)

[SuGlider]

@egnor

Serial.setTxTimeoutMs(0); // <<<====== solves this issue of delay

That's indeed my current workaround but it's not great in a lot of cases because if the buffer fills during normal operation it drops everything. If you happen to have a burst of printout, it gets truncated, which can be very confusing to see in the output. (Also if two threads try to use the port at the same time-- more common than one might think due to logging from worker threads-- it completely skips the second write, since the timeout applies to mutex acquisition as well as buffer writing.)

Yes, I agree it is not great, but even when it is plugged and the buffer is full, after the time out, it also drops all data.
Setting it to zero is specifically for the issue here presented.
Other normal operations, such as you are describing, should use default time out and treat when Serial.write() returns zero, indicating that it couldn't write because the buffer is full. Repeating the operation later on.
In case it can't write after a certain time, for instance, 5 seconds, the application can assume that USB is unplugged or that USB Host has some issue.

[SuGlider]

If necessary, it is possible to change RX or TX Buffer sizes. Default size for both is 256 bytes.
setRxBufferSize(size_t);
setTxBufferSize(size_t);

@egnor - The current Arduino driver already uses a software Rx/Tx buffer that is used to send/get data to/from USB CDC based on Interrupts generated by USB EndPoints. Therefore, the timeout is used to read/write from/to theses buffers.

[SuGlider]

@egnor

FIFO level timeouts have the problem that they trigger either on USB disconnect/closure/backpressure or the FIFO filling from a burst write, even if USB is working perfectly. FIFO level timeouts also need to re-timeout for every write operation. FIFO level timeouts also have no obvious correct timeout level, since it depends on how much is being written.

There might still be some issues coming up with the appropriate USB-level timeout, but it would certainly be an improvement.

Serial.setTimeout() Serial.setTxTimeoutMs() is related to the USB RX and TX Buffer, not FIFO.
Serial.write() will write to an intermediate buffer and then USB ISR will transfer data from TX buffer to EndPoints.
Therefore, the ESP32-C3 Arduino implementation for the CDC takes care of everything necessary.

[egnor]

@SuGlider

Serial.setTimeout() is related to the USB RX and TX Buffer, not FIFO. Serial.write() will write to an intermediate buffer and then USB ISR will transfer data from TX buffer to EndPoints. Therefore, the ESP32-C3 Arduino implementation for the CDC takes care of everything necessary.

Do you mean Serial.setTxTimeoutMs()? I can't find a Serial.setTimeout() in that code.

And Serial.setTxTimeoutMs() sets tx_timeout_ms which is used here:

            if(xRingbufferSend(tx_ring_buf, (void*) (buffer+so_far), max_size, tx_timeout_ms / portTICK_PERIOD_MS) != pdTRUE){
                size = so_far;
                break;
            }

This is specifically the timeout writing the FIFO, not USB RX and TX. (It's also used for some lock acquisition but I think that's incidental here.) Am I misreading the code? Or looking at the wrong code?

[SuGlider]

USB ISR will read asynchronously TX Buffer as it transmits the data, thus, the time out may help the buffering writing process, while it is done by Arduino or other task.
Remember also that ESP32 Arduino is Multitask and FreeRTOS based.

[SuGlider]

@mahboud - Please let me know if we can close this issue, once the specific solution to the issue you proposed is in
#6983 (comment)

[mahboud]

I'll give that a try later today. My custom boards, in production use, are never connected to USB (serial). They are only charged via USB. That's why having long delays added when USB serial isn't connected makes my device unusable. Removing the timeout may help. It may even be better if I could turn off Serial completely. Let me ask this: do the ESP_LOGE() and similar calls also go through the same path as Serial.print()? Some of the libraries I use call ESP_LOGE() and ESP_DRAM_LOGE(). mahboud

…

On Sep 8, 2022, at 6:54 PM, Rodrigo Garcia ***@***.***> wrote: @mahboud <https://github.com/mahboud> - Please let me know if we can close this issue, once the specific solution to the issue you proposed is in #6983 (comment) <#6983 (comment)> — Reply to this email directly, view it on GitHub <#6983 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAM4MB75FAWQXMQWIGXZJHDV5KKDZANCNFSM53RFG5UQ>. You are receiving this because you were mentioned.

[SuGlider]

@mahboud

It may even be better if I could turn off Serial completely.

It is possible. Do you build your application using Arduino IDE? There is an option in the IDE to turn off USB CDC.

Let me ask this: do the ESP_LOGE() and similar calls also go through the same path as Serial.print()? Some of the libraries I use call ESP_LOGE() and ESP_DRAM_LOGE().

No. ESP_LOGE()/ESP_DRAM_LOGE() are IDF calls that use other method.
ESP32 Arduino has log_e() which uses the same Arduino HardwareSerial structure as Serial.print()

[egnor]

@SuGlider

No. ESP_LOGE()/ESP_DRAM_LOGE() are IDF calls that use other method.
ESP32 Arduino has log_e() which uses the same Arduino HardwareSerial structure as Serial.print()

Are you sure? I thought this code redefined ESP_LOGE to use log_e:

arduino-esp32/cores/esp32/esp32-hal-log.h

Line 209 in 37cbaec

#define ESP_LOGE(tag, format, ...) log_e("[%s] " format, tag, ##__VA_ARGS__)

Note that you can turn off debug logging to the serial console with Serial.setDebugOutput(false), which may help you @mahboud.

[mahboud]

Both Serial.setDebugOutput(false); and Serial.setTxTimeoutMs(0); Work well to remove the delay I was experiencing. Thank you.

…

On Sep 8, 2022, at 6:54 PM, Rodrigo Garcia ***@***.***> wrote: @mahboud - Please let me know if we can close this issue, once the specific solution to the issue you proposed is in #6983 (comment) — Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you were mentioned.

[svdrummer]

Same issue on the S3

[SuGlider]

Confirmed on S3.

[svdrummer]

the T-DisplayS3 from TTGO.
error. i have not defined hardware serial include
class HardwareSerial' has no member named 'setTxTimeoutMs'; did you mean 'setRxTimeout'?

[iamcrawford]

Should be possible to monitor the 5V line to detect if there is a USB connection if running from a LiPo battery.

[SuGlider]

As said in #6983 (comment), a workaround is to do this:

void setup() {
  // put your setup code here, to run once:
  Serial.begin(115200);
  Serial.setTxTimeoutMs(0);   // <<<====== solves this issue of delay
}

[tshcherban]

Hi
I still have the same issue with board hang after serial monitor closed (ESP32-S3). However im using VS Code with arduino plugin.
With Arduino IDE (1.8) and its serial monitor it works fine.
Any ideas?

[beingflo]

If someone sees similar behavior while sending ESP Now messages, this could well be the culprit. I just managed to increase message throughput from 3 per second to 850 per second just by applying the suggested work-around.
Just mentioning it to make sure people find this.

[zalexzperez]

Hi
I still have the same issue with board hang after serial monitor closed (ESP32-S3). However im using VS Code with arduino plugin.
With Arduino IDE (1.8) and its serial monitor it works fine.
Any ideas?

Hi, did you manage to solve your problem?
I think I'm experiencing the same issue with my ESP32-S3 based custom board. In Arduino IDE I can reset the board and the serial monitor reconnects automatically.
However, in PlatformIO (VSCode), serial monitor does not reconnect upon resetting the board. I also tried with Putty and I get "Fatal error. Error reading from serial device" when resetting the board.

I tried with both USB-OTG and Hardware CDC USB modes.
USB CDC on boot enabled.

@SuGlider Are you familiar with the issue I'm describing?