Esp-idf: [TW#14555] Crash on WROVER working with flash pSRAM memory (IDFGH-857)

[nkolban]

I am working on a WROVER module using the latest ESP-IDF and toolchain for WROVER as of the date of this post. When I run my application (which is very large ... too much to simply supply you as a sample), I crash with the following exception log:

Guru Meditation Error: Core  0 panic'ed (Cache disabled but cached memory region accessed)
Register dump:
PC      : 0x400953ed  PS      : 0x00060b34  A0      : 0x80095b3c  A1      : 0x3ffce760  
0x400953ed: esp_rom_spiflash_read_data at /home/kolban/esp32/wrover/esp-idf/components/spi_flash/./spi_flash_rom_patch.c:412

A2      : 0x3ffae270  A3      : 0x001d2500  A4      : 0x3f800764  A5      : 0x00000050  
A6      : 0xf0000040  A7      : 0x00000005  A8      : 0x0000000f  A9      : 0x00000001  
A10     : 0x00042080  A11     : 0x3f800764  A12     : 0x00000ffc  A13     : 0x00000002  
A14     : 0x00000000  A15     : 0xff000000  SAR     : 0x00000020  EXCCAUSE: 0x00000007  
EXCVADDR: 0x00000000  LBEG    : 0x400012c5  LEND    : 0x400012d5  LCOUNT  : 0xfffffff6  

Backtrace: 0x400953ed:0x3ffce760 0x40095b3c:0x3ffce780 0x4008341b:0x3ffce7a0 0x40172332:0x3ffce800 0x401730c5:0x3ffce830 0x40174109:0x3ffce860 0x40174405:0x3ffce8d0 0x401759bd:0x3ffce910 0x40172d84:0x3ffce950 0x400df295:0x3ffce980 0x400deb18:0x3ffce9f0 0x4000bcc8:0x3ffcea10 0x4016894c:0x3ffcea30 0x400e5026:0x3ffcea50 0x400f5d2a:0x3ffceac0 0x400f9f38:0x3ffceb20 0x400f57b0:0x3ffceb40 0x400f5a84:0x3ffceba0 0x400f5c9d:0x3ffcec30 0x400f5ec8:0x3ffcec90 0x40108dac:0x3ffced60 0x400def66:0x3ffced80
0x400953ed: esp_rom_spiflash_read_data at /home/kolban/esp32/wrover/esp-idf/components/spi_flash/./spi_flash_rom_patch.c:412

0x40095b3c: esp_rom_spiflash_read at /home/kolban/esp32/wrover/esp-idf/components/spi_flash/./spi_flash_rom_patch.c:586

0x4008341b: spi_flash_read at /home/kolban/esp32/wrover/esp-idf/components/spi_flash/./flash_ops.c:405

0x40172332: esp32_spi_flash_read at /home/kolban/esp32/esptest/apps/workspace/duktape/components/spiffs/./esp_spiffs.c:66

0x401730c5: spiffs_phys_rd at /home/kolban/esp32/esptest/apps/workspace/duktape/components/spiffs/./spiffs_cache.c:143

0x40174109: spiffs_object_find_object_index_header_by_name_v at /home/kolban/esp32/esptest/apps/workspace/duktape/components/spiffs/./spiffs_nucleus.c:1114

0x40174405: spiffs_obj_lu_find_entry_visitor at /home/kolban/esp32/esptest/apps/workspace/duktape/components/spiffs/./spiffs_nucleus.c:1114

0x401759bd: spiffs_object_find_object_index_header_by_name at /home/kolban/esp32/esptest/apps/workspace/duktape/components/spiffs/./spiffs_nucleus.c:1655

0x40172d84: SPIFFS_stat at /home/kolban/esp32/esptest/apps/workspace/duktape/components/spiffs/./spiffs_hydrogen.c:795

0x400df295: vfs_stat at /home/kolban/esp32/esptest/apps/workspace/duktape/main/./duktape_spiffs.c:76

0x400deb18: esp_vfs_stat at /home/kolban/esp32/wrover/esp-idf/components/vfs/./vfs.c:283 (discriminator 3)

0x4016894c: stat at /home/jeroen/esp8266/esp32/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/syscalls/../../../.././newlib/libc/syscalls/sysstat.c:13

0x400e5026: js_fs_statSync at /home/kolban/esp32/esptest/apps/workspace/duktape/main/./module_fs.c:232

0x400f5d2a: duk__handle_call_inner at /home/kolban/esp32/esptest/apps/workspace/duktape/build/duktape/duk_api_stack.c:3752

0x400f9f38: duk_handle_call_unprotected at /home/kolban/esp32/esptest/apps/workspace/duktape/build/duktape/duk_api_stack.c:3752

0x400f57b0: duk__js_execute_bytecode_inner at /home/kolban/esp32/esptest/apps/workspace/duktape/build/duktape/duk_api_stack.c:3752

0x400f5a84: duk_js_execute_bytecode at /home/kolban/esp32/esptest/apps/workspace/duktape/build/duktape/duk_api_stack.c:3752

0x400f5c9d: duk__handle_call_inner at /home/kolban/esp32/esptest/apps/workspace/duktape/build/duktape/duk_api_stack.c:3752

0x400f5ec8: duk_handle_call_protected at /home/kolban/esp32/esptest/apps/workspace/duktape/build/duktape/duk_api_stack.c:3752

0x40108dac: duk_pcall at /home/kolban/esp32/esptest/apps/workspace/duktape/build/duktape/duk_api_stack.c:3752

0x400def66: duktape_task at /home/kolban/esp32/esptest/apps/workspace/duktape/main/./duktape_task.c:276


CPU halted.

As we see, we are failing deep in the heart of what appears to be ROM based code and far outside of my comprehension skills. I will be happy to switch on any additional diagnostics requested or demonstrate live via screen share.

[igrr]

Currently, when using the pSRAM, you must make sure that buffers passed to spi_flash_read function (and spi_flash_write as well) are not located in external memory. If the buffer coming from the upper layer (in your case that is SPIFFS, spiffs_phys_rd) can be allocated in external memory, you need to create a temporary buffer using heap_caps_malloc(size, MALLOC_CAP_DMA); to get some internal memory, read into this temporary buffer, and then copy to the buffer passed in by the application (which may be in pSRAM region).

The reason for this is that when we access SPI flash, we disable the cache, which is the mechanism which is used to memory-map SPI flash and SPI RAM into CPU's address space. With cache disabled, attempts to access memory-mapped SPI flash and SPI RAM will fail. This is why the buffer passed to spi_flash_read/spi_flash_write must be in the internal memory.

We will make this automatic within spi_flash_read functions, before integrating pSRAM support into master. For now, you need to do this yourself in your application.

Another thing to note: the stack of the task calling spi_flash_* functions must also be located in the internal memory, not in pSRAM. If it was in pSRAM, it would suddenly become inaccessible once cache is disabled inside spi_flash functions, which is certainly not going to end well. So make sure you that the stack is allocated in the internal memory. @Spritetm may give more guidance on that, as I am not sure how this is currently controlled in the pSRAM support branch.

[negativekelvin]

I am not sure how this is currently controlled in the pSRAM support branch.

AFAIK it is not other than the fact that internal memory has higher priority in heap allocator

[nkolban]

Thank you guys, this is pure gold. I'm hoping I didn't miss a readme or other public memo. Is there somewhere where we are collecting pSRAM notes like these? Hopefully others who may run into the problem in future may find a match on a search on Github issues. I will start work re-working my own code usage to exercise the new instructions/knowledge outlined above. I'll keep the issue open until then and add notes and results ... hopefully for the benefit of others. MANY thanks for responding.

[nkolban]

Hmmm .... a puzzle. I sat down this evening to try out this technique on the WROVER. According to instructions, for the WROVER, I am supposed to use this version of the ESP-IDF:

https://github.com/espressif/esp-idf/tree/feature/psram_malloc

However, that doesn't have the component called "heap" which is where I believe the heap_caps_malloc() is supposed to be found. I'm afraid I'm stuck.

[negativekelvin]

@nkolban it was branched before heap was split out as a separate component so it is still in /components/esp32

[nkolban]

@negativekelvin Thank you sir. Based upon your clues and the info from @igrr, I found a recipe which seems to work:

1. Include in my C source
2. Include "esp_heap_alloc_caps.h" in my C source
3. Instead of calling malloc() (what I had been doing) or heap_caps_malloc() (as @igrr suggested) I ended up calling pvPortMallocCaps(size, MALLOC_CAP_DMA)

So far so good ... seems to be working ... (fingers crossed).

(Edited: 2017-08-04 to correct a misspelled function name)

[negativekelvin]

I think you mean pvPortMallocCaps

[loboris]

I'm also having occasional error:
Guru Meditation Error: Core 0 panic'ed (Cache disabled but cached memory region accessed)

Guru Meditation Error: Core  0 panic'ed (Cache disabled but cached memory region accessed)
Register dump:
PC      : 0x40085830  PS      : 0x00060834  A0      : 0x8008146e  A1      : 0x3ffaeac0  
0x40085830: spi_flash_op_block_func at /home/LoBo2_Razno/ESP32/MicroPython/MicroPython_ESP32_psRAM_LoBo/esp-idf_psram/components/spi_flash/./cache_utils.c:84 (discriminator 1)

A2      : 0x3ffbfc01  A3      : 0x00000001  A4      : 0x3ffae5cc  A5      : 0x00000000  
A6      : 0x00000000  A7      : 0x00000001  A8      : 0x00000000  A9      : 0x3ffaeaa0  
A10     : 0x00000820  A11     : 0x3ffbfc08  A12     : 0x00000006  A13     : 0x3ff00040  
A14     : 0x00000828  A15     : 0x00000002  SAR     : 0x00000000  EXCCAUSE: 0x00000007  
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  

Backtrace: 0x40085830:0x3ffaeac0 0x4008146e:0x3ffaeae0
0x40085830: spi_flash_op_block_func at /home/LoBo2_Razno/ESP32/MicroPython/MicroPython_ESP32_psRAM_LoBo/esp-idf_psram/components/spi_flash/./cache_utils.c:84 (discriminator 1)

0x4008146e: ipc_task at /home/LoBo2_Razno/ESP32/MicroPython/MicroPython_ESP32_psRAM_LoBo/esp-idf_psram/components/esp32/./ipc.c:64


CPU halted.

I'm working with a large project (MicroPython port) and most of the time it works perfectly.
As far as I can tell, the mentioned error occurs only when accessing flash file system (both FatFS and SPIFFS (I'm using pvPortMallocCaps(size, MALLOC_CAP_DMA) and I can read/write files without problem most of the time)).
The error occurs randomly, for no obvious reason.
I'm running on both cores, but the error is always: Core 0 panic'ed, and always on the same place, _components/spi_flash/./cache_utils.c:84 (discriminator 1)_

[nkolban]

Howdy @loboris,
If you are interested, I'll be delighted to work with you to debug the issue. I think the core of the story will be look at the underlying spi_flash_* calls and see what they are passing in and receiving. From there we can take a look and see if are certain that we know the the memory was allocated from the MALLOC_CAP_DMA pool. My tests seemed to show that when I crashed, it was as a result of performing spi_flash calls using malloc'd memory that came from the pSRAM ... which based on the documented restrictions in the post from @igrr I seem to have circumvented by validating that I am allocating from the MALLOC_CAP_DMA pool.

[loboris]

@nkolban
I hope you'll have more success in debugging this issue, but maybe it's best to wait for the psRAM branch update.
I've tried all combinations of SPI RAM settings and SPI Flash/SPI RAM speeds, and the error always eventually occurs.
Even if I _disable_ malloc() can also allocate in SPI SRAM option, so that psRAM memory can be allocated only explicitly (and I'm doing this in one place only, when allocating MicroPython heap) using pvPortMallocCaps(size, MALLOC_CAP_DMA), the error still occurs.
It looks like it is not related to SPI flash read/write from application, but to instruction fetching/caching from flash, on more lower level than I'm capable of and willing to debug.
I was never able to find the exact place in application code which causes the error. Sometimes the application runs for hours and then crashes for no obvious reason.

[nkolban]

Oh my ... the key to me in the above was that you disabled malloc() for SPI SRAM and still the problem was encountered. This should result in no allocation of RAM from pSRAM that could possibily be used for flash source or destination for the file system APIs. If that's the case ... then (although I already was) ... I'm out of my depth and can't offer anything other than a fresh pair of eyes to listen to colleague thinking. I'll be happy to do that if you desire. Do we have any knowledge on when the "psRAM branch update" may be scheduled for?

[negativekelvin]

and I'm doing this in one place only, when allocating MicroPython heap) using pvPortMallocCaps(size, MALLOC_CAP_DMA)

I think you mean MALLOC_CAP_SPISRAM

Are you saying buffers in micropython heap are not used directly for filesystem transactions?

[loboris]

@negativekelvin
Yes, I've meant MALLOC_CAP_SPISRAM.
File system transactions are done via low level driver (_esp_spiffs.c_ for spiffs, wear leveling driver for FatFS) which allocates temporary buffers for r/w, so yes, micropython heap is never used directly in fs transactions.

Even if malloc() can also allocate in SPI SRAM is _enabled_, I always set the option that memory smaller than 32768 bytes is allocated in DRAM and, as far as I'm aware, nothing ever allocates the larger buffer.

I still think that the problem is on the lower level. Concurrent reads from spi flash & spi sram occurs all the time, instruction codes, if not cached are read from flash, micropython bytecode or/and tata are read from spi sram ... and somewhere, sometimes Cache disabled but cached memory region accessed error occurs.

[ikawaljeet]

Hi all,
I am also getting this error though in esp_ota_begin() function. My flash size is around 1.2MB and both ble and wifi is on at time of ota.
My partition file info: (make partition_table)

---

Espressif ESP32 Partition Table

Name, Type, SubType, Offset, Size, Flags

nvs,data,nvs,0x9000,16K,
otadata,data,ota,0xd000,8K,
phy_init,data,phy,0xf000,4K,
ota_0,app,ota_0,0x10000,1536K,
ota_1,app,ota_1,0x190000,1536K,

---

With ota example, it is working fine. With my project it is giving this error. I have used malloc throughout my project and when i see api, it is also using malloc only.
I am using esp-idf master branch to this date: commit:9a26296

[Spritetm]

@ikawaljeet: Do you have SPI RAM enabled?

[ikawaljeet]

If you mean "Support for external, SPI-connected RAM" then it is not enabled.

Though when i unloaded bluetooth stack, it got working. I think it was more of RAM availability problem on my side.

[igrr]

@loboris @nkolban Are you folks still seeing this issue in your applications?

[loboris]

Since SPIRAM support was merged into esp-idf master branch and Xtenssa toolchain I don't remember I had any issue.

[nkolban]

No sir ... I haven't seen any similar problems in a while.

[HanVertegaal]

I seem to be having this same problem in ESP-IDF v3.1.3:

`Guru Meditation Error: Core 0 panic'ed (Cache disabled but cached memory region accessed)
Core 0 register dump:
PC : 0x400995d8 PS : 0x00060434 A0 : 0x800860bc A1 : 0x3ffbd4f0
0x400995d8: memcpy at /home/jeroen/esp8266/esp32/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/machine/xtensa/../../../../.././newlib/libc/machine/xtensa/memcpy.S:342

A2 : 0x3f801020 A3 : 0x3ffbd538 A4 : 0x0000000b A5 : 0x3f801028
A6 : 0x9f3886a8 A7 : 0xa8bbfaba A8 : 0x9f3886a8 A9 : 0x3ffbd4c0
A10 : 0x00000000 A11 : 0x00000001 A12 : 0x3ffbd53c A13 : 0x00000000
A14 : 0xf0000040 A15 : 0x00000006 SAR : 0x00000008 EXCCAUSE: 0x00000007
EXCVADDR: 0x00000000 LBEG : 0x40099585 LEND : 0x400995b9 LCOUNT : 0xffffffff
0x40099585: memcpy at /home/jeroen/esp8266/esp32/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/machine/xtensa/../../../../.././newlib/libc/machine/xtensa/memcpy.S:291

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

Backtrace: 0x400995d8:0x3ffbd4f0 0x400860b9:0x3ffbd500 0x40115a9f:0x3ffbd570
0x40117803:0x3ffbd5a0 0x401eb911:0x3ffbd5d0 0x4011ae29:0x3ffbd5f0 0x40116ad8:0x3ffbd640 0x40117105:0x3ffbd670 0x401167a5:0x3ffbd690 0x4011f6b6:0x3ffbd6b0
0x4000bdbb:0x3ffbd6d0 0x40099f2e:0x3ffbd6f0 0x40121dc6:0x3ffbd710 0x401231d6:0x3ffbd730 0x401ec7c1:0x3ffbd750 0x40126732:0x3ffbd770 0x400f29f5:0x3ffbd7a0
0x400995d8: memcpy at /home/jeroen/esp8266/esp32/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/machine/xtensa/../../../../.././newlib/libc/machine/xtensa/memcpy.S:342

0x400860b9: spi_flash_read at /home/han/esp/esp-idf-v3.1.3/components/spi_flash/flash_ops.c:498

0x40115a9f: esp_partition_read at /home/han/esp/esp-idf-v3.1.3/components/spi_flash/partition.c:240

0x40117803: spiffs_api_read at /home/han/esp/esp-idf-v3.1.3/components/spiffs/spiffs_api.c:36

0x401eb911: spiffs_phys_rd at /home/han/esp/esp-idf-v3.1.3/components/spiffs/spiffs/src/spiffs_nucleus.c:70

0x4011ae29: spiffs_object_read at /home/han/esp/esp-idf-v3.1.3/components/spiffs/spiffs/src/spiffs_nucleus.c:2043

0x40116ad8: spiffs_hydro_read at /home/han/esp/esp-idf-v3.1.3/components/spiffs/spiffs/src/spiffs_hydrogen.c:1121

0x40117105: SPIFFS_read at /home/han/esp/esp-idf-v3.1.3/components/spiffs/spiffs/src/spiffs_hydrogen.c:1121

0x401167a5: vfs_spiffs_read at /home/han/esp/esp-idf-v3.1.3/components/spiffs/esp_spiffs.c:324

0x4011f6b6: esp_vfs_read at /home/han/esp/esp-idf-v3.1.3/components/vfs/vfs.c:962

0x40099f2e: read at /home/jeroen/esp8266/esp32/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/syscalls/../../../.././newlib/libc/syscalls/sysread.c:12

0x40121dc6: std::__basic_file::xsgetn(char*, int) at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/build/build-cc-gcc-final/xtensa-esp32-elf/libstdc++-v3/src/c++98/basic_file.cc:211

0x401231d6: std::basic_filebuf >::xsgetn(char*,
int) at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/build/build-cc-gcc-final/xtensa-esp32-elf/libstdc++-v3/include/fstream:758

0x401ec7c1: std::basic_streambuf >::sgetn(char*, int) at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/build/build-cc-gcc-final/xtensa-esp32-elf/libstdc++-v3/include/streambuf:436

0x40126732: std::istream::read(char*, int) at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/build/build-cc-gcc-final/xtensa-esp32-elf/libstdc++-v3/include/bits/streambuf_iterator.h:113

0x400f29f5: FileHelper::ReadFileTask(void*) at /mnt/c/Users/han/Documents/Projects/esp32base/components/network/fileHelper.cpp:146`

This happens whenever I try to copy a file from a spiffs filesystem in flash, into a buffer allocated in PSRAM.