uart deadlock while using automatic light sleep (IDFGH-11870)

[tshcherban]

Answers checklist.

• I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v5.3-dev-1353-gb3f7e2c8a4
v5.2-beta1-263-ge49823f10c
v4.4.6-374-gbb8dd9d35b

Espressif SoC revision.

ESP32-S3 (QFN56) (rev v0.1)
ESP32-D0WD-V3 (rev v3.1)
ESP32-C3 (QFN32) (rev v0.3)

Operating System used.

Windows

How did you build your project?

VS Code IDE

If you are using Windows, please specify command line type.

PowerShell

Development Kit.

ESP32-S3/C3 DevKits
Wemos D1-Mini ESP32
ESP32/S3 custom boards

Power Supply used.

External 3.3V, USB (irrelevant)

What is the expected behavior?

Uart is working with automatic light sleep enabled

What is the actual behavior?

Uart locks indefinitely with automatic light sleep enabled

Steps to reproduce.

app main:

#include "driver/uart.h"
#include "esp_pm.h"
#include "esp_timer.h"
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
#include "hal/uart_types.h"

const uart_port_t uart_nr = (uart_port_t)0;
const int rx_buffer_size = 256;
const int tx_buffer_size = 0;
const int queue_size = 20;
const int baud_rate = 115200;
const int rx_flow_ctrl_thresh = 112; // value taken from arduino core

QueueHandle_t uart_event_queue;

extern "C" void app_main()
{
    uart_config_t uart_config;
    uart_config.data_bits = uart_word_length_t::UART_DATA_8_BITS;
    uart_config.parity = uart_parity_t::UART_PARITY_DISABLE;
    uart_config.stop_bits = uart_stop_bits_t::UART_STOP_BITS_1;
    uart_config.flow_ctrl = uart_hw_flowcontrol_t::UART_HW_FLOWCTRL_DISABLE;
    uart_config.rx_flow_ctrl_thresh = rx_flow_ctrl_thresh;
    uart_config.baud_rate = baud_rate;
    uart_config.source_clk = UART_SCLK_DEFAULT;

    ESP_ERROR_CHECK(uart_driver_install(uart_nr, rx_buffer_size, tx_buffer_size, queue_size, &uart_event_queue, 0));
    ESP_ERROR_CHECK(uart_param_config(uart_nr, &uart_config));

    esp_pm_config_t pm_config = {
        .max_freq_mhz = 160,
        .min_freq_mhz = 160,
        .light_sleep_enable = true,
    };

    ESP_ERROR_CHECK(esp_pm_configure(&pm_config));

    uart_wait_tx_idle_polling(uart_nr);

    while (true)
    {
        char buf[1024];
        int size = sprintf(buf, "Time from boot: %lld\n", (esp_timer_get_time() / 1000ULL));

        uart_write_bytes(uart_nr, buf, size);
        // uart_wait_tx_idle_polling(uart_nr);

        vTaskDelay(1000 / portTICK_PERIOD_MS);
    }
}

sdkconfig

CONFIG_PM_ENABLE=y
CONFIG_FREERTOS_HZ=1000
CONFIG_FREERTOS_USE_TICKLESS_IDLE=y

Debug Logs.

ESP-ROM:esp32c3-api1-20210207
Build:Feb  7 2021
rst:0x1 (POWERON),boot:0xc (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fcd5820,len:0x1714
load:0x403cc710,len:0x968
load:0x403ce710,len:0x2f9c
entry 0x403cc710
I (30) boot: ESP-IDF v5.1.2-602-gdb1e54a0c5 2nd stage bootloader
I (30) boot: compile time Jan 10 2024 19:56:27
I (31) boot: chip revision: v0.3
I (35) boot.esp32c3: SPI Speed      : 80MHz
I (39) boot.esp32c3: SPI Mode       : DIO
I (44) boot.esp32c3: SPI Flash Size : 2MB
I (49) boot: Enabling RNG early entropy source...
I (54) boot: Partition Table:
I (58) boot: ## Label            Usage          Type ST Offset   Length
I (65) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (73) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (80) boot:  2 factory          factory app      00 00 00010000 00100000
I (87) boot: End of partition table
I (92) esp_image: segment 0: paddr=00010020 vaddr=3c020020 size=09d40h ( 40256) map
I (107) esp_image: segment 1: paddr=00019d68 vaddr=3fc8d600 size=011d8h (  4568) load
I (109) esp_image: segment 2: paddr=0001af48 vaddr=40380000 size=050d0h ( 20688) load
I (121) esp_image: segment 3: paddr=00020020 vaddr=42000020 size=1b1b0h (111024) map
I (143) esp_image: segment 4: paddr=0003b1d8 vaddr=403850d0 size=084c8h ( 33992) load
I (150) esp_image: segment 5: paddr=000436a8 vaddr=50000010 size=00004h (     4) load
I (154) boot: Loaded app from partition at offset 0x10000
I (155) boot: Disabling RNG early entropy source...
I (172) cpu_start: Unicore app
I (172) cpu_start: Pro cpu up.
I (181) cpu_start: Pro cpu start user code
I (181) cpu_start: cpu freq: 160000000 Hz
I (181) cpu_start: Application information:
I (184) cpu_start: Project name:     uart-lightsleep-deadlock
I (190) cpu_start: App version:      5a04b5d-dirty
I (196) cpu_start: Compile time:     Jan 10 2024 19:56:11
I (202) cpu_start: ELF file SHA256:  788c280a5ec37e35...
I (208) cpu_start: ESP-IDF:          v5.1.2-602-gdb1e54a0c5
I (214) cpu_start: Min chip rev:     v0.3
I (219) cpu_start: Max chip rev:     v1.99 
I (224) cpu_start: Chip rev:         v0.3
I (228) heap_init: Initializing. RAM available for dynamic allocation:
I (236) heap_init: At 3FC8F6E0 len 00030920 (194 KiB): DRAM
I (242) heap_init: At 3FCC0000 len 0001C710 (113 KiB): DRAM/RETENTION
I (249) heap_init: At 3FCDC710 len 00002950 (10 KiB): DRAM/RETENTION/STACK
I (256) heap_init: At 50000014 len 00001FD4 (7 KiB): RTCRAM
I (264) spi_flash: detected chip: generic
I (267) spi_flash: flash io: dio
W (271) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (285) sleep: Configure to isolate all GPIO pins in sleep state
I (291) sleep: Enable automatic switching of GPIO sleep configuration
I (310) app_start: Starting scheduler on CPU0
I (310) main_]�I (316) pm: Frequency switching config: CPU_MAX: 160, APB_MAX: 160, APB_MIN: 160, Light sleep: ENABLED
Time from boot: 327
Time from boot: 132

More Information.

A problem seems to be in the uart.c line 1202:

        while (size) {
            //semaphore for tx_fifo available
1202 >>  if (pdTRUE == xSemaphoreTake(p_uart_obj[uart_num]->tx_fifo_sem, (TickType_t)portMAX_DELAY)) { <<<<
                uint32_t sent = uart_enable_tx_write_fifo(uart_num, (const uint8_t *) src, size);
                if (sent < size) {
                    p_uart_obj[uart_num]->tx_waiting_fifo = true;
                    uart_enable_tx_intr(uart_num, 1, UART_EMPTY_THRESH_DEFAULT);
                }
                size -= sent;
                src += sent;
            }
        }

cyclic xSemaphoreTake(p_uart_obj[uart_num]->tx_fifo_sem, with indefinite timeout. It obtains the lock, and on the next iteration tries to obtain it again and eventually hangs forever.
I've moved that xSemaphoreTake before while - and it started working as expected (on all three CPUs). However im not sure if this would be correct, because if we should wait for some ISR to happen - maybe lightsleep prevents this interrupt from trigger?

[tshcherban]

Taking into account Sleep Modes: UART Output Handling and available UART wakeup sources (TX detection), probably better solution might be wrapping that while loop with a esp_pm_lock_acquire and esp_pm_lock_release with a ESP_PM_NO_LIGHT_SLEEP lock type. Such kind of a fix also works as expected.

[songruo]

@tshcherban You are right! We are aware of this issue, the MR to add the PM lock to UART driver is under internal review.

[tshcherban]

@songruo can i help in any way with it? (some testing etc)

[AxelLin]

@tshcherban You are right! We are aware of this issue, the MR to add the PM lock to UART driver is under internal review.

@songruo
It has been 3 Months since your last reply.How is the status now?

[AxelLin]

@tshcherban You are right! We are aware of this issue, the MR to add the PM lock to UART driver is under internal review.

@songruo It has been 3 Months since your last reply.How is the status now?

@songruo Are you still working on this issue? Or someone else will help to fix it?
@igrr

[AxelLin]

@tshcherban You are right! We are aware of this issue, the MR to add the PM lock to UART driver is under internal review.

@songruo When will this get fixed?