fast isr_handler during flash write or erase gives "Cache disabled but cached memory region accessed"

[bwendin]

We are using the example ISR handler for mcpwm esp-idf/examples/peripherals/mcpwm/mcpwm_bldc_control/main/mcpwm_bldc_control_hall_sensor_example.c
CAP0 is setup on rising edge, and CAP1 on falling edge of a 910Hz signal. So we are getting interrupts every at a rate of 1.82Khz.

Our main loop writes to NVRAM periodically and we get this failure. If I don't call mcpwm_isr_register to add the isr_handle, I never get this error form serial port:


15:13 , 15:13 Guru Meditation Error: Core 0 panic'ed (Cache disabled but cached memory region accessed)
Core 0 register dump:
PC : 0x40088d6b PS : 0x00060034 A0 : 0x80088de0 A1 : 0x3ffbf0e0
0x40088d6b: esp_cpu_stall at C:/msys32/home/Infusion/esp/esp-idf/components/soc/esp32/cpu_util.c:27

A2 : 0xbad00bad A3 : 0x00000001 A4 : 0x80090e91 A5 : 0x3ffbb1d0
A6 : 0x00000000 A7 : 0x3ffbb200 A8 : 0x3f417f04 A9 : 0x00000000
A10 : 0x00000000 A11 : 0x000000ff A12 : 0x00000000 A13 : 0x3ffbb1b0
A14 : 0x00000000 A15 : 0x00000005 SAR : 0x0000001b EXCCAUSE: 0x00000007
EXCVADDR: 0x00000000 LBEG : 0x40096579 LEND : 0x40096590 LCOUNT : 0xfffffffe
0x40096579: lmacRecycleMPDU at ??:?

0x40096590: lmacRecycleMPDU at ??:?

Core 0 was running in ISR context:
EPC1 : 0x400899c4 EPC2 : 0x40091026 EPC3 : 0x00000000 EPC4 : 0x40088d6b
0x400899c4: get_mmu_region at C:/msys32/home/Infusion/esp/esp-idf/components/spi_flash/flash_mmap.c:382

0x40091026: prvReceiveGeneric at C:/msys32/home/Infusion/esp/esp-idf/components/esp_ringbuf/ringbuf.c:969

0x40088d6b: esp_cpu_stall at C:/msys32/home/Infusion/esp/esp-idf/components/soc/esp32/cpu_util.c:27


ELF file SHA256: ad0bd0baad0bd0baad0bd0baad0bd0baad0bd0baad0bd0baad0bd0baad0bd0ba

Backtrace: 0x40088d6b:0x3ffbf0e0 0x40088ddd:0x3ffbf100 0x40088261:0x3ffbf130 0x40091023:0x3ffbb230 0x40091821:0x3ffbb250 0x400894e2:0x3ffbb270 0x40122b51:0x3ffbb2e0 0x40121e41:0x3ffbb300 0x40121ea5:0x3ffbb320 0
x40122475:0x3ffbb360 0x40120cc1:0x3ffbb3c0 0x4011f829:0x3ffbb430 0x4011ff79:0x3ffbb480 0x40184bde:0x3ffbb4a0 0x4012a437:0x3ffbb4c0 0x40124051:0x3ffbb500 0x40124112:0x3ffbb530 0x4010d0fe:0x3ffbb560 0x4010c617:0x
3ffbb5a0 0x400d07e2:0x3ffbb5e0 0x4009c731:0x3ffbb600
0x40088d6b: esp_cpu_stall at C:/msys32/home/Infusion/esp/esp-idf/components/soc/esp32/cpu_util.c:27

0x40088ddd: esp_cpu_unstall at C:/msys32/home/Infusion/esp/esp-idf/components/soc/esp32/cpu_util.c:37

0x40088261: _xt_medint3 at C:/msys32/home/Infusion/esp/esp-idf/components/freertos/xtensa_vectors.S:1323

0x40091023: prvReceiveGeneric at C:/msys32/home/Infusion/esp/esp-idf/components/esp_ringbuf/ringbuf.c:969

0x40091821: xthal_window_spill_nw at /Users/igrokhotkov/e/esp32/hal/hal/windowspill_asm.S:135

0x400894e2: spi_flash_read at C:/msys32/home/Infusion/esp/esp-idf/components/spi_flash/flash_ops.c:624 (discriminator 4)

0x40122b51: nvs::Item::calculateCrc32() const at C:/msys32/home/Infusion/esp/esp-idf/components/nvs_flash/src/nvs_types.cpp:29

0x40121e41: nvs::Page::readEntry(unsigned int, nvs::Item&) const at C:/msys32/home/Infusion/esp/esp-idf/components/nvs_flash/src/nvs_page.cpp:852

0x40121ea5: nvs::Page::eraseEntryAndSpan(unsigned int) at C:/msys32/home/Infusion/esp/esp-idf/components/nvs_flash/src/nvs_page.cpp:852

0x40122475: nvs::Page::mLoadEntryTable() at C:/msys32/home/Infusion/esp/esp-idf/components/nvs_flash/src/nvs_page.cpp:852

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

0x4011f829: int nvs_set<unsigned int>(unsigned int, char const*, unsigned int) at C:/msys32/home/Infusion/esp/esp-idf/components/nvs_flash/src/nvs_api.cpp:486

0x4011ff79: nvs_set_i64 at C:/msys32/home/Infusion/esp/esp-idf/components/nvs_flash/src/nvs_api.cpp:486

0x40184bde: BWPStoreWrite at C:/Users/Infusion/Documents/breadware/bwesp32/components/bwdriveresp32/bwpstoreesp32.c:124

0x4012a437: PurVOCReadValue at C:/Users/Infusion/Documents/breadware/puretecESP/components/purdrivers/purvoc.c:184

0x40124051: PurVOCPoll at C:/Users/Infusion/Documents/breadware/puretecESP/components/purapplication/pursensors.c:43

0x40124112: PurSensorsPoll at C:/Users/Infusion/Documents/breadware/puretecESP/components/purapplication/pursensors.c:226

0x4010d0fe: AppRun at C:/Users/Infusion/Documents/breadware/puretecESP/main/app.c:371

0x4010c617: app_main at C:/Users/Infusion/Documents/breadware/puretecESP/main/purtec.c:40 (discriminator 12)

0x400d07e2: main_task at C:/msys32/home/Infusion/esp/esp-idf/components/esp32/cpu_start.c:542

0x4009c731: vPortYield at C:/msys32/home/Infusion/esp/esp-idf/components/freertos/portasm.S:555


Rebooting...
ets Jun 8 2016 00:22:57

rst:0x3 (SW_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:6368
ho 0 tail 12 room 4
load:0x40078000,len:11624
ho 0 tail 12 room 4
load:0x40080400,len:6648
entry 0x40080764
I (32) boot: ESP-IDF v3.3-dirty 2nd stage bootloader
I (32) boot: compile time 13:36:28
I (32) boot: Enabling RNG early entropy source...
I (37) boot: SPI Speed : 40MHz
I (41) boot: SPI Mode : DIO
I (45) boot: SPI Flash Size : 8MB
I (49) boot: Partition Table:
I (53) boot: ## Label Usage Type ST Offset Length
I (60) boot: 0 nvs WiFi data 01 02 00009000 00004000
I (68) boot: 1 otadata OTA data 01 00 0000d000 00002000
I (75) boot: 2 phy_init RF data 01 01 0000f000 00001000
I (83) boot: 3 ota_0 OTA app 00 10 00010000 00300000
I (90) boot: 4 ota_1 OTA app 00 11 00310000 00300000
I (98) boot: End of partition table
I (102) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x4c290 (311952) map
I (220) esp_image: segment 1: paddr=0x0005c2b8 vaddr=0x3ffbdb60 size=0x03d58 ( 15704) load
I (227) esp_image: segment 2: paddr=0x00060018 vaddr=0x400d0018 size=0x120b80 (1182592) map
0x400d0018: _flash_cache_start at ??:?

I (642) esp_image: segment 3: paddr=0x00180ba0 vaddr=0x3ffc18b8 size=0x01894 ( 6292) load
I (645) esp_image: segment 4: paddr=0x0018243c vaddr=0x40080000 size=0x00400 ( 1024) load
0x40080000: _WindowOverflow4 at C:/msys32/home/Infusion/esp/esp-idf/components/freertos/xtensa_vectors.S:1779

I (649) esp_image: segment 5: paddr=0x00182844 vaddr=0x40080400 size=0x1eeb4 (126644) load
I (729) boot: Loaded app from partition at offset 0x10000
I (729) boot: Disabling RNG early entropy source...
I (729) psram: This chip is ESP32-D0WD
I (735) spiram: Found 64MBit SPI RAM device

[bwendin]

And it appears this happens with NVS reads too:

DEBUG: tvocPPB: 0ppb ethanolRaw: 34063
Guru Meditation Error: Core 0 panic'ed (Cache disabled but cached memory region accessed)
Core 0 register dump:
PC : 0x40088d6b PS : 0x00060034 A0 : 0x80088de0 A1 : 0x3ffbf0e0
0x40088d6b: esp_cpu_stall at C:/msys32/home/Infusion/esp/esp-idf/components/soc/esp32/cpu_util.c:27

A2 : 0xbad00bad A3 : 0x00000001 A4 : 0x800899c4 A5 : 0x3ffbb270
A6 : 0x00000006 A7 : 0x3ffc5838 A8 : 0x3f417f04 A9 : 0x3ffbb690
A10 : 0xf0000070 A11 : 0x00000000 A12 : 0xfffffff7 A13 : 0x3ffbb250
A14 : 0x00004020 A15 : 0xfff9cffb SAR : 0x00000015 EXCCAUSE: 0x00000007
EXCVADDR: 0x00000000 LBEG : 0x40096579 LEND : 0x40096590 LCOUNT : 0xfffffffd
0x40096579: lmacRecycleMPDU at ??:?

0x40096590: lmacRecycleMPDU at ??:?

Core 0 was running in ISR context:
EPC1 : 0x400899c4 EPC2 : 0x4008942a EPC3 : 0x00000000 EPC4 : 0x40088d6b
0x400899c4: get_mmu_region at C:/msys32/home/Infusion/esp/esp-idf/components/spi_flash/flash_mmap.c:382

0x4008942a: spi_flash_guard_start at C:/msys32/home/Infusion/esp/esp-idf/components/spi_flash/flash_ops.c:161
(inlined by) spi_flash_read at C:/msys32/home/Infusion/esp/esp-idf/components/spi_flash/flash_ops.c:586

0x40088d6b: esp_cpu_stall at C:/msys32/home/Infusion/esp/esp-idf/components/soc/esp32/cpu_util.c:27


ELF file SHA256: ad0bd0baad0bd0baad0bd0baad0bd0baad0bd0baad0bd0baad0bd0baad0bd0ba

Backtrace: 0x40088d6b:0x3ffbf0e0 0x40088ddd:0x3ffbf100 0x40088261:0x3ffbf130 0x40089427:0x3ffbb2b0 0x40122b51:0x3ffbb320 0x40121e41:0x3ffbb340 0x4012220f:0x3ffbb360 0x40122376:0x3ffbb3c0 0x40120a61:0x3ffbb440 0
x4011f9ed:0x3ffbb4a0 0x401200c1:0x3ffbb4e0 0x40184da1:0x3ffbb500 0x4010cad3:0x3ffbb530 0x4010d10c:0x3ffbb560 0x4010c617:0x3ffbb5a0 0x400d07e2:0x3ffbb5e0 0x4009c731:0x3ffbb600
0x40088d6b: esp_cpu_stall at C:/msys32/home/Infusion/esp/esp-idf/components/soc/esp32/cpu_util.c:27

0x40088ddd: esp_cpu_unstall at C:/msys32/home/Infusion/esp/esp-idf/components/soc/esp32/cpu_util.c:37

0x40088261: _xt_medint3 at C:/msys32/home/Infusion/esp/esp-idf/components/freertos/xtensa_vectors.S:1323

0x40089427: spi_flash_guard_end at C:/msys32/home/Infusion/esp/esp-idf/components/spi_flash/flash_ops.c:169
(inlined by) spi_flash_read at C:/msys32/home/Infusion/esp/esp-idf/components/spi_flash/flash_ops.c:585

0x40122b51: nvs::Item::calculateCrc32() const at C:/msys32/home/Infusion/esp/esp-idf/components/nvs_flash/src/nvs_types.cpp:29

0x40121e41: nvs::Page::readEntry(unsigned int, nvs::Item&) const at C:/msys32/home/Infusion/esp/esp-idf/components/nvs_flash/src/nvs_page.cpp:852

0x4012220f: nvs::Page::findItem(unsigned char, nvs::ItemType, char const*, unsigned int&, nvs::Item&, unsigned char, nvs::VerOffset) at C:/msys32/home/Infusion/esp/esp-idf/components/nvs_flash/src/nvs_page.cpp:
852

0x40122376: nvs::isVariableLengthType(nvs::ItemType) at C:/msys32/home/Infusion/esp/esp-idf/components/nvs_flash/src/nvs_page.cpp:852
(inlined by) nvs::Page::readItem(unsigned char, nvs::ItemType, char const*, void*, unsigned int, unsigned char, nvs::VerOffset) at C:/msys32/home/Infusion/esp/esp-idf/components/nvs_flash/src/nvs_page.cpp:274

0x40120a61: nvs::Storage::readItem(unsigned char, nvs::ItemType, char const*, void*, unsigned int) at C:/msys32/home/Infusion/esp/esp-idf/components/nvs_flash/src/nvs_storage.cpp:557

0x4011f9ed: nvs::Lock::~Lock() at C:/msys32/home/Infusion/esp/esp-idf/components/nvs_flash/src/nvs_api.cpp:486
(inlined by) nvs_get<short unsigned int> at C:/msys32/home/Infusion/esp/esp-idf/components/nvs_flash/src/nvs_api.cpp:438

0x401200c1: nvs_get_i32 at C:/msys32/home/Infusion/esp/esp-idf/components/nvs_flash/src/nvs_api.cpp:486

0x40184da1: BWPStoreRead at C:/Users/Infusion/Documents/breadware/bwesp32/components/bwdriveresp32/bwpstoreesp32.c:275

0x4010cad3: AppPresenceDetectedDelayPeriodIsActive at C:/Users/Infusion/Documents/breadware/puretecESP/main/app.c:235

0x4010d10c: AppRun at C:/Users/Infusion/Documents/breadware/puretecESP/main/app.c:383

0x4010c617: app_main at C:/Users/Infusion/Documents/breadware/puretecESP/main/purtec.c:40 (discriminator 12)

0x400d07e2: main_task at C:/msys32/home/Infusion/esp/esp-idf/components/esp32/cpu_start.c:542

0x4009c731: vPortYield at C:/msys32/home/Infusion/esp/esp-idf/components/freertos/portasm.S:555


Rebooting...
ets Jun 8 2016 00:22:57

rst:0x3 (SW_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:6368
ho 0 tail 12 room 4
load:0x40078000,len:11624
ho 0 tail 12 room 4
load:0x40080400,len:6648
entry 0x40080764
I (32) boot: ESP-IDF v3.3-dirty 2nd stage bootloader
I (32) boot: compile time 13:36:28
I (32) boot: Enabling RNG early entropy source...
I (37) boot: SPI Speed : 40MHz
I (41) boot: SPI Mode : DIO
I (45) boot: SPI Flash Size : 8MB
I (49) boot: Partition Table:
I (53) boot: ## Label Usage Type ST Offset Length
I (60) boot: 0 nvs WiFi data 01 02

[szguyer]

This problem seems very similar to the one I have been encountering (see post viewtopic.php?f=13&t=13855 from yesterday).

I think the relevant documentation is here:

https://github.com/espressif/esp-idf/tr ... sh-on-spi1

"Because the SPI1 flash is also used for firmware execution via the instruction & data caches, these caches must be disabled while reading/writing/erasing. This means that both CPUs must be running code from IRAM and must only be reading data from DRAM while flash write operations occur."

[ESP_igrr]

Hi bwendin,

What arguments do you pass to mcpwm_isr_register? If you mark this interrupt as IRAM capable, you need to make sure that the interrupt handler and the functions called by it are placed into IRAM. You can do the latter either using IRAM_ATTR attribute or (preferably) a linker fragment file.

[bwendin]

Regarding, mcpwm_isr_register questions, I copied mcpwm_bldc_control example so I am calling ISR in IRAM_ATTR context:

mcpwm_isr_register(MCPWM_UNIT_0, isr_handler, NULL, ESP_INTR_FLAG_IRAM, NULL);

[ESP_Angus]

Hi bwendin,

Passing the "ESP_INTR_FLAG_IRAM" marks the ISR as "IRAM safe", meaning it will only ever access buffers allocated from internal memory and execute functions that are loaded into IRAM not flash.

This means that the ISR can keep running even while writing to flash (including NVS operations). Otherwise any pending interrupt is queued until after the flash operation finishes.

The fix is either to remove the flag (pass 0 for this argument), or to make sure all of the isr_handler function is in IRAM and doesn't access any flash or call a function which accesses flash.

You can find some more documentation about this here: https://docs.espressif.com/projects/esp ... t-handlers

Angus