Apparent race condition in ledc (IDFGH-5565)

[acf-bwl]

Environment

• Development Kit: Lolin D32 (non-espressif tool)
• Kit version (for WroverKit/PicoKit/DevKitC): N/A
• Module or chip used: ESP32-WROOM32
• IDF version (run git describe --tags to find it): v4.3 and v4.4-dev-2184-g166c30e7b2 (master at the time of this submission)
• Build System: idf.py / cmake
• Compiler version (run xtensa-esp32-elf-gcc --version to find it):
  when building on v4.3: xtensa-esp32-elf-gcc (crosstool-NG esp-2020r3) 8.4.0
  when building on v4.4-dev-2184-g166c30e7b2: xtensa-esp32-elf-gcc (crosstool-NG esp-2021r1) 8.4.0
• Operating System: Windows 10 x86_64
• (Windows only) environment type: esp-idf Command Prompt
• Using an IDE?: No
• Power Supply: USB

Problem Description

In certain specific cases, the esp-idf ledc driver fails to apply values set with ledc_set_duty and ledc_update_duty. In these cases, the PWM duty cycles set are neither visible on an oscilloscope, nor correctly reported by a call to ledc_get_duty. Inserting a small ets_delay_us resolves the problem. The example code provided below should reproduce this problem on esp-idf v4.3 and v4.4-dev-2184-g166c30e7b2 (master at the time of this submission). Please use the provided sdkconfig, or ensure the optimization level is set to -O2 when attempting to reproduce.

GitHub does not allow attaching of .elf files or files with no extension (ie, sdkconfig), so I have uploaded a zip of the entire project directory. It is contains the build directory with the elf, and is otherwise ready for "idf.py build" and "idf.py flash" with the current esp-idf master (v4.4-dev-2184-g166c30e7b2).

Expected Behavior

A PWM signal corresponding to the set value appears on pin 26 regardless of the ets_delay_us(). All four calls to ledc_get_duty() return six.

Actual Behavior

No PWM signal appears on pin 26 unless the ets_delay_us() line is uncommented. The first of two pairs of calls to ledc_get_duty returns zero for both channels. The second pair returns six for channel 0 and zero for channel 1.

Steps to reproduce

1. Build the attached code and upload it onto the board (or, upload the attached elf)

2. Check pin 26 of the ESP32-WROOM32 on an oscilloscope

3. Observe that no PWM signal (edges) is present

4. Observe the following lines in the console output:

I (321) LedDriver: ch0 duty: 0, ch1 duty: 0
I (331) LedDriver: ch0 duty: 6, ch1 duty: 0

Code to reproduce this issue

Please use attached zip so that you are using the same sdkconfig file. In particular, optimizations must be enabled at level -O2.

#include "esp_log.h"
#include "driver/ledc.h"

#define TAG "LedDriver"

extern "C" void app_main() {
    ledc_timer_config_t timer_conf;
    timer_conf.duty_resolution = LEDC_TIMER_12_BIT;
    timer_conf.freq_hz = 10000;
    timer_conf.speed_mode = LEDC_HIGH_SPEED_MODE;
    timer_conf.timer_num = LEDC_TIMER_0;
    timer_conf.clk_cfg = LEDC_USE_APB_CLK;
    ESP_ERROR_CHECK(ledc_timer_config(&timer_conf));

    ledc_channel_config_t config0 = ledc_channel_config_t{
        .gpio_num   = GPIO_NUM_25,
        .speed_mode = LEDC_HIGH_SPEED_MODE,
        .channel    = LEDC_CHANNEL_0,
        .intr_type  = LEDC_INTR_DISABLE,
        .timer_sel  = LEDC_TIMER_0,
        .duty       = 0,
        .hpoint     = 0,
    };
    ESP_ERROR_CHECK(ledc_channel_config(&config0));
        
    ledc_channel_config_t config1 = ledc_channel_config_t{
        .gpio_num   = GPIO_NUM_26,
        .speed_mode = LEDC_HIGH_SPEED_MODE,
        .channel    = LEDC_CHANNEL_1,
        .intr_type  = LEDC_INTR_DISABLE,
        .timer_sel  = LEDC_TIMER_0,
        .duty       = 0,
        .hpoint     = 0,
    };
    ESP_ERROR_CHECK(ledc_channel_config(&config1));

    ledc_set_duty(LEDC_HIGH_SPEED_MODE, LEDC_CHANNEL_0, 6);
    ledc_update_duty(LEDC_HIGH_SPEED_MODE, LEDC_CHANNEL_0);
    
    //ets_delay_us(100);
    
    ledc_set_duty(LEDC_HIGH_SPEED_MODE, LEDC_CHANNEL_1, 6);
    ledc_update_duty(LEDC_HIGH_SPEED_MODE, LEDC_CHANNEL_1);
    
    ESP_LOGI(TAG, "ch0 duty: %d, ch1 duty: %d", ledc_get_duty(LEDC_HIGH_SPEED_MODE, LEDC_CHANNEL_0), ledc_get_duty(LEDC_HIGH_SPEED_MODE, LEDC_CHANNEL_1));
    
    ets_delay_us(100);
    
    ESP_LOGI(TAG, "ch0 duty: %d, ch1 duty: %d", ledc_get_duty(LEDC_HIGH_SPEED_MODE, LEDC_CHANNEL_0), ledc_get_duty(LEDC_HIGH_SPEED_MODE, LEDC_CHANNEL_1));
}

Debug Logs

Note the last two lines: the first indicates that the duty cycle of both channels is '0'. The second, printed after a 100us delay, indicates that the duty cycle of the first channel is '6' and that of the second channel is '0'. It is expected that all four values mentioned should be '6'.

I (28) boot: ESP-IDF v4.2.1-780-g166c30e7b2-dirty 2nd stage bootloader
I (28) boot: compile time 13:02:22
I (29) boot: chip revision: 1
I (33) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (40) boot.esp32: SPI Speed      : 40MHz
I (45) boot.esp32: SPI Mode       : DIO
I (49) boot.esp32: SPI Flash Size : 2MB
I (54) boot: Enabling RNG early entropy source...
I (59) boot: Partition Table:
I (63) boot: ## Label            Usage          Type ST Offset   Length
I (70) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (77) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (85) boot:  2 factory          factory app      00 00 00010000 00100000
I (92) boot: End of partition table
I (97) boot_comm: chip revision: 1, min. application chip revision: 0
I (104) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=07a58h ( 31320) map
I (124) esp_image: segment 1: paddr=00017a80 vaddr=3ffb0000 size=02168h (  8552) load
I (127) esp_image: segment 2: paddr=00019bf0 vaddr=40080000 size=06428h ( 25640) load
I (142) esp_image: segment 3: paddr=00020020 vaddr=400d0020 size=14fd0h ( 85968) map
I (173) esp_image: segment 4: paddr=00034ff8 vaddr=40086428 size=03f30h ( 16176) load
I (180) esp_image: segment 5: paddr=00038f30 vaddr=50000000 size=00010h (    16) load
I (186) boot: Loaded app from partition at offset 0x10000
I (186) boot: Disabling RNG early entropy source...
I (202) cpu_start: Pro cpu up.
I (202) cpu_start: Starting app cpu, entry point is 0x40080f50
I (0) cpu_start: App cpu up.
I (216) cpu_start: Pro cpu start user code
I (216) cpu_start: cpu freq: 160000000
I (216) cpu_start: Application information:
I (221) cpu_start: Project name:     ledc_test
I (226) cpu_start: App version:      14589af-dirty
I (231) cpu_start: Compile time:     Jul 19 2021 13:02:10
I (237) cpu_start: ELF file SHA256:  24b1beb798eedf45...
I (243) cpu_start: ESP-IDF:          v4.2.1-780-g166c30e7b2-dirty
I (250) heap_init: Initializing. RAM available for dynamic allocation:
I (257) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (263) heap_init: At 3FFB2A88 len 0002D578 (181 KiB): DRAM
I (270) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (276) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (283) heap_init: At 4008A358 len 00015CA8 (87 KiB): IRAM
I (290) spi_flash: detected chip: gd
I (293) spi_flash: flash io: dio
W (297) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (311) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (321) LedDriver: ch0 duty: 0, ch1 duty: 0
I (331) LedDriver: ch0 duty: 6, ch1 duty: 0

[acf-bwl]

Due to GitHub upload size limitations, project without binaries:
ledc_test-1.zip

Application binary:
ledc_test-elf.zip

[Alvin1Zhang]

@acf-bwl Thanks for reporting and sorry for the slow turnaround. We had a fix under internal reviewing. The issue will be closed automatically once the fix is available on GitHub. Thanks.

[acf-bwl]

Thanks for looking into this. Our ets_delay_us workaround is working fine for now, but glad to hear the fix will be in master soon.

[UnexpectedMaker]

I'm still seeing this issue.... any word on a fix please?

[IhorNehrutsa]

I also see this bug in v4.2
Please fix it. Thank you.