Crash after accelerating the timer interrupt

JAC · January 28, 2021, 1:30pm

Hello,
I have TIMER_0 ISR:

void IRAM_ATTR timer_group0_isr(void *para)
{
    gpio_set_level(GPO_LED,1);//set pin High (see it on oscilloscope)

    timer_spinlock_take(TIMER_GROUP_0);
    //some variables that i will use in this ISR
    static unsigned char negbit=0;
    static unsigned char smSHR2 = IDDLE;
    static unsigned char RfBuffer_new2[9]={};            
    static unsigned char *RfBufferPtr2=RfBuffer_new2;    
    static unsigned char bitpos2;
    uint64_t tmr1_value=0;

    //reset TIMER_1 value (it's not timer caused this interrupt - it's free-running TIMER_1)
    timer_set_counter_value(TIMER_GROUP_0, TIMER_1, 0x00000000ULL);

    //clear interrupt status and turn TIMER_0 alarm on
    timer_group_clr_intr_status_in_isr(TIMER_GROUP_0, TIMER_0);
    timer_group_enable_alarm_in_isr(TIMER_GROUP_0, TIMER_0);

    timer_spinlock_give(TIMER_GROUP_0);

    //set LOW  (see it on oscilloscope)
    gpio_set_level(GPO_LED,0);
}

I observe GPO_LED on oscilloscope so know how long it spend inside ISR and how often ISR comes.

TIMER_0 configuration is:

    timer_config_t config0 = {
        .divider = TIMER_DIVIDER,
        .counter_dir = TIMER_COUNT_UP,
        .counter_en = TIMER_PAUSE,
        .alarm_en = TIMER_ALARM_EN,
        .auto_reload = 1,
    }; // default clock source is APB

When TIMER_DIVIDER = 1024, i see that:

time spent in the interrupt: 4,1us
interrupt period: 320us

When TIMER_DIVIDER = 512, i see that:

time spent in the interrupt: 4,1us
interrupt period: 160us

When TIMER_DIVIDER = 256, i see… crash, BUT ONLY FOR A MINUTE, than starts work:

abort() was called at PC 0x4008263a on core 0
0x4008263a: lock_acquire_generic at F:/GitHub/esp-idf/components/newlib/locks.c:140


Backtrace:0x4008f707:0x3ffbe160 0x4008fe4d:0x3ffbe180 0x40094c46:0x3ffbe1a0 0x4008263a:0x3ffbe210 0x40082785:0x3ffbe240 0x4013cac2:0x3ffbe260 0x4013fb21:0x3ffbe570 0x4014a7f9:0x3ffbe5a0 0x40094ad9:0x3ffbe5d0 0x4012973d:0x3ffbe620 0x400828a1:0x3ffbe650 0x40082476:0x3ffbe670 0x4000bfed:0x3ffb7390 0x40091e9d:0x3ffb73a0 0x400d4ddf:0x3ffb73c0 0x40129bc3:0x3ffb73e0 0x400d94b4:0x3ffb7410 0x400d9548:0x3ffb7460 0x400d985e:0x3ffb7490 0x4014a31f:0x3ffb7500 0x40091cb1:0x3ffb7520
0x4008f707: panic_abort at F:/GitHub/esp-idf/components/esp_system/panic.c:367

0x4008fe4d: esp_system_abort at F:/GitHub/esp-idf/components/esp_system/system_api.c:108

0x40094c46: abort at F:/GitHub/esp-idf/components/newlib/abort.c:46

0x4008263a: lock_acquire_generic at F:/GitHub/esp-idf/components/newlib/locks.c:140

0x40082785: _lock_acquire_recursive at F:/GitHub/esp-idf/components/newlib/locks.c:168

0x4013cac2: _vfprintf_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vfprintf.c:853 (discriminator 2)

0x4013fb21: vprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vprintf.c:34 (discriminator 5)

0x4014a7f9: esp_log_writev at F:/GitHub/esp-idf/components/log/log.c:189

0x40094ad9: esp_log_write at F:/GitHub/esp-idf/components/log/log.c:199

0x4012973d: timer_set_counter_value at F:/GitHub/esp-idf/components/driver/timer.c:99 (discriminator 5)

0x400828a1: timer_group0_isr at f:\github\ble_spp_server\build/../main/ble_spp_server_demo.c:1159

0x40082476: _xt_lowint1 at F:/GitHub/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1105

0x40091e9d: vPortExitCritical at F:/GitHub/esp-idf/components/freertos/port/xtensa/port.c:469

0x400d4ddf: vPortExitCriticalSafe at F:/GitHub/esp-idf/components/freertos/port/xtensa/include/freertos/portmacro.h:233
 (inlined by) periph_module_enable at F:/GitHub/esp-idf/components/driver/periph_ctrl.c:30

0x40129bc3: timer_init at F:/GitHub/esp-idf/components/driver/timer.c:282 (discriminator 2)

0x400d94b4: example_tg0_timer_init at f:\github\ble_spp_server\build/../main/ble_spp_server_demo.c:1056

0x400d9548: main_task_init at f:\github\ble_spp_server\build/../main/ble_spp_server_demo.c:677

0x400d985e: app_main at f:\github\ble_spp_server\build/../main/ble_spp_server_demo.c:967

0x4014a31f: main_task at F:/GitHub/esp-idf/components/freertos/port/port_common.c:133 (discriminator 2)

0x40091cb1: vPortTaskWrapper at F:/GitHub/esp-idf/components/freertos/port/xtensa/port.c:168



ELF file SHA256: 7f6f4ca23e29a8ef

Rebooting...

After while, i see (TIMER_DIVIDER = 256):

time spent in the interrupt: 4,1us
interrupt period: 80us

When TIMER_DIVIDER = 128, also crash, but this time doesn’t start working after few minutes.

You can see that ISR period could be still much more than spending inside ISR, it should be 40us, so ten times more than time spent inside interrupt. So what is going wrong with it?

And the last, when I comment out:
//timer_set_counter_value(TIMER_GROUP_0, TIMER_1, 0x00000000ULL);
it starts working with expected period 40us and lower time spent inside - 2,5us

hs2 · January 28, 2021, 1:55pm

You shouldn’t call or cause a call to a printf - family function in an ISR.
This will almost always cause problems like internal locking not working in ISR context, stack overflows, etc.
Try to avoid that and try again.

Edit: Since timer_set_counter_value (sometimes ?) calls vprintf, commenting it helps to avoid the crash obviously caused by (v)printf function.

I wonder what timer_spinlock_take/give really does. Is it related to Espressif multi-core support ?

JAC · January 28, 2021, 2:11pm

esp_err_t timer_set_counter_value(timer_group_t group_num, timer_idx_t timer_num, uint64_t load_val)
{
    TIMER_CHECK(group_num < TIMER_GROUP_MAX, TIMER_GROUP_NUM_ERROR, ESP_ERR_INVALID_ARG);
    TIMER_CHECK(timer_num < TIMER_MAX, TIMER_NUM_ERROR, ESP_ERR_INVALID_ARG);
    TIMER_CHECK(p_timer_obj[group_num][timer_num] != NULL, TIMER_NEVER_INIT_ERROR, ESP_ERR_INVALID_ARG);
    TIMER_ENTER_CRITICAL(&timer_spinlock[group_num]);
    timer_hal_set_counter_value(&(p_timer_obj[group_num][timer_num]->hal), load_val);
    TIMER_EXIT_CRITICAL(&timer_spinlock[group_num]);
    return ESP_OK;
}

#define timer_hal_set_counter_value(hal, load_val) timer_ll_set_counter_value((hal)->dev, (hal)->idx, load_val)

static inline void timer_ll_set_counter_value(timg_dev_t *hw, timer_idx_t timer_num, uint64_t load_val)
{
    hw->hw_timer[timer_num].load_high = (uint32_t) (load_val >> 32);
    hw->hw_timer[timer_num].load_low = (uint32_t) load_val;
    hw->hw_timer[timer_num].reload = 1;
}

There is not vprintf.

hs2 · January 28, 2021, 2:21pm

Look at the crash call stack you posted. It tells the truth
And then look up the TIMER_CHECK macro… I guess it does error logging probably for DEBUG builds only.
This in turn tells you that there is an additional problem with configuring the timer you have to find and fix…

JAC · January 28, 2021, 2:42pm

You right
BIG THANX!

BUT… i only want to reset timer_1. Is any other method than use timer_set_counter_value()? or i have to modify library?

Sorry, i can’t see this. I don’t fully anderstand this crashing raport. Could You show me where is this information?

hs2 · January 28, 2021, 2:49pm

I afraid you have to verify the Espressif docs regarding the timer API/programming.
I’m not familiar with it.
It should also be noted for each (HAL) function whether it can be used in ISRs or not.

JAC · January 28, 2021, 3:42pm

Thank You Hartmut one more time. I commented out all TIMER_CHECK calls in timer_set_counter_value() and now works even with 20us ISR period, that I needed.
I will find more elegant solution than modyfing library function but issue is resolved thanks to You.

hs2 · January 28, 2021, 4:10pm

That’s good so far …
But if the TIMER_CHECK only outputs something if the check fails, then there is still a problem ! I think without knowing anything about the Espressif timers that probably this check fails:

The other parameters TIMER_GROUP_0 and TIMER_1 are probably ok/in range.
You should verify that TIMER_1 is correctly initialized before the ISR can be entered (i.e. TIMER_0 interrupt is enabled) and that timer_set_counter_value can be called in ISR context.
Otherwise your application might seem to work for now but fails later due to corrupted data or something, which is very hard to track down.

JAC · January 29, 2021, 10:39am

The problem was that I initialised TIMER_0 with interrupt and than initialised TIMER_1. Before TIMER_1 initialised, there was interrupt from TIMER_0 in whitch I wanted to set counter value of TIMER_1 (that was not initialised yet). Thats why it occured only with short interrupt period.
I changed order - first initialisation is for TIMER_1 now.

But now i have other crash:

Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0).

Core  0 register dump:
PC      : 0x40091e87  PS      : 0x00060034  A0      : 0x80129fc6  A1      : 0x3ffbe600
0x40091e87: vPortExitCritical at F:/GitHub/esp-idf/components/freertos/port/xtensa/port.c:462

A2      : 0x3ffbec10  A3      : 0x00000000  A4      : 0x80091e9c  A5      : 0x3ffb73b0
A6      : 0x00000003  A7      : 0x00060623  A8      : 0x3ffc55d4  A9      : 0x00000000
A10     : 0x00000001  A11     : 0x00060023  A12     : 0x00060023  A13     : 0x3ffb7340
A14     : 0x3ffc55e0  A15     : 0x3ffc75f0  SAR     : 0x0000000d  EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000  LBEG    : 0x4000c46c  LEND    : 0x4000c477  LCOUNT  : 0x00000000
Core  0 was running in ISR context:
EPC1    : 0x4014a39f  EPC2    : 0x00000000  EPC3    : 0x00000000  EPC4    : 0x40091e87
0x4014a39f: uart_hal_write_txfifo at F:/GitHub/esp-idf/components/hal/uart_hal_iram.c:35

0x40091e87: vPortExitCritical at F:/GitHub/esp-idf/components/freertos/port/xtensa/port.c:462


Backtrace:0x40091e84:0x3ffbe600 0x40129fc3:0x3ffbe620 0x400828bf:0x3ffbe650 0x40082476:0x3ffbe670 0x400814d2:0x3ffb7400 0x400906aa:0x3ffb7420 0x400d954d:0x3ffb7460 0x400d9852:0x3ffb7490 0x4014a2bf:0x3ffb7500 0x40091cad:0x3ffb7520
0x40091e84: vPortExitCritical at F:/GitHub/esp-idf/components/freertos/port/xtensa/port.c:460

0x40129fc3: vPortExitCriticalSafe at F:/GitHub/esp-idf/components/freertos/port/xtensa/include/freertos/portmacro.h:231
 (inlined by) timer_spinlock_give at F:/GitHub/esp-idf/components/driver/timer.c:500

0x400828bf: timer_group0_isr at f:\github\ble_spp_server\build/../main/ble_spp_server_demo.c:1441

0x40082476: _xt_lowint1 at F:/GitHub/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1105

0x400814d2: heap_caps_malloc at F:/GitHub/esp-idf/components/heap/heap_caps.c:125

0x400906aa: xTaskCreatePinnedToCore at F:/GitHub/esp-idf/components/freertos/tasks.c:830

0x400d954d: xTaskCreate at F:/GitHub/esp-idf/components/freertos/include/freertos/task.h:388
 (inlined by) main_task_init at f:\github\ble_spp_server\build/../main/ble_spp_server_demo.c:683

0x400d9852: app_main at f:\github\ble_spp_server\build/../main/ble_spp_server_demo.c:972

0x4014a2bf: main_task at F:/GitHub/esp-idf/components/freertos/port/port_common.c:133 (discriminator 2)

0x40091cad: vPortTaskWrapper at F:/GitHub/esp-idf/components/freertos/port/xtensa/port.c:168



ELF file SHA256: bda9eb8567d1ee0a

Rebooting...

This is there:

void __attribute__((optimize("-O3"))) vPortExitCritical(portMUX_TYPE *mux)
{
	vPortCPUReleaseMutex( mux );
	BaseType_t coreID = xPortGetCoreID();
	BaseType_t nesting =  port_uxCriticalNesting[coreID];

	if(nesting > 0U)      <=========== THERE is line 462.
	{
		nesting--;
		port_uxCriticalNesting[coreID] = nesting;

		if( nesting == 0U )
		{
			portEXIT_CRITICAL_NESTED(port_uxOldInterruptState[coreID]);
		}
	}
}

hs2 · January 29, 2021, 12:45pm

It’s this this mutex a few lines above:

For me it seems that the vprintf implementation uses a recursive mutex internally.
Recursive mutexes in ISRs are not supported by FreeRTOS and also don’t make much sense there.
So it seems that also on ESP32 printf-family functions can’t be used in ISRs as suspected.
However, the question remains if and why one of the CHECK_TIMER tests causes an (error ?) output.
I’d try to find out the reason with a debugger setting suitable breakpoints in the existing CHECK_TIMER code or add some code before those CHECK_TIMERs to do the checks myself and directly set breakpoints as needed.
The ESP32 docs and examples tell that timer_set_counter_value can be called in ISRs.
Nevertheless I’d avoid calling it concurrently/from a task.

JAC · January 29, 2021, 1:42pm

I’ve go it!
Wrong order of inicjalisation. Initialised firstly timers (with wrong order TIMER_0 / TIMER_1) and also initialised GPIO that i use to see on oscilloscope after timer initialisation, so used it in ISR before initilised. Now correted order and everthink works fine.
Thank You Hartmut very much for Your help.