[BUG][PATCH]Delay in esp_timer task callback prevents dispatch of ESP_TIMER_ISR callbacks (IDFGH-10379)

[acf-bwl]

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.

master

Operating System used.

Windows

How did you build your project?

Command line with idf.py

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

CMD

Development Kit.

Lolin D32, in-house board

Power Supply used.

USB

What is the expected behavior?

I would expect that callbacks dispatched as ESP_TIMER_ISR would run asynchronously to those dispatched as ESP_TIMER_TASK, so that even if a long delay were to occur in a callback in the timer task, the callbacks run in the ISR would continue to run unimpeded during this delay. Indeed, in esp_timer code, the esp_timer_impl abstraction layer appears to provide two separate alarms: one for the time task and one for the isr. One would expect that even when the timer task is busy, the separate ISR alarm would continue unaffected.

What is the actual behavior?

Introducing a one second delay into a callback in the timer task causes all ISR callbacks to stop being serviced until the aforementioned timer task callback returns. This means no ISR-dispatched esp_timer s are serviced for around a second. This seems like it somewhat defeats the purpose of the ESP_TIMER_ISR dispatch method.

Steps to reproduce.

Please build and run the attached code on ESP32: esp_timer_issue.zip
. A copy of the main file is provided below for convenience. Note that the CONFIG_ESP_TIMER_SUPPORTS_ISR_DISPATCH_METHOD option must be enabled.

Note that following a print of "task callback", which prints with a period of 2 seconds, "isr callback" stops printing for some time prior to resuming its regular printing with a period of 200ms.

#include "esp_log.h"
#include "esp_timer.h"
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"

#define TAG "timer_issue"

void task_timer_cb(void *arg);
void isr_timer_cb(void *arg);

void app_main(void)
{
    esp_timer_handle_t task_timer_handle;
    esp_timer_handle_t isr_timer_handle;
    
    const esp_timer_create_args_t task_timer_args = {
        .callback = &task_timer_cb,
        .arg = NULL,
        .dispatch_method = ESP_TIMER_TASK,
        .name = "task_timer",
        .skip_unhandled_events = true,
    };
    
    const esp_timer_create_args_t isr_timer_args = {
        .callback = &isr_timer_cb,
        .arg = xTaskGetCurrentTaskHandle(),
        .dispatch_method = ESP_TIMER_ISR,
        .name = "isr_timer",
        .skip_unhandled_events = true,
    };
        
    ESP_ERROR_CHECK(esp_timer_create(&task_timer_args, &task_timer_handle));
    esp_timer_create(&isr_timer_args, &isr_timer_handle);
    ESP_ERROR_CHECK(esp_timer_start_periodic(task_timer_handle, 2*1000*1000));
    esp_timer_start_periodic(isr_timer_handle, 200*1000);
    
    uint32_t bits = 0;
    for (;;) {
        xTaskNotifyWait(0, 1, &bits, portMAX_DELAY);
        if (bits & 1) {
            ESP_LOGI(TAG, "isr callback");
        }
    }
    
    for (;;) vTaskDelay(100);
}

void task_timer_cb(void *arg) {
    ESP_LOGI(TAG, "task callback");
    
    /* note: very long callback in timer task*/
    vTaskDelay( 1000 / portTICK_PERIOD_MS );
}

void IRAM_ATTR isr_timer_cb(void *arg) {
    BaseType_t pxHigherPriorityTaskWoken;
    
    TaskHandle_t *th = (TaskHandle_t *) arg;
    xTaskNotifyFromISR(th, 1, eSetBits, &pxHigherPriorityTaskWoken);
    if (pxHigherPriorityTaskWoken) {
        esp_timer_isr_dispatch_need_yield();
    }
}

Debug Logs.

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:6664
load:0x40078000,len:14848
load:0x40080400,len:3792
0x40080400: _init at ??:?

entry 0x40080694
I (27) boot: ESP-IDF -128-NOTFOUND 2nd stage bootloader
I (27) boot: compile time 13:04:53
I (27) boot: chip revision: 3
I (31) boot_comm: chip revision: 3, min. bootloader chip revision: 0
I (38) boot.esp32: SPI Speed      : 40MHz
I (42) boot.esp32: SPI Mode       : DIO
I (47) boot.esp32: SPI Flash Size : 2MB
I (52) boot: Enabling RNG early entropy source...
I (57) boot: Partition Table:
I (60) boot: ## Label            Usage          Type ST Offset   Length
I (68) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (75) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (83) boot:  2 factory          factory app      00 00 00010000 00100000
I (90) boot: End of partition table
I (94) boot_comm: chip revision: 3, min. application chip revision: 0
I (101) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=07a44h ( 31300) map
I (121) esp_image: segment 1: paddr=00017a6c vaddr=3ffb0000 size=02308h (  8968) load
I (125) esp_image: segment 2: paddr=00019d7c vaddr=40080000 size=0629ch ( 25244) load
I (140) esp_image: segment 3: paddr=00020020 vaddr=400d0020 size=148c4h ( 84164) map
I (170) esp_image: segment 4: paddr=000348ec vaddr=4008629c size=05878h ( 22648) load
I (180) esp_image: segment 5: paddr=0003a16c 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 (201) cpu_start: Pro cpu up.
I (201) cpu_start: Starting app cpu, entry point is 0x40081048
0x40081048: call_start_cpu1 at C:/Users/User/Documents/esp-idf-v4.4/components/esp_system/port/cpu_start.c:148

I (0) cpu_start: App cpu up.
I (215) cpu_start: Pro cpu start user code
I (215) cpu_start: cpu freq: 160000000
I (216) cpu_start: Application information:
I (220) cpu_start: Project name:     esp_timer_issue
I (226) cpu_start: App version:      1
I (230) cpu_start: Compile time:     Jun  9 2023 13:04:37
I (236) cpu_start: ELF file SHA256:  2edf21fd09572af5...
I (242) cpu_start: ESP-IDF:          -128-NOTFOUND
I (248) heap_init: Initializing. RAM available for dynamic allocation:
I (255) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (261) heap_init: At 3FFB2C00 len 0002D400 (181 KiB): DRAM
I (267) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (274) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (280) heap_init: At 4008BB14 len 000144EC (81 KiB): IRAM
I (287) spi_flash: detected chip: generic
I (291) spi_flash: flash io: dio
W (295) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (309) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (719) timer_issue: isr callback
I (919) timer_issue: isr callback
I (1119) timer_issue: isr callback
I (1319) timer_issue: isr callback
I (1519) timer_issue: isr callback
I (1719) timer_issue: isr callback
I (1919) timer_issue: isr callback
I (2119) timer_issue: isr callback
I (2319) timer_issue: isr callback
I (2519) timer_issue: task callback
I (3519) timer_issue: isr callback
I (3719) timer_issue: isr callback
I (3919) timer_issue: isr callback
I (4119) timer_issue: isr callback
I (4319) timer_issue: isr callback
I (4519) timer_issue: isr callback
I (4519) timer_issue: task callback
I (5519) timer_issue: isr callback
I (5719) timer_issue: isr callback
I (5919) timer_issue: isr callback
I (6119) timer_issue: isr callback
I (6319) timer_issue: isr callback
I (6519) timer_issue: isr callback
I (6519) timer_issue: task callback
I (7519) timer_issue: isr callback
I (7719) timer_issue: isr callback
I (7919) timer_issue: isr callback
I (8119) timer_issue: isr callback
I (8319) timer_issue: isr callback
I (8519) timer_issue: isr callback
I (8519) timer_issue: task callback
I (9519) timer_issue: isr callback
I (9719) timer_issue: isr callback
I (9919) timer_issue: isr callback
I (10119) timer_issue: isr callback
I (10319) timer_issue: isr callback
I (10519) timer_issue: isr callback
I (10519) timer_issue: task callback
I (11519) timer_issue: isr callback
I (11719) timer_issue: isr callback
I (11919) timer_issue: isr callback
I (12119) timer_issue: isr callback
I (12319) timer_issue: isr callback
I (12519) timer_issue: isr callback
I (12519) timer_issue: task callback
I (13519) timer_issue: isr callback

Done

More Information.

This occurs because the LAC timer has only one compare register to use for both the timer task dispatch alarm and the ISR dispatch alarm. Both methods use the

void IRAM_ATTR esp_timer_impl_set_alarm_id(uint64_t timestamp, unsigned alarm_id)

function to set their timers, with alarm_id distinguishing between the two. The timestamps of both alarms are stored, and esp_timer_impl_set_alarm_id compares them and places the lesser of the two in the actual hardware timer compare register.

During the interrupt, however, the hardware timer compare register is never updated. The next update to the compare register comes after the next callback is finished running, whether in the ISR or in the timer task. This means that the timer compare register will continue to hold an outdated compare value, rather than the compare value for the upcoming ISR alarm, until the callback in the timer task is complete and the time task once again calls esp_timer_impl_set_alarm_id(). This scenario only occurs if this timer expiry was dispatched to the timer task and the next is destined to be dispatched to be run in the ISR, or perhaps theoretically the opposite.

This appears to affect the LAC esp_timer backend; I have not checked whether any of the others are affected. I have a patch for this bug for both esp-idf master and release/v4.4 which I will attach to this bug report as pull requests.

[acf-bwl]

Pull requests are #11637 and #11638

[KonstantinKondrashov]

Hi @acf-bwl!
Thanks for your attention to this case. I agree that if such a delay happends then following timers will starving. According to the esp_timer doc it is recommended to only do the minimal possible amount of work from the callback itself.

ESP_TIMER_TASK. Timer callbacks are dispatched from a high-priority esp_timer task. Because all the callbacks are dispatched from the same task, it is recommended to only do the minimal possible amount of work from the callback itself, posting an event to a lower-priority task using a queue instead.

Yes, I confirm that your fix is able to fix a ceratin scenario. I will applay your changes with some addoptions.

[acf-bwl]

great, thanks :)