stat() function on SPIFFS is too slow (IDFGH-934)

[no1seman]

• Development Kit: ESP32-Wrover-Kit
• Kit version: v4
• Module or chip used: ESP32-WROVER
• IDF version: v4.0-dev-266-ge7f85f198
• Build System: CMake
• Compiler version: 1.22.0-80-g6c4433a
• Operating System: Linux
• Power Supply: USB

Problem Description

I my program logic I have to check file existance during config checks processing (see code in Code to reproduce this issue section). When I call is_file_exist() function during boot (before setting up Network, BLE, MQTT, etc. I've got 1,333 seconds delay for each check of file existance and when I call this function later from http handler - delay becomes terrible, about 14 seconds.
It seems to me that 1,33 for stat() - is inadmissible delay for such a function and 14 seconds - is out of my understanding.

Expected Behavior

stat() on SPIFFS must work rather faster in all circumstances.

Actual Behavior

stat() on SPIFFS tackes from 1,33 to 15 seconds acording to MCU payload or if there any other way to check file existance faster?

Steps to repropduce

call is_file_exist() after mounting SPIFFS and enabling WiFi and/or Ethernet, BLE, MQTT ...
sdkconfig.zip

Code to reproduce this issue

bool is_file_exist(char *filename)
{
ESP_LOGI(TAG, "Enter is_file_exist()");
if (is_filesystem_mounted())
{

    char *file_path = pvPortMalloc(strlen(MOUNT_PATH) + strlen(filename) + 3);

    strcpy(file_path, MOUNT_PATH);
    strcat(file_path, "/");
    strcat(file_path, filename);

    struct stat st;
    ESP_LOGI(TAG, "Before stat()");
    if (stat(file_path, &st) == 0)
    {
       ESP_LOGI(TAG, "After stat() if file exist");
        if (file_path)
        {
            vPortFree(file_path);
            file_path = NULL;
        }
        ESP_LOGI(TAG, "Exit is_file_exist()");
        return true;
    }
    else
    {
        ESP_LOGI(TAG, "After stat() if file NOT exist");
        if (file_path)
        {
            vPortFree(file_path);
            file_path = NULL;
        }
        CONFIG_LOGI("Exit is_file_exist()");
        return false;
    }
}

ESP_LOGI(TAG, "Exit is_file_exist()");
return false;
}

Debug Logs

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_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:0x3fff0018,len:4
load:0x3fff001c,len:6716
load:0x40078000,len:13312
load:0x40080400,len:7808
entry 0x40080780
I (28) boot: ESP-IDF v4.0-dev-266-ge7f85f198 2nd stage bootloader
I (28) boot: compile time 12:48:47
I (37) boot: Enabling RNG early entropy source...
I (38) qio_mode: Enabling QIO for flash chip WinBond
I (40) boot: SPI Speed      : 40MHz
I (44) boot: SPI Mode       : QIO
I (48) boot: SPI Flash Size : 8MB
I (52) boot: Partition Table:
I (56) boot: ## Label            Usage          Type ST Offset   Length
I (63) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (71) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (78) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (86) boot:  3 factory          factory app      00 00 00010000 001f0000
I (93) boot:  4 ota_0            OTA app          00 10 00200000 001f0000
I (100) boot:  5 ota_1            OTA app          00 11 003f0000 001f0000
I (108) boot:  6 storage          Unknown data     01 82 005e0000 00200000
I (116) boot:  7 coredump         Unknown data     01 03 007e0000 00020000
I (123) boot: End of partition table
I (127) boot: Defaulting to factory image
I (132) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x3655c (222556) map
I (207) esp_image: segment 1: paddr=0x00046584 vaddr=0x3ffbdb60 size=0x05b68 ( 23400) load
I (216) esp_image: segment 2: paddr=0x0004c0f4 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _WindowOverflow4 at /home/user/esp/esp-mdf/esp-idf/components/freertos/xtensa_vectors.S:1779

I (216) esp_image: segment 3: paddr=0x0004c4fc vaddr=0x40080400 size=0x03b14 ( 15124) load
I (229) esp_image: segment 4: paddr=0x00050018 vaddr=0x400d0018 size=0x105c80 (1072256) map
0x400d0018: _flash_cache_start at ??:?

I (551) esp_image: segment 5: paddr=0x00155ca0 vaddr=0x40083f14 size=0x1a2a4 (107172) load
0x40083f14: psram_spi_init at /home/user/esp/esp-mdf/esp-idf/components/esp32/spiram_psram.c:495 (discriminator 31)

I (610) boot: Loaded app from partition at offset 0x10000
I (610) boot: Disabling RNG early entropy source...
I (611) spiram: Found 64MBit SPI RAM device
I (615) spiram: SPI RAM mode: flash 40m sram 40m
I (620) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
I (627) cpu_start: Pro cpu up.
I (631) cpu_start: Application information:
I (636) cpu_start: Project name:     beacon
I (641) cpu_start: App version:      v.0.0.5-67-g1f08b83
I (647) cpu_start: Compile time:     Apr  8 2019 12:48:43
I (653) cpu_start: ELF file SHA256:  98aaed758a52caee...
I (659) cpu_start: ESP-IDF:          v4.0-dev-266-ge7f85f198
I (665) cpu_start: Starting app cpu, entry point is 0x4008154c
0x4008154c: call_start_cpu1 at /home/user/esp/esp-mdf/esp-idf/components/esp32/cpu_start.c:267

I (0) cpu_start: App cpu up.
I (677) heap_init: Initializing. RAM available for dynamic allocation:
I (683) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (689) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (695) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (701) heap_init: At 3FFBDB5C len 00000004 (0 KiB): DRAM
I (707) heap_init: At 3FFC5EB0 len 0001A150 (104 KiB): DRAM
I (713) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (719) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (726) heap_init: At 4009E1B8 len 00001E48 (7 KiB): IRAM
I (732) cpu_start: Pro cpu start user code
I (737) spiram: Adding pool of 4073K of external SPI memory to heap allocator
I (643) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (646) spiram: Reserving pool of 63K of internal memory for DMA/internal allocations
I (656) APP: Logging init completed
E (826) NVS: Error (ERROR) reading!

E (826) NVS: Error (ERROR) reading!

I (2446) FILESYSTEM: Filesystem mounted. Partition size: total: 1920401, used: 9538
I (2446) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (2456) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (2466) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (2476) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE

I (2536) CONFIG: Checking config...
........
I (2866) CONFIG: Processing value: 'CACertPemFile'
I (2866) CONFIG: Enter is_file_exist()
I (2876) CONFIG: Before stat()
I (4206) CONFIG: After stat() if NOT exist
I (4206) CONFIG: Exit is_file_exist()
I (4206) CONFIG: Processing value: 'ClientCertPemFile'
I (4216) CONFIG: Enter is_file_exist()
I (4216) CONFIG: Before stat()
I (5556) CONFIG: After stat() if NOT exist
I (5556) CONFIG: Exit is_file_exist()
I (5556) CONFIG: Processing value: 'ClientKeyPemFile'
I (5556) CONFIG: Enter is_file_exist()
I (5556) CONFIG: Before stat()
I (6896) CONFIG: After stat() if NOT exist
I (6896) CONFIG: Exit is_file_exist()
........
I (6926) CONFIG: Processing value: 'CACertPemFile'
I (6926) CONFIG: Enter is_file_exist()
I (6936) CONFIG: Before stat()
I (6946) CONFIG: After stat() if exist
I (6946) CONFIG: Exit is_file_exist()
I (6946) CONFIG: Processing value: 'PvtKeyPemFile'
I (6956) CONFIG: Enter is_file_exist()
I (6956) CONFIG: Before stat()
I (8296) CONFIG: After stat() if exist
I (8296) CONFIG: Exit is_file_exist()
............
I (8386) CONFIG: Checking config finished.
............
I (8576) CONFIG: Config successfully saved
.............
I (8726) ETHERNET: Power On Ethernet PHY
I (8736) SNTP: Initializing SNTP...
I (8746) ETHERNET: Started
.............
I (8766) MQTT: Setting up MQTT Client...
.............
I (22746) ETHERNET: Link Up
I (22746) ETHERNET: Connected. IP: '192.168.3.222', Netmask: '255.255.255.0', Gateway: '192.168.3.1'
I (22746) SNTP: SNTP client started
.............
I (25596) MQTT: MQTT client connected
.............
W (46776) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration
I (46916) phy: phy_version: 4100, 6fa5e27, Jan 25 2019, 17:02:06, 0, 2
I (47576) APP: Blink task started
I (47576) APP: Telnet task started
I (47576) APP: MQTT BLE task started
I (47586) APP: Beacons task started

<============ calling config check from http handler=========================================
I (283096) CONFIG: Checking config...
...............
I (283446) CONFIG: Processing value: 'CACertPemFile'
I (283456) CONFIG: Enter is_file_exist()
I (283456) CONFIG: Before stat()
I (298396) CONFIG: After stat() if NOT exist
I (298396) CONFIG: Exit is_file_exist()
I (298396) CONFIG: Processing value: 'ClientCertPemFile'
I (298396) CONFIG: Enter is_file_exist()
I (298406) CONFIG: Before stat()
I (322836) CONFIG: After stat() if NOT exist
I (322836) CONFIG: Exit is_file_exist()
I (322836) CONFIG: Processing value: 'ClientKeyPemFile'
I (322836) CONFIG: Enter is_file_exist()
I (322846) CONFIG: Before stat()
I (348866) CONFIG: After stat() if NOT exist
I (348866) CONFIG: Exit is_file_exist()
...............
I (348896) CONFIG: Processing value: 'CACertPemFile'
I (348906) CONFIG: Enter is_file_exist()
I (348906) CONFIG: Before stat()
I (349166) CONFIG: After stat() if exist
I (349166) CONFIG: Exit is_file_exist()
I (349166) CONFIG: Processing value: 'PvtKeyPemFile'
I (349166) CONFIG: Enter is_file_exist()
I (349166) CONFIG: Before stat()
I (376796) CONFIG: After stat() if exist
I (376796) CONFIG: Exit is_file_exist()
................
I (376886) CONFIG: Checking config finished.


 

Other items if possible

• sdkconfig file (attach the sdkconfig file from your project folder)

[igrr]

SPIFFS traverses the entire filesystem when doing open and stat operations, so they can take long time for larger partitions. See the issue in SPIFFS repository: pellepl/spiffs#169, specifically:

This is due to the design goal of using as little ram as possible - compared to other fs:s, there are no index tables or file trees built in memory.

Since SPIFFS does have a cache, order of files also matters. Consider 2 cases:

1. Best case, files are created in the same order as stat-ed. 736 read operations in 80ms:

I (13874) spi_flash: read   count=     736  time=   80948us  bytes=  106816
I (13875) spi_flash: write  count=       0  time=       0us  bytes=       0
I (13879) spi_flash: erase  count=       0  time=       0us  bytes=       0

2. Worst case, reverse order. 39k read operations in 4 seconds:

I (20996) spi_flash: read   count=   39272  time= 4221830us  bytes= 4741268
I (20997) spi_flash: write  count=       0  time=       0us  bytes=       0
I (21001) spi_flash: erase  count=       0  time=       0us  bytes=       0

Code used:

    test_setup();
    int file_count = 100;
    for (int i = 0; i < file_count; ++i) {
        char name[32];
        snprintf(name, sizeof(name), "%s%d.txt", filename, i);
        test_spiffs_create_file_with_text(name, "foo\n");
    }
    test_teardown();
    test_setup();
    spi_flash_reset_counters();
    for (int i = 0; i < file_count; ++i) {
        char name[32];
        snprintf(name, sizeof(name), "%s%d.txt", filename, i);
        struct stat st;
        TEST_ASSERT_EQUAL(0, stat(name, &st));
        TEST_ASSERT(st.st_mode & S_IFREG);
        TEST_ASSERT_FALSE(st.st_mode & S_IFDIR);
    }
    spi_flash_dump_counters();
    test_teardown();

and in the second test the loop is for (int i = file_count - 1; i >= 0; --i) {.

test_setup and test_teardown functions are from test_spiffs.c

In the context of IDF repository, we can't change the logic of SPIFFS. You can increase SPIFFS logical page size, which will result in fewer pages in the filesystem, and fewer read operations. With 512 byte page size, above "worst case" test results in 23k read operations. This is not orders of magnitude of improvement you are probably looking for, though.

Flash read operations are expensive on the ESP32 in dual core mode, and even more so if PSRAM support is enabled. It is possible to do some caching of flash reads, e.g. by reading whole 4kB sectors when SPIFFS only asks for 256 bytes. However this approach doesn't bring performance improvement, unfortunately. In the "worst case" test, such modification results in 13k flash read operations, but because each operation reads more data, the total time is increased to 10 seconds.

In the end, if you need better stat performance, it might make sense to either consider using FATFS, or to use a much smaller SPIFFS partition.

[no1seman]

OK, I understand, I will try to use FATFS, but...

...my partition is about 2 Mbytes, only 5 files and only 9538 bytes used:
-rw-rw-r-- 1 user user 2780 mar 30 23:09 beacon.json
-rw-r--r-- 1 user user 1150 oct 7 2018 favicon.ico
-rw-r--r-- 1 user user 1159 nov 22 08:26 http_cert.pem
-rw-r--r-- 1 user user 1704 nov 22 08:26 http_key.pem
-rw-rw-r-- 1 user user 959 nov 27 11:03 index.html

If I'm right stat() needs to read only 5 blocks (maximum) to find a file and all information to fill stat structure. I'm really confused that reading of 5 blocks may long 15 seconds. If it is so there no ways to use SPIFFS on ESP32 at all for any purposes?

Thanks

[igrr]

If I'm right stat() needs to read only 5 blocks (maximum) to find a file and all information to fill stat structure. I'm really confused that reading of 5 blocks may long 15 seconds.

@no1seman Please try enabling CONFIG_SPI_FLASH_ENABLE_COUNTERS in menuconfig, call spi_flash_reset_counters() before calling stat, and call spi_flash_dump_counters() after calling stat. This will print the number of read operations performed by SPIFFS.