[ESP32-S3] usb_serial_jtag printing skips bytes (IDFGH-9870) #11192
Comments
github-actions
bot
changed the title
|
@chipweinberger This is actually expected, since USB_SERIAL_JTAG driver will drop characters if the host is not picking them up fast enough. Could you try increasing TX_FLUSH_TIMEOUT_US in components/vfs/vfs_usb_serial_jtag.c and see if that makes any difference in your test? ( |
|
My understanding is there is subtlety. If the USB host "cannot keep up" then the usb device will send bytes slower. We will only drop bytes if the host picks up zero bytes for +50ms. The USB Host polling rate is well below this afaik (like ~15ms), so this should only happen when USB is malfunctioning or unplugged. Perhaps we should keep a counter of when we drop bytes to make this condition easier to debug (and log the state of this counter after usb transfers resume). This is otherwise tricky to notice it is happening, or why it happens.
Yes Ill give this a try.
Can you elaborate? or share the code? |
Here is a backtrace I see if i set a breakpoint in
I think in practice the serial port driver on the host also doesn't have an infinite buffer. If the application (monitor) doesn't fetch data from the driver fast enough, i think the driver will just not empty the USB endpoint buffer anymore once its own buffer becomes full. |
diff --git a/components/vfs/vfs_usb_serial_jtag.c b/components/vfs/vfs_usb_serial_jtag.c
index d17a2a4d6c..264035abec 100644
--- a/components/vfs/vfs_usb_serial_jtag.c
+++ b/components/vfs/vfs_usb_serial_jtag.c
@@ -101,6 +101,8 @@ static vfs_usb_serial_jtag_context_t s_ctx = {
.rx_func = usb_serial_jtag_rx_char
};
+static int usb_serial_jtag_bytes_dropped = 0;
+
static int usb_serial_jtag_open(const char * path, int flags, int mode)
{
s_ctx.non_blocking = ((flags & O_NONBLOCK) == O_NONBLOCK);
@@ -121,10 +123,10 @@ static void usb_serial_jtag_tx_char(int fd, int c)
if (usb_serial_jtag_ll_txfifo_writable()) {
usb_serial_jtag_ll_write_txfifo(&cc, 1);
s_ctx.last_tx_ts = esp_timer_get_time();
- break;
+ return;
}
} while ((esp_timer_get_time() - s_ctx.last_tx_ts) < TX_FLUSH_TIMEOUT_US);
-
+ usb_serial_jtag_bytes_dropped++;
}
static int usb_serial_jtag_rx_char(int fd)Adding a counter, and running the example you have attached, I definitely see that |
|
Thanks for your debugging effort, Ivan! So, perhaps you are right all along that I just need to increase TX_FLUSH_TIMEOUT_US. I imagine most people will want this increased as well! Any guess why esp_rom_printf does not repro? |
|
Actually, my previous test was on C3. After running your example on S3 I also can't reproduce the original issue anymore (with Unfortunately I don't have time now to try again on C3 and find the difference. If you have further findings in the meantime, please leave a comment, I'll take a look at this issue again later. Just to check, are you testing with CONFIG_ESP_CONSOLE_USB_SERIAL_JTAG=y or CONFIG_ESP_CONSOLE_SECONDARY_USB_SERIAL_JTAG=y. |
|
I'm using CONFIG_ESP_CONSOLE_SECONDARY_USB_SERIAL_JTAG=y |
|
I think I need to ask you for more detailed instructions to reproduce (including maybe the software you are using on the host to receive the serial output, your OS, etc.) I am not seeing this issue with ESP32-S3 even with CONFIG_ESP_CONSOLE_SECONDARY_USB_SERIAL_JTAG=y. |
|
Yes it does matter! Easiest to repro with (repros in ~4 seconds):
Hard to repro with (repros in ~30+ seconds):
Specs:
Python: |
|
I'll add |
|
So I have some bad news. I am not able to repro this issue on my current configuration, even when running the scripts for 15+ minutes:
Python: C: Python logs: As expected, we do drop some characters (97) in the beginning before python connects. But we never drop anymore (neither the I still would not feel comfortable calling this issue gone. I repro'd it recently on the config I mentioned earlier (maybe it was a macOS 12 bug?). But as for me, I cant be of much further assistance it seems until I can repro it again. And, I've already switched my code to |
|
We had a problem with dropped printf bytes using esp.isdf v5.0.1 (with some cherry-picked fixes from master) on an ESP32-S3. Here is the patch that fixes the problem we had. |
From b8902f24f9a2a5593a9fdaffe596b79936ceb794 Mon Sep 17 00:00:00 2001
From: michel <michel.benoit@tibber.com>
Date: Wed, 3 May 2023 18:39:41 +0200
Subject: [PATCH 1/2] usb_serial_jtag: Fix tx so that bytes are not lost when
the TX FIFO is busy
---
.../driver/usb_serial_jtag/usb_serial_jtag.c | 86 ++++++++++++++-----
components/vfs/vfs_usb_serial_jtag.c | 4 +
2 files changed, 69 insertions(+), 21 deletions(-)
diff --git a/components/driver/usb_serial_jtag/usb_serial_jtag.c b/components/driver/usb_serial_jtag/usb_serial_jtag.c
index 75e80e2cd4..e461e04bc9 100644
--- a/components/driver/usb_serial_jtag/usb_serial_jtag.c
+++ b/components/driver/usb_serial_jtag/usb_serial_jtag.c
@@ -6,6 +6,7 @@
#include <string.h>
#include <stdbool.h>
+#include <sys/param.h>
#include "esp_log.h"
#include "hal/usb_serial_jtag_ll.h"
#include "hal/usb_phy_ll.h"
@@ -22,26 +23,29 @@
#define USB_SER_JTAG_RX_MAX_SIZE (64)
typedef struct{
- intr_handle_t intr_handle; /*!< USB-SERIAL-JTAG interrupt handler */
+ intr_handle_t intr_handle; /*!< USB-SERIAL-JTAG interrupt handler */
// RX parameters
- RingbufHandle_t rx_ring_buf; /*!< RX ring buffer handler */
- uint32_t rx_buf_size; /*!< TX buffer size */
- uint8_t rx_data_buf[64]; /*!< Data buffer to stash FIFO data */
+ RingbufHandle_t rx_ring_buf; /*!< RX ring buffer handler */
+ uint32_t rx_buf_size; /*!< RX buffer size */
+ uint8_t rx_data_buf[USB_SER_JTAG_RX_MAX_SIZE]; /*!< Data buffer to stash RX FIFO data */
// TX parameters
- uint32_t tx_buf_size; /*!< TX buffer size */
- RingbufHandle_t tx_ring_buf; /*!< TX ring buffer handler */
+ uint32_t tx_buf_size; /*!< TX buffer size */
+ RingbufHandle_t tx_ring_buf; /*!< TX ring buffer handler */
+ uint8_t tx_data_buf[USB_SER_JTAG_ENDP_SIZE]; /*!< Data buffer to stash TX FIFO data */
+ size_t tx_stash_cnt; /*!< Number of stashed TX FIFO bytes */
} usb_serial_jtag_obj_t;
static usb_serial_jtag_obj_t *p_usb_serial_jtag_obj = NULL;
static const char* USB_SERIAL_JTAG_TAG = "usb_serial_jtag";
-static void usb_serial_jtag_write_and_flush(const uint8_t *buf, uint32_t wr_len)
+static int usb_serial_jtag_write_and_flush(const uint8_t *buf, uint32_t wr_len)
{
- usb_serial_jtag_ll_write_txfifo(buf, wr_len);
+ int size = usb_serial_jtag_ll_write_txfifo(buf, wr_len);
usb_serial_jtag_ll_txfifo_flush();
+ return size;
}
static void usb_serial_jtag_isr_handler_default(void *arg) {
@@ -52,17 +56,48 @@ static void usb_serial_jtag_isr_handler_default(void *arg) {
if (usbjtag_intr_status & USB_SERIAL_JTAG_INTR_SERIAL_IN_EMPTY) {
// Interrupt tells us the host picked up the data we sent. If we have more data, we can put it in the buffer and the host will pick that up next.
// Send data in isr.
+
+ // If the hardware fifo is avaliable, write in it. Otherwise, do nothing.
if (usb_serial_jtag_ll_txfifo_writable() == 1) {
// We disable the interrupt here so that the interrupt won't be triggered if there is no data to send.
usb_serial_jtag_ll_disable_intr_mask(USB_SERIAL_JTAG_INTR_SERIAL_IN_EMPTY);
size_t queued_size;
- uint8_t *queued_buff = (uint8_t *)xRingbufferReceiveUpToFromISR(p_usb_serial_jtag_obj->tx_ring_buf, &queued_size, 64);
- // If the hardware fifo is avaliable, write in it. Otherwise, do nothing.
- if (queued_buff != NULL) { //Although tx_queued_bytes may be larger than 0. We may have interrupt before xRingbufferSend() was called.
- //Copy the queued buffer into the TX FIFO
- usb_serial_jtag_ll_clr_intsts_mask(USB_SERIAL_JTAG_INTR_SERIAL_IN_EMPTY);
- usb_serial_jtag_write_and_flush(queued_buff, queued_size);
- vRingbufferReturnItemFromISR(p_usb_serial_jtag_obj->tx_ring_buf, queued_buff, &xTaskWoken);
+ uint8_t *queued_buff = NULL;
+ bool is_stashed_data = false;
+ if (p_usb_serial_jtag_obj->tx_stash_cnt != 0) {
+ // Send stashed tx bytes before reading bytes from ring buffer
+ queued_buff = p_usb_serial_jtag_obj->tx_data_buf;
+ queued_size = p_usb_serial_jtag_obj->tx_stash_cnt;
+ is_stashed_data = true;
+ }
+ else {
+ queued_buff = (uint8_t *)xRingbufferReceiveUpToFromISR(p_usb_serial_jtag_obj->tx_ring_buf, &queued_size, USB_SER_JTAG_ENDP_SIZE); // Max 64 data payload size in a single EndPoint
+ }
+
+ usb_serial_jtag_ll_clr_intsts_mask(USB_SERIAL_JTAG_INTR_SERIAL_IN_EMPTY);
+ if (queued_buff != NULL) { // Although tx_queued_bytes may be larger than 0. We may have interrupt before xRingbufferSend() was called.
+ // Copy the queued buffer into the TX FIFO
+
+ // On ringbuffer wrap-around the size can be 0 even though the buffer returned is not NULL
+ if (queued_size > 0) {
+ uint32_t sent_size = usb_serial_jtag_write_and_flush(queued_buff, queued_size);
+
+ if (sent_size < queued_size) {
+ // Not all bytes could be sent at once, stash the unwritten bytes in a tx buffer
+ size_t stash_size = MIN(USB_SER_JTAG_ENDP_SIZE, queued_size - sent_size);
+
+ // Copy the missed bytes to tx stash buffer. May copy from stash buffer to itself
+ memcpy(p_usb_serial_jtag_obj->tx_data_buf, &queued_buff[sent_size], stash_size);
+ p_usb_serial_jtag_obj->tx_stash_cnt = stash_size;
+ }
+ else {
+ p_usb_serial_jtag_obj->tx_stash_cnt = 0;
+ }
+ }
+ if (is_stashed_data == false) {
+ vRingbufferReturnItemFromISR(p_usb_serial_jtag_obj->tx_ring_buf, queued_buff, &xTaskWoken);
+ }
+
usb_serial_jtag_ll_ena_intr_mask(USB_SERIAL_JTAG_INTR_SERIAL_IN_EMPTY);
}
} else {
@@ -91,13 +126,14 @@ esp_err_t usb_serial_jtag_driver_install(usb_serial_jtag_driver_config_t *usb_se
ESP_RETURN_ON_FALSE((usb_serial_jtag_config->rx_buffer_size > USB_SER_JTAG_RX_MAX_SIZE), ESP_ERR_INVALID_ARG, USB_SERIAL_JTAG_TAG, "RX buffer prepared is so small, should larger than 64");
ESP_RETURN_ON_FALSE((usb_serial_jtag_config->tx_buffer_size > 0), ESP_ERR_INVALID_ARG, USB_SERIAL_JTAG_TAG, "TX buffer is not prepared");
p_usb_serial_jtag_obj = (usb_serial_jtag_obj_t*) heap_caps_calloc(1, sizeof(usb_serial_jtag_obj_t), MALLOC_CAP_INTERNAL|MALLOC_CAP_8BIT);
- p_usb_serial_jtag_obj->rx_buf_size = usb_serial_jtag_config->rx_buffer_size;
- p_usb_serial_jtag_obj->tx_buf_size = usb_serial_jtag_config->tx_buffer_size;
if (p_usb_serial_jtag_obj == NULL) {
ESP_LOGE(USB_SERIAL_JTAG_TAG, "memory allocate error");
err = ESP_ERR_NO_MEM;
goto _exit;
}
+ p_usb_serial_jtag_obj->rx_buf_size = usb_serial_jtag_config->rx_buffer_size;
+ p_usb_serial_jtag_obj->tx_buf_size = usb_serial_jtag_config->tx_buffer_size;
+ p_usb_serial_jtag_obj->tx_stash_cnt = 0;
p_usb_serial_jtag_obj->rx_ring_buf = xRingbufferCreate(p_usb_serial_jtag_obj->rx_buf_size, RINGBUF_TYPE_BYTEBUF);
if (p_usb_serial_jtag_obj->rx_ring_buf == NULL) {
@@ -161,12 +197,20 @@ int usb_serial_jtag_write_bytes(const void* src, size_t size, TickType_t ticks_t
ESP_RETURN_ON_FALSE(src != NULL, ESP_ERR_INVALID_ARG, USB_SERIAL_JTAG_TAG, "Invalid buffer pointer.");
ESP_RETURN_ON_FALSE(p_usb_serial_jtag_obj != NULL, ESP_ERR_INVALID_ARG, USB_SERIAL_JTAG_TAG, "The driver hasn't been initialized");
+ int ret_size = 0;
+
const uint8_t *buff = (const uint8_t *)src;
// Blocking method, Sending data to ringbuffer, and handle the data in ISR.
- xRingbufferSend(p_usb_serial_jtag_obj->tx_ring_buf, (void*) (buff), size, ticks_to_wait);
- // Now trigger the ISR to read data from the ring buffer.
- usb_serial_jtag_ll_ena_intr_mask(USB_SERIAL_JTAG_INTR_SERIAL_IN_EMPTY);
- return size;
+ BaseType_t data_sent = xRingbufferSend(p_usb_serial_jtag_obj->tx_ring_buf, (void*) (buff), size, ticks_to_wait);
+ if (data_sent == pdTRUE) {
+ // Now trigger the ISR to read data from the ring buffer.
+ usb_serial_jtag_ll_ena_intr_mask(USB_SERIAL_JTAG_INTR_SERIAL_IN_EMPTY);
+ ret_size = size;
+ }
+ else {
+ ret_size = 0;
+ }
+ return ret_size;
}
esp_err_t usb_serial_jtag_driver_uninstall(void)
diff --git a/components/vfs/vfs_usb_serial_jtag.c b/components/vfs/vfs_usb_serial_jtag.c
index 51a089dd05..0f45f56b0f 100644
--- a/components/vfs/vfs_usb_serial_jtag.c
+++ b/components/vfs/vfs_usb_serial_jtag.c
@@ -407,11 +407,15 @@ static void usbjtag_tx_char_via_driver(int fd, int c)
{
char ch = (char) c;
TickType_t ticks = (TX_FLUSH_TIMEOUT_US / 1000) / portTICK_PERIOD_MS;
+
+ // Will return immediately if the driver is blocked because there is no USB connection
if (usb_serial_jtag_write_bytes(&ch, 1, 0) != 0) {
s_ctx.tx_tried_blocking = false;
return;
}
+ // If the last attempt with blocking write failed do not block again until
+ // a non-blocking write suceeds
if (s_ctx.tx_tried_blocking == false) {
if (usb_serial_jtag_write_bytes(&ch, 1, ticks) != 0) {
return;
--
2.34.1 |
|
I've put your changes into a PR: https://github.com/espressif/esp-idf/pull/11344/files @mbenoitTibber, could you describe the solution more? What was the issue? |
|
May I leave some comments here?
|
Why is that? |
|
Because non-blocking mode is handled in |
|
BTW, may I know what computer(os) you're using? @chipweinberger |
|
I use a Macbook pro, M1, MacOS 13.3.1 (22E261)
That is a good insight. Yes, I was able to reproduce these issues without the console registered. |
…e data randomly, Closes espressif#12119, Closes espressif#11344, Closes espressif#9318 Closes espressif#11192
espressif-bot
added
Resolution: Done
Original Issue: #9318
Making a new issue to get more eyes on this and to summarize the issue.
IDF version.
v4.4.4
Development Kit.
ESP32-S3 Dev Kit C
What is the expected behavior?
printf should log all the characters, even when using usb_serial_jtag.
What is the actual behavior?
characters are skipped when using USB Serial JTAG, sometimes
Steps to reproduce.
Expected output:
> 0,0
> 0,1
> 0,2
...
> 0,10238
> 0,10239
> 1,0
> 1,1
> 1,2
...
Actual output:
...
> 0,2372
> 0,2373
> 0,6250
> 0,6251
More Information.
I've likely figured it out.
The skipping character problem only repros with printf & putc. It does not repro with uart_tx_char directly, or esp_rom_printf.
printf & putc are both buffered. They write to an internal buffer, and then flush when the buffer is full, or a newline is hit.
My guess is that _fflush_r is buggy. It's not waiting long enough to actually flush the data, and therefor we are printing faster than we actually can, and skipping bytes.
fflush is implemented in ROM only. PROVIDE( _fflush_r = 0x4000150c ); I don't have the source code for it. I think fflush just needs to wait on some registers in both UART and USB Serial JTAG peripherals before returning.
The text was updated successfully, but these errors were encountered: