Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Using SPIFFS and SDSPI together at the same time results in a lockup (IDFGH-4722) #6529

Closed
pyjamasam opened this issue Feb 11, 2021 · 7 comments
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally

Comments

@pyjamasam
Copy link

Environment

  • Development Kit: none
  • Kit version: N/A
  • Module or chip used: ESP32-WROOM-32D
  • IDF version: v4.2-238-g8cd16b60f and v4.4-dev-4-g73db14240
  • Build System: idf.py
  • Compiler version: For both esp-idf v4.2 and v4.4-dev I am using xtensa-esp32-elf-gcc (crosstool-NG esp-2020r3) 8.4.0
  • Operating System: macOS
  • Using an IDE?: VSCode and Command line. Doesn't change the outcome of the issue
  • Power Supply: USB

Problem Description

When writing to a SDSPI connected SD card (Using the VSPI bus with the standard pins via IOMUX) in one task and trying to read a file from a SPIFFS partition in another task from the same core an exception occurs.

The current example code is using fatfs directly vs through the VFS layer as I was attempting to trim down the code that caused the problem. But this problem also occurs when using the vfs layer for SD card access.

Expected Behavior

Data should be written to the SD card, and data should be read from the SPIFFS partition

Actual Behavior

When running with my project sdkconfig file settings the chip locks up and eventually resets due to the watchdog with a DoubleException

When running the a default sdkconfig file a core panic occurs due to 'Cache disabled but cached memory region accessed'

Steps to reproduce

A repository with code to reproduce the error
https://github.com/pyjamasam/SPIFFS_SDSPI_Test

Connect a SD card via the VSPI standard pins:
MOSI = GPIO23
MISO = GPIO19
CLK = GPIO18
CS = GPIO5

I have tried with a 10k pull up to 3.3v on MOSI.

Running the referenced code will result in an error (when the SD card initializes correctly - once the error occurs the esp will restart and then the SD card will not initialize correctly. It then takes a few restart cycles until the SD card is ready to be used again).

Code to reproduce this issue

https://github.com/pyjamasam/SPIFFS_SDSPI_Test

Debug Logs

rst:0xc (SW_CPU_RESET),boot:0x13 (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:0x3fff0030,len:6924
ho 0 tail 12 room 4
load:0x40078000,len:14336
load:0x40080400,len:3672
0x40080400: _init at ??:?

entry 0x40080678
I (29) boot: ESP-IDF v4.4-dev-4-g73db14240-dirty 2nd stage bootloader
I (29) boot: compile time 16:23:44
I (30) boot: chip revision: 1
I (33) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (41) boot.esp32: SPI Speed      : 40MHz
I (45) boot.esp32: SPI Mode       : DIO
I (50) boot.esp32: SPI Flash Size : 4MB
I (54) boot: Enabling RNG early entropy source...
I (60) boot: Partition Table:
I (63) boot: ## Label            Usage          Type ST Offset   Length
I (71) boot:  0 coredump         Unknown data     01 03 00009000 00005000
I (78) boot:  1 otadata          OTA data         01 00 0000e000 00002000
I (85) boot:  2 app0             OTA app          00 10 00010000 00180000
I (93) boot:  3 app1             OTA app          00 11 00190000 00180000
I (100) boot:  4 spiffs-ui        Unknown data     01 82 00310000 000e1000
I (108) boot:  5 spiffs-data      Unknown data     01 82 003f1000 0000c000
I (116) boot:  6 nvs              WiFi data        01 02 003fd000 00003000
I (123) boot: End of partition table
I (127) boot_comm: chip revision: 1, min. application chip revision: 0
I (135) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=0b60ch ( 46604) map
I (160) esp_image: segment 1: paddr=0001b634 vaddr=3ffb0000 size=02c84h ( 11396) load
I (164) esp_image: segment 2: paddr=0001e2c0 vaddr=40080000 size=01d58h (  7512) load
I (168) esp_image: segment 3: paddr=00020020 vaddr=400d0020 size=23754h (145236) map
I (225) esp_image: segment 4: paddr=0004377c vaddr=40081d58 size=0b7c0h ( 47040) load
I (252) boot: Loaded app from partition at offset 0x10000
I (252) boot: Disabling RNG early entropy source...
I (263) cpu_start: Pro cpu up.
I (263) cpu_start: Starting app cpu, entry point is 0x40081194
0x40081194: call_start_cpu1 at /Users/chris/esp-idf/components/esp_system/port/cpu_start.c:143

I (249) cpu_start: App cpu up.
I (278) cpu_start: Pro cpu start user code
I (278) cpu_start: cpu freq: 160000000
I (278) cpu_start: Application information:
I (282) cpu_start: Project name:     SPIFFS_SD_Test
I (288) cpu_start: App version:      e083801
I (293) cpu_start: Compile time:     Feb 11 2021 16:23:37
I (299) cpu_start: ELF file SHA256:  1565b70710e7a330...
I (305) cpu_start: ESP-IDF:          v4.4-dev-4-g73db14240-dirty
I (312) heap_init: Initializing. RAM available for dynamic allocation:
I (319) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (325) heap_init: At 3FFB5948 len 0002A6B8 (169 KiB): DRAM
I (331) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (337) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (344) heap_init: At 4008D518 len 00012AE8 (74 KiB): IRAM
I (351) spi_flash: detected chip: generic
I (355) spi_flash: flash io: dio
I (360) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.








I (371) core0: Setup starting...
I (381) spiffs: Initializing SPIFFS partition (spiffs-ui)...
I (481) spiffs: Partition size (spiffs-ui): total: 839846, used: 18825
I (481) sdcard: Initializing SD card (spi)...
I (481) gpio: GPIO[5]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (531) sdspi_transaction: cmd=5, R1 response: command not supported
Name: 00000
Type: SDHC/SDXC
Speed: 20 MHz
Size: 15279MB
I (541) sdcard: SD card online
I (541) core0: Setup complete
I (571) core1: Setup starting...
I (571) core1: Setup complete
I (771) core0: Processing starting...
E (771) core0: about to open file
I (771) core1: Processing starting...
E (771) core0: about write
I (771) core0_1: Processing starting...
E (781) core0_1: about to open file
wrote: 1024
E (791) core0_1: file open
E (791) core0_1: about to read
E (791) core0_1: about to read
E (791) core0_1: about to read
E (801) core0: about write
E (791) core0_1: about to read
wrote: 1024
E (801) core0_1: about to read
E (811) core0: about write
Re-enable cpu cache.
Guru Meditation Error: Core  0 panic'ed (Cache disabled but cached memory region accessed). 

Core  0 register dump:
PC      : 0x400e06a8  PS      : 0x00060034  A0      : 0x800847b8  A1      : 0x3ffb07e0  
0x400e06a8: spi_bus_intr_disable at /Users/chris/esp-idf/components/driver/spi_master.c:512

A2      : 0x3ffbcc00  A3      : 0x3ffba754  A4      : 0x80082f2d  A5      : 0x3ffc6b40  
A6      : 0x00000026  A7      : 0x3ffb5784  A8      : 0x80085138  A9      : 0x3ffb96e8  
A10     : 0x3ffbcc60  A11     : 0x3ffc6cb0  A12     : 0xfffffff7  A13     : 0x3ffc6b20  
A14     : 0x00000020  A15     : 0xffffeffb  SAR     : 0x00000018  EXCCAUSE: 0x00000007  
EXCVADDR: 0x00000000  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0x00000000  

Backtrace:0x400e06a5:0x3ffb07e0 0x400847b5:0x3ffb0800 0x40082651:0x3ffb0830 0x4000c305:0x3ffc6b20 0x40089b95:0x3ffc6b30 0x4008c459:0x3ffc6b60 0x40083c83:0x3ffc6be0 0x400dd9c6:0x3ffc6c20 0x400d8add:0x3ffc6c50 0x400dc5fb:0x3ffc6c80 0x400d9e33:0x3ffc6cb0 0x400dc0f9:0x3ffc6ce0 0x400d8d48:0x3ffc6d30 0x400d92ad:0x3ffc6d60 0x400d88f2:0x3ffc6d80 0x400d203a:0x3ffc6da0 0x4000bdbb:0x3ffc6dc0 0x40001125:0x3ffc6de0 0x400594e9:0x3ffc6e00 0x400e405d:0x3ffc6e20 0x400e40ed:0x3ffc6e60 0x400d646d:0x3ffc6e80 0x4008923d:0x3ffc6eb0
0x400e06a5: spi_master_deinit_driver at /Users/chris/esp-idf/components/driver/spi_master.c:288

0x400847b5: spi_intr at /Users/chris/esp-idf/components/driver/spi_master.c:603

0x40082651: _xt_medint3 at /Users/chris/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1274

0x40089b95: spi_flash_ll_get_buffer_data at /Users/chris/esp-idf/components/hal/esp32/include/hal/spi_flash_ll.h:146
 (inlined by) spi_flash_hal_read at /Users/chris/esp-idf/components/hal/spi_flash_hal_common.inc:189

0x4008c459: spi_flash_chip_generic_read at /Users/chris/esp-idf/components/spi_flash/spi_flash_chip_generic.c:206

0x40083c83: esp_flash_read at /Users/chris/esp-idf/components/spi_flash/esp_flash_api.c:663 (discriminator 4)

0x400dd9c6: esp_partition_read at /Users/chris/esp-idf/components/spi_flash/partition.c:347

0x400d8add: spiffs_api_read at /Users/chris/esp-idf/components/spiffs/spiffs_api.c:36

0x400dc5fb: spiffs_phys_rd at /Users/chris/esp-idf/components/spiffs/spiffs/src/spiffs_cache.c:161

0x400d9e33: spiffs_page_data_check at /Users/chris/esp-idf/components/spiffs/spiffs/src/spiffs_nucleus.c:20

0x400dc0f9: spiffs_object_read at /Users/chris/esp-idf/components/spiffs/spiffs/src/spiffs_nucleus.c:2035

0x400d8d48: spiffs_hydro_read at /Users/chris/esp-idf/components/spiffs/spiffs/src/spiffs_hydrogen.c:414

0x400d92ad: SPIFFS_read at /Users/chris/esp-idf/components/spiffs/spiffs/src/spiffs_hydrogen.c:426

0x400d88f2: vfs_spiffs_read at /Users/chris/esp-idf/components/spiffs/esp_spiffs.c:504

0x400d203a: esp_vfs_read at /Users/chris/esp-idf/components/vfs/vfs.c:449 (discriminator 3)

0x400e405d: _fread_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/fread.c:228

0x400e40ed: fread at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/fread.c:266

0x400d646d: processing_core0_1(void*) at /Users/chris/Documents/Projects/SPIFFS_SDSPI_Test/build/../main/main.cpp:83

0x4008923d: vPortTaskWrapper at /Users/chris/esp-idf/components/freertos/port/xtensa/port.c:168

Other items if possible

  • Multiple sdkconfig files are in the referenced repository which result in slightly differnt lockup scenarios. One (sdkconfig.project) results in a silent lockup, and the other (sdkconfig) produces the Cache panic.
@github-actions github-actions bot changed the title Using SPIFFS and SDSPI together at the same time results in a lockup Using SPIFFS and SDSPI together at the same time results in a lockup (IDFGH-4722) Feb 11, 2021
@igrr
Copy link
Member

igrr commented Feb 11, 2021

@pyjamasam For the cache issue, could you please try modifying spi_bus_intr_disable function in /Users/chris/esp-idf/components/driver/spi_master.c:512 as follows:

static void SPI_MASTER_ISR_ATTR spi_bus_intr_disable(void *host)

(add SPI_MASTER_ISR_ATTR).

For the lockup issue, it seems you have interrupt watchdog disabled in sdkconfig. Could you please try enabling it and see if this yields any additional information (e.g. a backtrace)?

@pyjamasam
Copy link
Author

Thanks for the quick response Ivan,

Enabling the interrupt watchdog did not result in any change to the lockup observed when using my sdkconfig.project file.

It still resulted in a silent lockup and then the following message after restarting

W (202) boot.esp32: WDT reset info: PRO CPU PC=0x400803c3
0x400803c3: _DoubleExceptionVector at /Users/chris/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:457

W (208) boot.esp32: WDT reset info: APP CPU PC=0x40083586
0x40083586: spi_flash_op_block_func at /Users/chris/esp-idf/components/spi_flash/cache_utils.c:115 (discriminator 1)

And the default sdkconfig that is also in the repository had that flag enabled and produced the original stack trace included in the issue.

BUT

Adding SPI_MASTER_ISR_ATTR to spi_master.c for the spi_bus_intr_disable function results the correct behaviour of being able to read from SPIFFS and write the SD card at the same time. In both IDF v4.2 and master (v4.4-dev).

I will test the fix in my larger application and report back the status of that.

@pyjamasam
Copy link
Author

I have been running at test for about 20 hours now, and I can successfully write the the SD card and continue to read from SPIFFS. This is using the IDF v4.2 tag with the modification to spi_master.c.

Thank you very much for the help with with. From my standpoint I consider this to be fixed, but I'd like to see it as part of the official repo.
Is there anything I need to do further to help this get added in to an upcoming release?

@igrr
Copy link
Member

igrr commented Feb 13, 2021

Thanks for the confirmation @pyjamasam, we will fix this in the master branch and also backport to release/v4.2. This issue will be closed once the fix is merged.

@AxelLin
Copy link
Contributor

AxelLin commented Aug 5, 2021

Thanks for the confirmation @pyjamasam, we will fix this in the master branch and also backport to release/v4.2. This issue will be closed once the fix is merged.

Hi @igrr
The issue is reported again by #7368
How is the status of the fix?

@ginkgm
Copy link
Collaborator

ginkgm commented Aug 5, 2021

Hi @AxelLin ,

It's being reviewed internally. There's no other considerations about it, so I think the reviewing will be fast.

@espressif-bot espressif-bot added Resolution: Done Issue is done internally Status: Done Issue is done internally labels Aug 9, 2021
@Alvin1Zhang
Copy link
Collaborator

Thanks for reporting, fix on master branch is available de0f24e, we are back porting the fix to release/4.2, thanks.

espressif-bot pushed a commit that referenced this issue Aug 11, 2021
espressif-bot pushed a commit that referenced this issue Oct 29, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally
Projects
None yet
Development

No branches or pull requests

6 participants