SPIFFS ftell doesn't return

[NathanJPhillips]

I repeatedly write a bit to an SPIFFS file and then call ftell on it. After doing this a few times (less than 100) in quick succession, ftell fairly consistently just hangs, doesn't return and uses all the CPU, causing a task WDT to report errors. Which source should I look at to start investigating where the loop could be that its spinning around in? I'm not sure where to find the ftell implementation in the ESP IDF.

[NathanJPhillips]

By way of update, I still haven't solved this, but my current best guess is that the culprit may be around cache_utils.c:141

Code: Select all

        while (!s_flash_op_can_start) {
            // Busy loop and wait for spi_flash_op_block_func to disable cache
            // on the other CPU
        }

I get to this by way of the following call stack:

Code: Select all

0x40084301: gpio_isr_loop at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/driver/gpio.c:405
 (inlined by) gpio_intr_service at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/driver/gpio.c:422
0x400819ed: shared_intr_isr at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/esp32/intr_alloc.c:508
0x40082945: _xt_lowint1 at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/freertos/xtensa_vectors.S:1153
0x40082fbb: spi_flash_disable_interrupts_caches_and_other_cpu at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/spi_flash/cache_utils.c:141 (discriminator 1)
0x40083e1d: spi1_start at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/spi_flash/spi_flash_os_func_app.c:59
0x400876c5: spiflash_start at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/spi_flash/esp_flash_api.c:78
0x40083d5d: esp_flash_write at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/spi_flash/esp_flash_api.c:610
0x4011c8ad: esp_partition_write at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/spi_flash/partition.c:389
0x4010a723: spiffs_api_write at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/spiffs/spiffs_api.c:47
0x4010e3fb: spiffs_phys_wr at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/spiffs/spiffs/src/spiffs_cache.c:221
0x4010c56c: spiffs_page_delete at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/spiffs/spiffs/src/spiffs_nucleus.c:884 (discriminator 4)
0x4010c6cb: spiffs_page_move at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/spiffs/spiffs/src/spiffs_nucleus.c:869 (discriminator 2)
0x4010ca9a: spiffs_object_update_index_hdr at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/spiffs/spiffs/src/spiffs_nucleus.c:1019 (discriminator 4)
0x4010d196: spiffs_object_append at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/spiffs/spiffs/src/spiffs_nucleus.c:1439
0x4010a812: spiffs_hydro_write at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/spiffs/spiffs/src/spiffs_hydrogen.c:450
0x4010a881: spiffs_fflush_cache at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/spiffs/spiffs/src/spiffs_hydrogen.c:863
0x4010b148: SPIFFS_lseek at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/spiffs/spiffs/src/spiffs_hydrogen.c:610 (discriminator 2)
0x4010a365: vfs_spiffs_lseek at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/spiffs/esp_spiffs.c:517
0x400d62a6: esp_vfs_lseek at C:/Users/Nathan.Phillips/Desktop/esp-idf/components/vfs/vfs.c:433 (discriminator 3)
0x401b7d8f: _ftello_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/ftello.c:120
0x401b7cf4: _ftell_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/ftell.c:91
 (inlined by) ftell at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/ftell.c:105

[NathanJPhillips]

This is obviously a difficult one, judging by the echoes in here (hello anyone?)

My best guess now is that the reason we get stuck in the loop above is because we have a deadlock caused when the other core is tied up waiting for the core that ftell is called from (in my case by esp_ipc_call_blocking, which is used from esp_intr_free). Weirdly, despite this latter being an IPC call from a user task the WDT reports the other core being in the IDLE task, which is why it was hard to see that both cores were waiting for the other.

Still no obvious solution springs to mind.