ESP32S3 - Narrowing cache issues

[vinci1989]

Hey

I've a hard time debugging some cache issue and need some pointers on where to start looking. My application is concurrently running:

• A webserver which performs flash access to answer some HTTP requests (NVS/SPIFFS) and
• low level signal generation using the RMT, GPTimer and UART peripherals

All my peripherals are configured to be placed in IRAM and I was careful not to accidentally pass constant data to the RMT peripherals somewhere. Also, all interrupt callbacks have the IRAM attribute attached to them. Yet, everytime I need to answer an HTTP requests at the same time my low level signal generation is running I'm getting core panics which seem to be related to cache.

The problem is that the log files don't seem to tell me much. They rather contain the result of my bugs, but not the cause. See for example the last log I've captured:

Code: Select all

Guru Meditation Error: Core  0 panic'ed (Cache disabled but cached memory region accessed). 


Core  0 register dump:
PC      : 0x4037abc8  PS      : 0x00060034  A0      : 0x4037c094  A1      : 0x3fca50e0  
0x4037abc8: shared_intr_isr at /home/vinci/esp/esp-idf/components/esp_hw_support/intr_alloc.c:446

0x4037c094: _xt_lowint1 at /home/vinci/esp/esp-idf/components/xtensa/xtensa_vectors.S:1236

A2      : 0x3c1b2cfc  A3      : 0x00000002  A4      : 0x8038bf0c  A5      : 0x40389bae  
0x40389bae: _frxt_int_enter at /home/vinci/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/portasm.S:139

A6      : 0x3fce6854  A7      : 0x60002058  A8      : 0x00000bad  A9      : 0x3fca50b0  
A10     : 0x00000001  A11     : 0x00060021  A12     : 0x00000000  A13     : 0x00060023  
A14     : 0xb33fffff  A15     : 0xb33fffff  SAR     : 0x0000001c  EXCCAUSE: 0x00000007  
EXCVADDR: 0x00000000  LBEG    : 0x400570e8  LEND    : 0x400570f3  LCOUNT  : 0x00000000  
0x400570e8: memset in ROM

0x400570f3: memset in ROM



Backtrace: 0x4037abc5:0x3fca50e0 0x4037c091:0x3fca5100 0x400011f1:0x3fce6800 0x4038c2ad:0x3fce6830 0x40391449:0x3fce6850 0x4037f1e7:0x3fce68d0 0x420403c2:0x3fce6910 0x42020fab:0x3fce6940 0x42024ae3:0x3fce6970 0x4202274f:0x3fce69a0 0x42023f2a:0x3fce69f0 0x42021ca9:0x3fce6a30 0x42020c2d:0x3fce6a60 0x42008fe6:0x3fce6b10 0x420d2a09:0x3fce6b30 0x4201b6b6:0x3fce6b50 0x420e5185:0x3fce6c00 0x4201b1c6:0x3fce6c20 0x42062b0b:0x3fce6c50 0x42063c89:0x3fce6c90 0x42063d88:0x3fce6d20 0x42061ec4:0x3fce6d40 0x420610c0:0x3fce6d60 0x420e7073:0x3fce6d80 0x42061886:0x3fce6da0 0x420618f2:0x3fce6df0 0x40389839:0x3fce6e10
0x4037abc5: shared_intr_isr at /home/vinci/esp/esp-idf/components/esp_hw_support/intr_alloc.c:439

0x4037c091: _xt_lowint1 at /home/vinci/esp/esp-idf/components/xtensa/xtensa_vectors.S:1236

0x400011f1: __call_memset in ROM

0x4038c2ad: spi_flash_hal_read at /home/vinci/esp/esp-idf/components/hal/spi_flash_hal_common.inc:195

0x40391449: spi_flash_chip_generic_read at /home/vinci/esp/esp-idf/components/spi_flash/spi_flash_chip_generic.c:246

0x4037f1e7: esp_flash_read at /home/vinci/esp/esp-idf/components/spi_flash/esp_flash_api.c:898 (discriminator 4)

0x420403c2: esp_partition_read at /home/vinci/esp/esp-idf/components/esp_partition/partition_target.c:38

0x42020fab: spiffs_api_read at /home/vinci/esp/esp-idf/components/spiffs/spiffs_api.c:27

0x42024ae3: spiffs_phys_rd at /home/vinci/esp/esp-idf/components/spiffs/spiffs/src/spiffs_cache.c:161

0x4202274f: spiffs_obj_lu_find_entry_visitor at /home/vinci/esp/esp-idf/components/spiffs/spiffs/src/spiffs_nucleus.c:166

0x42023f2a: spiffs_object_find_object_index_header_by_name at /home/vinci/esp/esp-idf/components/spiffs/spiffs/src/spiffs_nucleus.c:1711

0x42021ca9: SPIFFS_stat at /home/vinci/esp/esp-idf/components/spiffs/spiffs/src/spiffs_hydrogen.c:804 (discriminator 2)

0x42020c2d: vfs_spiffs_stat at /home/vinci/esp/esp-idf/components/spiffs/esp_spiffs.c:622

0x42008fe6: esp_vfs_stat at /home/vinci/esp/esp-idf/components/vfs/vfs.c:594 (discriminator 3)

0x420d2a09: stat at /builds/idf/crosstool-NG/.build/xtensa-esp32s3-elf/src/newlib/newlib/libc/syscalls/sysstat.c:11

0x4201b6b6: http::sta::Server::wildcardGetHandler(httpd_req*) at /home/vinci/Develop/VSCode/WULF/src/http/sta/server.cpp:230

0x420e5185: int std::__invoke_impl<int, int (http::sta::Server::*&)(httpd_req*), http::sta::Server*&, httpd_req*>(std::__invoke_memfun_deref, int (http::sta::Server::*&)(httpd_req*), http::sta::Server*&, httpd_req*&&) at /home/vinci/.espressif/tools/xtensa-esp32s3-elf/esp-12.2.0_20230208/xtensa-esp32s3-elf/xtensa-esp32s3-elf/include/c++/12.2.0/bits/invoke.h:74 (discriminator 4)

0x4201b1c6: std::__invoke_result<int (http::sta::Server::*&)(httpd_req*), http::sta::Server*&, httpd_req*>::type std::__invoke<int (http::sta::Server::*&)(httpd_req*), http::sta::Server*&, httpd_req*>(int (http::sta::Server::*&)(httpd_req*), http::sta::Server*&, httpd_req*&&) at /home/vinci/.espressif/tools/xtensa-esp32s3-elf/esp-12.2.0_20230208/xtensa-esp32s3-elf/xtensa-esp32s3-elf/include/c++/12.2.0/bits/invoke.h:96
 (inlined by) std::invoke_result<int (http::sta::Server::*&)(httpd_req*), http::sta::Server*&, httpd_req*>::type std::invoke<int (http::sta::Server::*&)(httpd_req*), http::sta::Server*&, httpd_req*>(int (http::sta::Server::*&)(httpd_req*), http::sta::Server*&, httpd_req*&&) at /home/vinci/.espressif/tools/xtensa-esp32s3-elf/esp-12.2.0_20230208/xtensa-esp32s3-elf/xtensa-esp32s3-elf/include/c++/12.2.0/functional:110
 (inlined by) operator() at /home/vinci/Develop/VSCode/WULF/src/utility.hpp:57
 (inlined by) _FUN at /home/vinci/Develop/VSCode/WULF/src/utility.hpp:56

0x42062b0b: httpd_uri at /home/vinci/esp/esp-idf/components/esp_http_server/src/httpd_uri.c:329

0x42063c89: httpd_parse_req at /home/vinci/esp/esp-idf/components/esp_http_server/src/httpd_parse.c:667 (discriminator 15)

0x42063d88: httpd_req_new at /home/vinci/esp/esp-idf/components/esp_http_server/src/httpd_parse.c:795

0x42061ec4: httpd_sess_process at /home/vinci/esp/esp-idf/components/esp_http_server/src/httpd_sess.c:426 (discriminator 15)

0x420610c0: httpd_process_session at /home/vinci/esp/esp-idf/components/esp_http_server/src/httpd_main.c:255 (discriminator 15)

0x420e7073: httpd_sess_enum at /home/vinci/esp/esp-idf/components/esp_http_server/src/httpd_sess.c:50 (discriminator 1)

0x42061886: httpd_server at /home/vinci/esp/esp-idf/components/esp_http_server/src/httpd_main.c:305

0x420618f2: httpd_thread at /home/vinci/esp/esp-idf/components/esp_http_server/src/httpd_main.c:327 (discriminator 15)

0x40389839: vPortTaskWrapper at /home/vinci/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

How can I interpret this? I mean, yes, obviously SPIFFS access caused the panic, but why?

[MicroController]

How can I interpret this?

To me it looks as though the issue could be that during an SPI flash read an interrupt is triggered and the ISR tries to access cached memory.
What version of the IDF are you using? Specifically, what does this version do in line 446 of esp-idf/components/esp_hw_support/intr_alloc.c?

[vinci1989]

How can I interpret this?

To me it looks as though the issue could be that during an SPI flash read an interrupt is triggered and the ISR tries to access cached memory.
What version of the IDF are you using? Specifically, what does this version do in line 446 of esp-idf/components/esp_hw_support/intr_alloc.c?

It's a function called shared_intr_isr.

Code: Select all

static void IRAM_ATTR shared_intr_isr(void *arg)
{
    vector_desc_t *vd = (vector_desc_t*)arg;
    shared_vector_desc_t *sh_vec = vd->shared_vec_info;
    portENTER_CRITICAL_ISR(&spinlock);
    while(sh_vec) {
        if (!sh_vec->disabled) {
            if ((sh_vec->statusreg == NULL) || (*sh_vec->statusreg & sh_vec->statusmask)) {
                traceISR_ENTER(sh_vec->source + ETS_INTERNAL_INTR_SOURCE_OFF);
                
                sh_vec->isr(sh_vec->arg);  // Backtrace points here
                
                // check if we will return to scheduler or to interrupted task after ISR
                if (!os_task_switch_is_pended(esp_cpu_get_core_id())) {
                    traceISR_EXIT();
                }
            }
        }
        sh_vec = sh_vec->next;
    }
    portEXIT_CRITICAL_ISR(&spinlock);
}

[MicroController]

sh_vec->isr(sh_vec->arg); // Backtrace points here

This seems to indicate one of two things:
a) the shared_vector_desc_t @ *sh_vec is located in flash/PSRAM, or
b) the ISR it tries to call is in flash and not IRAM.
Maybe double-check the IRAM configuration of all relevant ISRs; and make sure that only IRAM ISRs are actually registered with ESP_INTR_FLAG_IRAM.

[vinci1989]

sh_vec->isr(sh_vec->arg); // Backtrace points here

This seems to indicate one of two things:
a) the shared_vector_desc_t @ *sh_vec is located in flash/PSRAM, or
b) the ISR it tries to call is in flash and not IRAM.
Maybe double-check the IRAM configuration of all relevant ISRs; and make sure that only IRAM ISRs are actually registered with ESP_INTR_FLAG_IRAM.

I've been able to reproduce my issue with fairly little code:
https://github.com/higaski/esp_idf_issue_12271
Apparently the combination of SPIFFS + RMT is enough to repro it.

That's why I've also opened an issue on that matter:
https://github.com/espressif/esp-idf/issues/12271

I'm quite sure that I got that "IRAM configuration stuff" right. Can you maybe elaborate further on a) ?
Is this also a configuration option I could set?

[MicroController]

Can you maybe elaborate further on a) ?

I think this is only a theoretical possibility, looking only at shared_intr_isr(). I haven't fully checked but I believe the shared_vector_desc_t are always allocated on the heap, in which case a) isn't actually possible.

[vinci1989]

Thank you, you've been on the right track.
This was indeed an ESP-IDF bug, quote:

The interrupt allocator internally allocated some buffer from the PSRAM, so causing the crash.