Closed chipweinberger closed 1 year ago
@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?
(_fflush_r
simply calls usb_serial_jtag_write
, which may or may not write all the requested bytes to the output.)
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.
Could you try increasing TX_FLUSH_TIMEOUT_US
Yes Ill give this a try.
(_fflush_r simply calls usb_serial_jtag_write, which may or may not write all the requested bytes to the output.)
Can you elaborate? or share the code?
Can you elaborate? or share the code?
Here is a backtrace I see if i set a breakpoint in usb_serial_jtag_write
after hitting a breakpoint in _fflush_r
:
(gdb) bt
#0 usb_serial_jtag_write (fd=0, data=0x3fc8cac8, size=13)
at /Users/ivan/e/esp-idf/components/vfs/vfs_usb_serial_jtag.c:141
#1 0x420056d2 in console_write (fd=<optimized out>, data=0x3fc8cac8, size=13)
at /Users/ivan/e/esp-idf/components/vfs/vfs_console.c:73
#2 0x42005246 in esp_vfs_write (r=0x3fc8ee34, fd=1, data=0x3fc8cac8, size=13)
at /Users/ivan/e/esp-idf/components/vfs/vfs.c:436
#3 0x42008f70 in __sflush_r (ptr=ptr@entry=0x3fc8ee34, fp=fp@entry=0x3fc8c884)
at /Users/brnomac003/.gitlab-runner/builds/qR2TxTby/0/idf/crosstool-NG/.build/riscv32-esp-elf/src/newlib/newlib/libc/stdio/fflush.c:224
#4 0x42008ffa in _fflush_r (ptr=ptr@entry=0x3fc8ee34, fp=fp@entry=0x3fc8c884)
at /Users/brnomac003/.gitlab-runner/builds/qR2TxTby/0/idf/crosstool-NG/.build/riscv32-esp-elf/src/newlib/newlib/libc/stdio/fflush.c:278
#5 0x420098ce in __sfvwrite_r (ptr=ptr@entry=0x3fc8ee34,
fp=fp@entry=0x3fc8c884, uio=uio@entry=0x3fc8ed34)
at /Users/brnomac003/.gitlab-runner/builds/qR2TxTby/0/idf/crosstool-NG/.build/riscv32-esp-elf/src/newlib/newlib/libc/stdio/fvwrite.c:251
#6 0x42009e18 in _puts_r (ptr=0x3fc8ee34, s=s@entry=0x1 "")
at /Users/brnomac003/.gitlab-runner/builds/qR2TxTby/0/idf/crosstool-NG/.build/riscv32-esp-elf/src/newlib/newlib/libc/stdio/puts.c:91
#7 0x42009e8e in puts (s=0x1 "", s@entry=0x3c025478 "Hello world!")
at /Users/brnomac003/.gitlab-runner/builds/qR2TxTby/0/idf/crosstool-NG/.build/riscv32-esp-elf/src/newlib/newlib/libc/stdio/puts.c:129
#8 0x42005dca in app_main ()
at /Users/ivan/e/esp-idf/examples/get-started/hello_world/main/hello_world_main.c:17
#9 0x42012676 in main_task (
args=<error reading variable: value has been optimized out>)
at /Users/ivan/e/esp-idf/components/freertos/app_startup.c:208
#10 0x403854d8 in vPortTaskWrapper (pxCode=<optimized out>,
pvParameters=<optimized out>)
at /Users/ivan/e/esp-idf/components/freertos/FreeRTOS-Kernel/portable/riscv/port.c:202
_fflush_r
and __sflush_r
are part of Newlib, you can find the code here. These functions don't deal with timeouts, the just call write
syscall (aliased to esp_vfs_write
) which in turn calls the write
function of the specific VFS driver. If anyone drops the bytes, that would be the VFS driver (in this case, usb_serial_jtag_write
function).
The USB Host polling rate is well below this afaik (like ~15ms), so this should only happen when USB is malfunctioning of unplugged.
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.
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.
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 usb_serial_jtag_bytes_dropped
counter is getting incremented. (I set a watchpoint on it using watch usb_serial_jtag_bytes_dropped
in GDB.)
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 printf
). I used Ctrl-T Ctrl-L in idf.py monitor to enable logging to file, and used this script to check the result.
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:
import serial
s = serial.Serial('/dev/cu.usbmodem1101', 460800)
while True:
line = s.readline().decode('utf-8')
print(line)
I'll add usb_serial_jtag_bytes_dropped++;
to my code and retest later today.
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:
# this calls get_security_info using esptool.py
jflashReboot.reboot(st)
console = serial.Serial()
console.baudrate = 460800
console.port = "/dev/cu.usbmodem101"
console.open()
i = 0
while True:
c = console.readline().decode('ascii', 'ignore')
print(" | " + c, end="")
c = c.replace("\r\n","")
if len(c) == 0:
continue
if "abcdefghijk" in c:
continue
parts = c.split(",")
val = int(parts[0])
if val != i:
print("fail " + c)
break
i = (i+1) % 1024
C:
void app_main(void)
{
vTaskDelay(100 * 3);
printf("\nabcdefghijk\n");
// repeatedly print numbers 0 to 1024
while (true) {
for(int i = 0; i < 1024; i++) {printf("%i,%i\n",i,usb_serial_jtag_bytes_dropped);}
vTaskDelay(1);
}
}
Python logs:
|
| abcdefghijk
| 0,97
| 1,97
| 2,97
| 3,97
| 4,97
| 5,97
| 6,97
| 7,97
As expected, we do drop some characters (97) in the beginning before python connects. But we never drop anymore (neither the usb_serial_jtag_bytes_dropped
variable, nor are numbers skipped in the log).
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 esp_rom_printf
for everything that needs to be reliable which is the workaround I've found for the bug when I was reproducing it.
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. Hope it can be of some help to anyone out there.
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?
because that code only work when console is registered.
Why is that?
Because usb_serial_jtag.c
is a file that we call it driver
part, it's only used in blocking mode, in idf, it's console. If you can see the code, who calls usb_serial_jtag_driver_install
is only esp_console_new_repl_usb_serial_jtag
non-blocking mode is handled in vfs_usb_serial_jtag.c
, I'm figuring out what happens.
BTW, may I know what computer(os) you're using? @chipweinberger
I use a Macbook pro, M1, MacOS 13.3.1 (22E261)
Because usb_serial_jtag.c is a file that we call it driver part, it's only used in blocking mode, in idf, it's console. If you can see the code, who calls usb_serial_jtag_driver_install is only esp_console_new_repl_usb_serial_jtag
That is a good insight. Yes, I was able to reproduce these issues without the console registered.
Original Issue: https://github.com/espressif/esp-idf/issues/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:
Actual output: ...
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.