esp-idf: SD Card write speeds considerably slower under 5.0.1 vs 4.4. (IDFGH-9592)

Answers checklist.

• I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

General issue report

I’m in the process of updating a project from IDF 4.4 to 5.0.1., and we’ve noticed a considerable drop in SD write speeds. I wrote up a test, using the the SDSPI SD Card example project as a base. Exact same code, see below, with the following results, using a PNY 128GB Class 10 SD Card, and an ESP32-PICO-V3-02:

• ESP IDF 4.4 = I (2712) SdCardSPI: Test writing 976 kB in 2100 ms (465.03kB/s)
• ESP IDF 5.0.1 = I (161682) SdCardSPI: Test writing 976 kB in 158910 ms (6.15kB/s)

*charstring.c is just #define BASESTRING1000 1000 character randomized string.

#include <errno.h>
#include <sys/unistd.h>
#include <sys/stat.h>
#include "esp_vfs_fat.h"
#include "sdmmc_cmd.h"
#include "charstring.c"

static const char *TAG = "SdCardSPI";

#define MOUNT_POINT "/sdcard"

// Pin mapping

/* works */
#define PIN_NUM_MISO 12
#define PIN_NUM_MOSI 13
#define PIN_NUM_CLK  14
#define PIN_NUM_CS   15

#define SPI_DMA_CHAN 1

void app_main(void)
{  
    esp_err_t ret;
    esp_vfs_fat_sdmmc_mount_config_t mount_config = {
        .format_if_mount_failed = true,
        .max_files = 5,
        .allocation_unit_size = 16 * 1024
    };
    sdmmc_card_t *card;
    const char mount_point[] = MOUNT_POINT;
    ESP_LOGI(TAG, "Initializing SD card");

    ESP_LOGI(TAG, "Using SPI peripheral");

    sdmmc_host_t host = SDSPI_HOST_DEFAULT();
    host.slot = SPI3_HOST;
    spi_bus_config_t bus_cfg = {
        .mosi_io_num = PIN_NUM_MOSI,
        .miso_io_num = PIN_NUM_MISO,
        .sclk_io_num = PIN_NUM_CLK,
        .quadwp_io_num = -1,
        .quadhd_io_num = -1,
        .max_transfer_sz = 4000,
    };
    ret = spi_bus_initialize(host.slot, &bus_cfg, SPI_DMA_CHAN);
    if (ret != ESP_OK) {
        ESP_LOGE(TAG, "Failed to initialize bus.");
        return;
    }

    sdspi_device_config_t slot_config = SDSPI_DEVICE_CONFIG_DEFAULT();
    slot_config.gpio_cs = PIN_NUM_CS;
    slot_config.host_id = host.slot;

    ESP_LOGI(TAG, "Mounting filesystem");
    ret = esp_vfs_fat_sdspi_mount(mount_point, &host, &slot_config, &mount_config, &card);

    if (ret != ESP_OK) {
        if (ret == ESP_FAIL) {
            ESP_LOGE(TAG, "Failed to mount filesystem. "
                     "If you want the card to be formatted, set the EXAMPLE_FORMAT_IF_MOUNT_FAILED menuconfig option.");
        } else {
            ESP_LOGE(TAG, "Failed to initialize the card (%s). "
                     "Make sure SD card lines have pull-up resistors in place.", esp_err_to_name(ret));
        }
        return;
    }
    ESP_LOGI(TAG, "Filesystem mounted");

    sdmmc_card_print_info(stdout, card);

    // First create a file.
    const char *file_hello = MOUNT_POINT"/hello.txt";

    ESP_LOGI(TAG, "Opening file %s", file_hello);
    FILE *f = fopen(file_hello, "w");
    if (f == NULL) {
        ESP_LOGE(TAG, "Failed to open file for writing, %s", strerror(errno));
        return;
    }
    fprintf(f, "Hello %s!\n", card->cid.name);
    fclose(f);
    ESP_LOGI(TAG, "Hello File written");

    const char *file_foo = MOUNT_POINT"/foo.txt";

    // Check if destination file exists before renaming
    struct stat st;
    if (stat(file_foo, &st) == 0) {
        // Delete it if it exists
        unlink(file_foo);
    }

    // Rename original file
    ESP_LOGI(TAG, "Renaming file %s to %s", file_hello, file_foo);
    if (rename(file_hello, file_foo) != 0) {
        ESP_LOGE(TAG, "Rename failed");
        return;
    }

    // Open renamed file for reading
    ESP_LOGI(TAG, "Reading file %s", file_foo);
    f = fopen(file_foo, "r");
    if (f == NULL) {
        ESP_LOGE(TAG, "Failed to open file for reading");
        return;
    }

    // Read a line from file
    char line[64];
    fgets(line, sizeof(line), f);
    fclose(f);

    // Strip newline
    char *pos = strchr(line, '\n');
    if (pos) {
        *pos = '\0';
    }
    ESP_LOGI(TAG, "Read from file: '%s'", line);

//#define BASESTR1000 "..."

    const char * file_test = MOUNT_POINT"/test.txt";
    FILE * test = fopen(file_test, "w");


    ESP_LOGI(TAG, "Start write test");
    TickType_t startTick = xTaskGetTickCount();

    int loopcount = 1000;
    for (int i = 0; i < loopcount; i++)
    {
        fwrite((const void *)BASESTR1000, strlen(BASESTR1000), 1, test);
    }
    TickType_t endTick = xTaskGetTickCount();
    ESP_LOGI(TAG, "Write complete, closing the file");
    fclose(test);

    uint32_t time_delta_ms  = pdTICKS_TO_MS(endTick - startTick);

    ESP_LOGI(TAG, "Test writing %d kB in %d ms (%.2fkB/s)",
        loopcount * strlen(BASESTR1000) / 1024, time_delta_ms, (double)loopcount * strlen(BASESTR1000) * 1000 / 1024 / time_delta_ms );

    // All done, unmount partition and disable SPI peripheral
    esp_vfs_fat_sdcard_unmount(mount_point, card);
    ESP_LOGI(TAG, "Card unmounted");

    //deinitialize the bus after all devices are removed
    spi_bus_free(host.slot);
}