ESP_EARLY_LOG during interrupt and critical section in new CAN driver leads to Guru Meditation

[jcsbanks]

Testing the CAN driver in the latest ESP IDF, I enabled CAN_ALERT_AND_LOG and various CAN_ALERT_ types and provoked various error situations to test the handling of them. The problem is that after a series of about 40 consecutive CAN: Alert 1024 (deliberately over-running the receive buffer to test), there is a Guru Meditation error.

The only thing that fixes it is not showing the alerts or making sure they are infrequent. However, CAN bus errors can be at high frequency so there is a lot of load from ESP_EARLY_LOGx calls in interrupts when something goes wrong, and I want to see that rather than have a Guru Meditation as well.

I could not find info about whether ESP_EARLY_LOGx are interrupt safe. I'm assuming they are not.

[jcsbanks]

Code: Select all

Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0)
Core 0 register dump:
PC      : 0x40082368  PS      : 0x00050034  A0      : 0x400e07f8  A1      : 0x3ffb0610
0x40082368: _xt_lowint1 at C:/msys32/home/Banks/esp/esp-idf/components/freertos/xtensa_vectors.S:1105

0x400e07f8: uart_tx_char at C:/msys32/home/Banks/esp/esp-idf/components/vfs/vfs_uart.c:139

A2      : 0x00002000  A3      : 0x0001a040  A4      : 0x0000203f  A5      : 0x3ffb05e0
A6      : 0x00000000  A7      : 0xff000000  A8      : 0x0000007f  A9      : 0x40085dd0
0x40085dd0: _frxt_int_enter at C:/msys32/home/Banks/esp/esp-idf/components/freertos/portasm.S:119

A10     : 0x3ff40000  A11     : 0xffffffff  A12     : 0x800e158a  A13     : 0x3ffb05c0
A14     : 0x3ffba344  A15     : 0x3ffb05e4  SAR     : 0x00000004  EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000  LBEG    : 0x400014fd  LEND    : 0x4000150d  LCOUNT  : 0xffffffff
Core 0 was running in ISR context:
EPC1    : 0x400e07f8  EPC2    : 0x00000000  EPC3    : 0x00000000  EPC4    : 0x40082368
0x400e07f8: uart_tx_char at C:/msys32/home/Banks/esp/esp-idf/components/vfs/vfs_uart.c:139

0x40082368: _xt_lowint1 at C:/msys32/home/Banks/esp/esp-idf/components/freertos/xtensa_vectors.S:1105


Backtrace: 0x40082368:0x3ffb0610 0x400e07f5:0x00000000
0x40082368: _xt_lowint1 at C:/msys32/home/Banks/esp/esp-idf/components/freertos/xtensa_vectors.S:1105

0x400e07f5: uart_tx_char at C:/msys32/home/Banks/esp/esp-idf/components/vfs/vfs_uart.c:139


Core 1 register dump:
PC      : 0x400e2b02  PS      : 0x00060134  A0      : 0x80084ae8  A1      : 0x3ffb5fd0
0x400e2b02: esp_vApplicationWaitiHook at C:/msys32/home/Banks/esp/esp-idf/components/esp32/freertos_hooks.c:66

A2      : 0x00000008  A3      : 0x00000001  A4      : 0x00000000  A5      : 0x3ffb590c
A6      : 0x00000000  A7      : 0x00000001  A8      : 0x3ffb2bcc  A9      : 0x3ffb2b90
A10     : 0x00000000  A11     : 0x80000001  A12     : 0x00000000  A13     : 0x00000001
A14     : 0x00060021  A15     : 0x00000000  SAR     : 0x00000000  EXCCAUSE: 0x00000005
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000

Backtrace: 0x400e2b02:0x3ffb5fd0 0x40084ae5:0x3ffb5ff0
0x400e2b02: esp_vApplicationWaitiHook at C:/msys32/home/Banks/esp/esp-idf/components/esp32/freertos_hooks.c:66

0x40084ae5: prvIdleTask at C:/msys32/home/Banks/esp/esp-idf/components/freertos/tasks.c:4617

So it is the interrupt watchdog timer. Presumably from sending stuff to UART in an interrupt.

[ESP_Angus]

Hi jcsbanks,

The ESP_LOGx APIs (which use printf) are not interrupt safe. ESP_EARLY_LOGx APIs bypass printf and use a ROM routine to write directly to the UART peripheral, so it is safe to call them in ISRs (this is why they're being used here). (The downside to them is that they don't do any software buffering, and don't lock the UART so can produce garbled output if multiple callers use them at once.)

However, these "early log" APIs still don't return until the full log text has been written to the UART FIFO. So they can increase the amount of time spent in the ISR significantly. If you're receiving CAN messages faster than the ISR can process them (and the ISR takes longer than usual due to logging), then the CPU may spend all of its time in CAN ISRs and the Interrupt WDT can trigger, as a warning that ISRs are preventing normal processing.

There are a number of possible ways around this:

• Reduce the amount/level of logging (the CAN log-in-ISRs feature is intended for general debugging but may not be suitable for logging under load.)
• Increase the UART console baud rate (so the FIFO clears more quickly).
• Increase the interrupt watchdog timeout, or disable it (so "logjamming" ISRs with a lot of CAN messages and logging doesn't set it off.)

If you're using the logging to debug some other CAN problem under high load, remember that any logging will change the timing of the ISR so it's possible that whatever behaviour you're investigating may change/disappear.

[jcsbanks]

Thanks. I think I will keep a separate error task and display at a few Hz instead of a few kHz, but using the new CAN driver I will not need to read the hardware registers directly.