CAN vs OTA: interrupt watchdog timeouts despite delay in OTA and IRAM_ATTR in CAN

[jcsbanks]

I've tweaked the OTA example to add a delay because large partition updates would cause interrupt watchdog timeouts on most attempts. Now they do not have this problem and instead of failing most of the time, work every time, until...

On attempting to do OTA with a live CAN bus (has about 600 frames per second), I get watchdog timeouts despite adding IRAM_ATTR to the functions in -------------------- Interrupt and Alert Handlers ------------------------

I could disable the CAN bus during OTA if I have to, but would there be a way to keep CAN Rx interrupts running?

Maybe just adding IRAM_ATTR to these functions doesn't cover other functions they call.

If I unplug the CAN bus, OTA works perfectly. It fails every time with CAN bus traffic.

After IRAM_ATTR:

Code: Select all

I (42267) esp_https_ota: Starting OTA...
I (42267) esp_https_ota: Writing to partition subtype 17 at offset 0x400000
Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0)
Core 0 register dump:
PC      : 0x40085cde  PS      : 0x00060034  A0      : 0x40085304  A1      : 0x3ffb0680
0x40085cde: can_intr_handler_main at C:/Users/jcsba/Documents/C/OBD_DS1/main/can.c:814

0x40085304: _xt_lowint1 at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/xtensa_vectors.S:1154

A2      : 0x00000000  A3      : 0x00000000  A4      : 0x3ffb3f40  A5      : 0x400963bc
0x400963bc: _frxt_int_enter at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/portasm.S:119

A6      : 0x00003004  A7      : 0x00000001  A8      : 0x80085cca  A9      : 0x3ffb0660
A10     : 0x3ffda5ac  A11     : 0x3ffb0684  A12     : 0x00000000  A13     : 0x00000040
A14     : 0x00060021  A15     : 0x00000000  SAR     : 0x0000001a  EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000
Core 0 was running in ISR context:
EPC1    : 0x40082108  EPC2    : 0x00000000  EPC3    : 0x00000000  EPC4    : 0x40085cde
0x40082108: esp_intr_noniram_enable at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/intr_alloc.c:883

0x40085cde: can_intr_handler_main at C:/Users/jcsba/Documents/C/OBD_DS1/main/can.c:814


ELF file SHA256: 73ee34ebef69180f8c1dcf7d2ffd3610d8101f1a0ba3c163c6a081b96e537980

Backtrace: 0x40085cde:0x3ffb0680 0x40085301:0x3ffb06b0 0x40082105:0x3ffbb660 0x40086abb:0x3ffbb680 0x4008216f:0x3ffbb6a0 0x40095329:0
x3ffbb6c0
0x40085cde: can_intr_handler_main at C:/Users/jcsba/Documents/C/OBD_DS1/main/can.c:814

0x40085301: _xt_lowint1 at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/xtensa_vectors.S:1154

0x40082105: esp_intr_noniram_enable at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/intr_alloc.c:883

0x40086abb: spi_flash_op_block_func at C:/msys32/home/jcsba/esp/esp-idf/components/spi_flash/cache_utils.c:201

0x4008216f: ipc_task at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/ipc.c:62

0x40095329: vPortTaskWrapper at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/port.c:435


Core 1 register dump:
PC      : 0x401a28be  PS      : 0x00060934  A0      : 0x800d3a99  A1      : 0x3ffbe080
0x401a28be: esp_pm_impl_waiti at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/pm_esp32.c:487

A2      : 0x00000000  A3      : 0x80000001  A4      : 0x00000000  A5      : 0x00000001
A6      : 0x00060620  A7      : 0x00000000  A8      : 0x800d2936  A9      : 0x3ffbe050
A10     : 0x00000000  A11     : 0x00000001  A12     : 0x80095522  A13     : 0x3ffde6f0
A14     : 0x00000003  A15     : 0x00060023  SAR     : 0x00000000  EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000

ELF file SHA256: 73ee34ebef69180f8c1dcf7d2ffd3610d8101f1a0ba3c163c6a081b96e537980

Backtrace: 0x401a28be:0x3ffbe080 0x400d3a96:0x3ffbe0a0 0x400943d1:0x3ffbe0c0 0x40095329:0x3ffbe0e0
0x401a28be: esp_pm_impl_waiti at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/pm_esp32.c:487

0x400d3a96: esp_vApplicationIdleHook at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/freertos_hooks.c:86

0x400943d1: prvIdleTask at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/tasks.c:4439

0x40095329: vPortTaskWrapper at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/port.c:435

Before IRAM_ATTR:

Code: Select all

I (208020) esp_https_ota: Starting OTA...
I (208021) esp_https_ota: Writing to partition subtype 17 at offset 0x400000
Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0)
Core 0 register dump:
PC      : 0x40093767  PS      : 0x00060734  A0      : 0x800dc94c  A1      : 0x3ffb0650
0x40093767: vTaskEnterCritical at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/tasks.c:4439

A2      : 0x3ffb11a0  A3      : 0x3ffb0684  A4      : 0x00000000  A5      : 0x00000020
A6      : 0x00060721  A7      : 0x00000000  A8      : 0x80093998  A9      : 0x3ffb0650
A10     : 0x00000003  A11     : 0x00060723  A12     : 0x00060721  A13     : 0x00000000
A14     : 0x3ffe43c0  A15     : 0x00060723  SAR     : 0x00000018  EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000  LBEG    : 0x4008d6e1  LEND    : 0x4008d715  LCOUNT  : 0xffffffff
0x4008d6e1: memcpy at /home/jeroen/esp8266/esp32/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/machine/xte
nsa/../../../../.././newlib/libc/machine/xtensa/memcpy.S:291

0x4008d715: memcpy at /home/jeroen/esp8266/esp32/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/machine/xte
nsa/../../../../.././newlib/libc/machine/xtensa/memcpy.S:324

Core 0 was running in ISR context:
EPC1    : 0x400dc9da  EPC2    : 0x00000000  EPC3    : 0x00000000  EPC4    : 0x40093767
0x400dc9da: can_intr_handler_main at C:/Users/jcsba/Documents/C/OBD_DS1/main/can.c:814

0x40093767: vTaskEnterCritical at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/tasks.c:4439


ELF file SHA256: e74d38b6767207ef213a9bb689b40da14ccc9f60c557eec6a8a3c91b1024618f

Backtrace: 0x40093767:0x3ffb0650 0x400dc949:0x3ffb0680 0x400852d5:0x3ffb06b0 0x400dc9d7:0x3ffbb660 0x400866d3:0x3ffbb680 0x40082143:0
x3ffbb6a0 0x40094f41:0x3ffbb6c0
0x40093767: vTaskEnterCritical at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/tasks.c:4439

0x400dc949: can_intr_handler_main at C:/Users/jcsba/Documents/C/OBD_DS1/main/can.c:814

0x400852d5: _xt_lowint1 at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/xtensa_vectors.S:1154

0x400dc9d7: can_intr_handler_main at C:/Users/jcsba/Documents/C/OBD_DS1/main/can.c:814

0x400866d3: spi_flash_op_block_func at C:/msys32/home/jcsba/esp/esp-idf/components/spi_flash/cache_utils.c:201

0x40082143: ipc_task at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/ipc.c:62

0x40094f41: vPortTaskWrapper at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/port.c:435


Core 1 register dump:
PC      : 0x401a2cca  PS      : 0x00060734  A0      : 0x800d3ab5  A1      : 0x3ffbe080
0x401a2cca: esp_pm_impl_waiti at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/pm_esp32.c:487

A2      : 0x00000000  A3      : 0x80000001  A4      : 0x00000000  A5      : 0x00000001
A6      : 0x00060620  A7      : 0x00000000  A8      : 0x00060023  A9      : 0x3ffbe170
A10     : 0x00000001  A11     : 0x00000001  A12     : 0x8009513a  A13     : 0x3ffde6f0
A14     : 0x00000003  A15     : 0x00060023  SAR     : 0x00000000  EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000

ELF file SHA256: e74d38b6767207ef213a9bb689b40da14ccc9f60c557eec6a8a3c91b1024618f

Backtrace: 0x401a2cca:0x3ffbe080 0x400d3ab2:0x3ffbe0a0 0x40093fe9:0x3ffbe0c0 0x40094f41:0x3ffbe0e0
0x401a2cca: esp_pm_impl_waiti at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/pm_esp32.c:487

0x400d3ab2: esp_vApplicationIdleHook at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/freertos_hooks.c:86

0x40093fe9: prvIdleTask at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/tasks.c:4439

0x40094f41: vPortTaskWrapper at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/port.c:435

[jcsbanks]

I'd like to follow this up. Whilst a vTaskDelay of 4ms works for OTA updates, I notice interrupt watchdog timeouts with the CAN driver in other circumstances involving writing to flash, such as if the NVS is written by the WiFi driver or a large file is written to FATFS.

The two approaches I see are avoiding concurrent actions that could cause the problems, or asking for advice on how to rewrite the CAN driver to make it more robust.

[WiFive]

Did you set the iram flag on the can interrupt itself? Do you run the can interrupt on an opposite core from flash tasks?

[jcsbanks]

Yes.

I can rewrite and split some tasks to get them on separate cores. Problem is that many things are able to write flash potentially, so nearly everything would end up on the other core to the CAN interrupt.

[jcsbanks]

Sometimes get Int WDT timeout when NVS is written by WiFi. It often seems to happen at startup after doing an OTA update. I really need to dig into this CAN driver code and fix this. I already have the timeout at 2 seconds and it seems NVS and other stuff doesn't take this long and although there is a reasonable interrupt load, the idle tasks get plenty of time in normal operation, until something like NVS or OTA write flash and everything is flakey. There seems to be some weird stuff going on between cores with critical sections related to high resolution timers, CAN. The idea of the critical sections to avoid a race sometimes seems to cause a lock. Deleting timers in a critical section could cause similar problems. Super vague I know, difficult to reproduce.

Code: Select all

I (3683) wifi: connected with BTHomeHub5-QXSW, channel 4, bssid = 00:8a:be:aa:6a:9c
Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0)
Core 0 register dump:
PC      : 0x40093978  PS      : 0x00060334  A0      : 0x800e1ae2  A1      : 0x3ffb0650
0x40093978: vPortCPUReleaseMutexIntsDisabled at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/tasks.c:4439
 (inlined by) vTaskExitCritical at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/tasks.c:4291

A2      : 0x3ffb119c  A3      : 0x3ffb0674  A4      : 0x00000000  A5      : 0x00000020
A6      : 0x00060321  A7      : 0x00000000  A8      : 0x007b119c  A9      : 0x3ffb0640
A10     : 0x00000003  A11     : 0x00060323  A12     : 0x00060321  A13     : 0x00000000
A14     : 0x3ffe43c0  A15     : 0x00060323  SAR     : 0x00000008  EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000  LBEG    : 0x4008d6d4  LEND    : 0x4008d702  LCOUNT  : 0xffffffff
0x4008d6d4: memcpy at /home/jeroen/esp8266/esp32/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/machine/xten
sa/../../../../.././newlib/libc/machine/xtensa/memcpy.S:168

0x4008d702: memcpy at /home/jeroen/esp8266/esp32/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/machine/xten
sa/../../../../.././newlib/libc/machine/xtensa/memcpy.S:201

Core 0 was running in ISR context:
EPC1    : 0x400e1afe  EPC2    : 0x00000000  EPC3    : 0x00000000  EPC4    : 0x40093978
0x400e1afe: can_intr_handler_main at C:/Users/jcsba/Documents/GitHub/testapp/C/testapp_embed/main/can.c:759

0x40093978: vPortCPUReleaseMutexIntsDisabled at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/tasks.c:4439
 (inlined by) vTaskExitCritical at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/tasks.c:4291


ELF file SHA256: 3208048f9ce877f675f6b6007eb1f9ddde708680549fa5623e81283f861acead

Backtrace: 0x40093978:0x3ffb0650 0x400e1adf:0x3ffb0670 0x400852dd:0x3ffb06a0 0x400e1afb:0x3ffcca60 0x400868d7:0x3ffcca80 0x40085f7c:0x
3ffccaa0 0x40085fde:0x3ffccac0 0x400fd883:0x3ffccae0 0x400fbeb9:0x3ffccb00 0x400fb556:0x3ffccb20 0x400fb9e1:0x3ffccba0 0x400faefd:0x3f
fccc10 0x4013776d:0x3ffccc50 0x40134cde:0x3ffccc80 0x401452ce:0x3ffcccb0 0x40136d1b:0x3ffccd30 0x40154f43:0x3ffccd50 0x40153323:0x3ffc
cd70 0x401543ac:0x3ffccd90 0x4014ab32:0x3ffcce20 0x400913cd:0x3ffcce50 0x40094ff5:0x3ffcce90
0x40093978: vPortCPUReleaseMutexIntsDisabled at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/tasks.c:4439
 (inlined by) vTaskExitCritical at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/tasks.c:4291

0x400e1adf: can_intr_handler_main at C:/Users/jcsba/Documents/GitHub/testapp/C/testapp_embed/main/can.c:759

0x400852dd: _xt_lowint1 at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/xtensa_vectors.S:1154

0x400e1afb: can_intr_handler_main at C:/Users/jcsba/Documents/GitHub/testapp/C/testapp_embed/main/can.c:759

0x400868d7: spi_flash_enable_interrupts_caches_and_other_cpu at C:/msys32/home/jcsba/esp/esp-idf/components/spi_flash/cache_utils.c:20
1

0x40085f7c: spi_flash_guard_end at C:/msys32/home/jcsba/esp/esp-idf/components/spi_flash/flash_ops.c:168
 (inlined by) spi_flash_erase_range at C:/msys32/home/jcsba/esp/esp-idf/components/spi_flash/flash_ops.c:237

0x40085fde: spi_flash_erase_sector at C:/msys32/home/jcsba/esp/esp-idf/components/spi_flash/flash_ops.c:204

0x400fd883: nvs::Page::erase() at C:/msys32/home/jcsba/esp/esp-idf/components/nvs_flash/src/nvs_page.cpp:857

0x400fbeb9: nvs::PageManager::requestNewPage() at C:/msys32/home/jcsba/esp/esp-idf/components/nvs_flash/src/nvs_pagemanager.cpp:182

0x400fb556: nvs::Storage::writeMultiPageBlob(unsigned char, char const*, void const*, unsigned int, nvs::VerOffset) at C:/msys32/home/
jcsba/esp/esp-idf/components/nvs_flash/src/nvs_storage.cpp:553

0x400fb9e1: nvs::Storage::writeItem(unsigned char, nvs::ItemType, char const*, void const*, unsigned int) at C:/msys32/home/jcsba/esp/
esp-idf/components/nvs_flash/src/nvs_storage.cpp:553

0x400faefd: nvs_set_blob at C:/msys32/home/jcsba/esp/esp-idf/components/nvs_flash/src/nvs_api.cpp:521

0x4013776d: wifi_nvs_set at ??:?

0x40134cde: wifi_station_save_ap_channel at ??:?

0x401452ce: cnx_auth_done at ??:?

0x40136d1b: ieee80211_auth_done at ??:?

0x40154f43: wpa_neg_complete at ??:?

0x40153323: wpa_parse_kde_ies at ??:?

0x401543ac: eapol_txcb at ??:?

0x4014ab32: ppProcTxDone at ??:?

0x400913cd: ppTask at ??:?

0x40094ff5: vPortTaskWrapper at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/port.c:435


Core 1 register dump:
PC      : 0x401afe3e  PS      : 0x00060834  A0      : 0x800d3c89  A1      : 0x3ffc0010
0x401afe3e: esp_pm_impl_waiti at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/pm_esp32.c:487

A2      : 0x00000000  A3      : 0x80000001  A4      : 0x00000000  A5      : 0x00000001
A6      : 0x00060620  A7      : 0x00000000  A8      : 0x800d2b3a  A9      : 0x3ffbffe0
A10     : 0x00000000  A11     : 0x00000001  A12     : 0x800951ee  A13     : 0x3ffbff20
A14     : 0x00000003  A15     : 0x00060023  SAR     : 0x00000000  EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000

ELF file SHA256: 3208048f9ce877f675f6b6007eb1f9ddde708680549fa5623e81283f861acead

Backtrace: 0x401afe3e:0x3ffc0010 0x400d3c86:0x3ffc0030 0x4009409d:0x3ffc0050 0x40094ff5:0x3ffc0070
0x401afe3e: esp_pm_impl_waiti at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/pm_esp32.c:487

0x400d3c86: esp_vApplicationIdleHook at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/freertos_hooks.c:86

0x4009409d: prvIdleTask at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/tasks.c:4439

0x40094ff5: vPortTaskWrapper at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/port.c:435


Rebooting...

[ESP_Dazz]

@jcsbanks
I think the first thing to do is to determine whether this is an actual deadlock or a legitimate interrupt watchdog timeout. It's possible that the duration of the the flash operation in addition to handling the CAN interrupt exceeds the interrupt watchdog timeout duration. Try increasing your interrupt watchdog timeout duration in menuconfig and see if the problem persists. If the issue was due to a deadlock, it should be reproducible regardless of the timeout duration.

Secondly, looking at the backtrace, can_intr_handler_main() seems to run only after esp_intr_noniram_enable(). Did you specify can_intr_handler_main() as an IRAM interrupt by providing ESP_INTR_FLAG_IRAM at the point of allocation?

[jcsbanks]

Thanks @ESP_Dazz The duration was 2 seconds for the interrupt watchdog timer in the NVS crash dump above, and the likelihood of it happening is similar to if it is set to 300ms, which makes me suspect a lock. This example interrupt watchdog timeout had queue lengths of 800 with 600 CAN frames per second and the only change in the CAN driver was to change the transmit interrupt so it unlocks the transmitting task, but I was not transmitting at the time. This example did not have any changes with IRAM_ATTR, as they did not work. One thing that helped was disabling CAN if doing a programmatic restart.

Some/all of the problem is resolved by 600 CAN frames a second not hitting the receive interrupt in production because a gateway blocks them, but would like to investigate still. Filters are pretty inflexible for a system that changes CAN IDs at run time in scripts. However, it all performs very well unless there is a flash write.

Working through getting the CAN interrupt handler and into IRAM properly, need to trace it through and also tag all the data and functions it hits too.

[jcsbanks]

In can_intr_handler_main I'm trying to pick out all the things that need to be IRAM_ATTR:

Code: Select all

    
        can_get_status();
        can_get_interrupt_reason()
        can_intr_handler_err_warn(&status, &task_woken, &alert_req);
        can_intr_handler_err_passive(&alert_req);
        can_intr_handler_bus_err(&alert_req);
        can_intr_handler_arb_lost(&alert_req);
        can_intr_handler_rx(&task_woken, &alert_req);
        can_intr_handler_tx(&status, &task_woken, &alert_req);

First two are inline, but marked them IRAM_ATTR anyway, as well as the can_intr_handler_ functions and all the runtime register functions called by them (all but one are inline).

all FreeRTOS APIs are currently placed into IRAM, so are safe to call from interrupt handlers

So I'm not going to do anything about these:

Code: Select all

CAN_ENTER_CRITICAL();
CAN_EXIT_CRITICAL();
xSemaphoreGiveFromISR(p_can_obj->alert_semphr, &task_woken);
portYIELD_FROM_ISR();

I cannot see anything that needs to be tagged to DRAM. It compiles anyway.

I will report back.

[jcsbanks]

So far, this is working well with code in IRAM, with 300ms interrupt watchdog timeout it is not being triggered. The loss of IRAM was <2KB, whereas just moving mbed_tls buffers to IRAM recovered about 40KB.

I have not yet reverted the OTA delay and tested with a large partition, will be interesting.

[dmaxben]

So far, this is working well with code in IRAM, with 300ms interrupt watchdog timeout it is not being triggered. The loss of IRAM was <2KB, whereas just moving mbed_tls buffers to IRAM recovered about 40KB.

I have not yet reverted the OTA delay and tested with a large partition, will be interesting.

John-

Did you ever get this 100% confirmed working? If so, what was the fix?

I currently just stop the CAN driver when doing an OTA update because I could never figure it out (the CAN / OTA conflict)...it would be nice to be able to not have to worry about stopping the CAN driver before doing an OTA update though.

Ben