SD Card random long write times

CharlesSeartech
Posts: 19
Joined: Fri Oct 06, 2017 10:27 am

SD Card random long write times

Postby CharlesSeartech » Tue Jun 05, 2018 10:36 am

Hello,

I'm using a ESP-WROOM32 module with a SD card. My problem are the write times to the SD card. Our current system captures 1424 bytes of data and then it gets written to the SD card and if there is a WiFi connection sent over the WiFi to a server. I then started having problems with overrun on the data as the writing to the SD card was stalling. To prove that it's not any other task I'm running on the module that is the problem I have run the following test code, SD_CardTest(), to show the problem. SD_CardTest() if the first call in app_main().

The following code basically initializes the WROOM32 I/O, sets up the I2C and initializes my port expander I/O. The SDMMC is then initialized

Code: Select all

void SD_CardTest(void)
{
#define LOOP_OUTER    100
#define LOOP_MID 	    (740 / 10)
#define LOOP_INER        10

#define SD_BASE_PATH  		"/sdcard"
#define SD_PATH  			SD_BASE_PATH"/"

    BOARD_InitPins();

    ESP_LOGI(TAG, "Init_I2C");
    i2c_master_init();

    // Configure the port expander
    PCAL6408A_Initialize();

    char fname[64];
    TickType_t startTick;
    TickType_t endTick;
    static uint8_t data[1424];
    size_t result = 1;
    FILE* file_write;

    ESP_LOGI(TAG, "Initializing SD card");
    ESP_LOGI(TAG, "Using SDMMC peripheral");

    sdmmc_host_t host = SDMMC_HOST_DEFAULT();

    // This initializes the slot without card detect (CD) and write protect (WP) signals.
    // Modify slot_config.gpio_cd and slot_config.gpio_wp if your board has these signals.
    sdmmc_slot_config_t slot_config = SDMMC_SLOT_CONFIG_DEFAULT();

    // GPIOs 15, 2, 4, 12, 13 should have external 10k pull-ups.
    // Internal pull-ups are not sufficient. However, enabling internal pull-ups
    // does make a difference some boards, so we do that here.
    gpio_set_pull_mode(15, GPIO_PULLUP_ONLY);   // CMD, needed in 4- and 1- line modes
    gpio_set_pull_mode(2, GPIO_PULLUP_ONLY);    // D0, needed in 4- and 1-line modes
    gpio_set_pull_mode(4, GPIO_PULLUP_ONLY);    // D1, needed in 4-line mode only
    gpio_set_pull_mode(12, GPIO_PULLUP_ONLY);   // D2, needed in 4-line mode only
    gpio_set_pull_mode(13, GPIO_PULLUP_ONLY);   // D3, needed in 4- and 1-line modes

    // Options for mounting the filesystem.
    // If format_if_mount_failed is set to true, SD card will be partitioned and
    // formatted in case when mounting fails.
    esp_vfs_fat_sdmmc_mount_config_t mount_config = {
        .format_if_mount_failed = false,
        .max_files = 5
    };

    // Use settings defined above to initialize SD card and mount FAT filesystem.
    // Note: esp_vfs_fat_sdmmc_mount is an all-in-one convenience function.
    // Please check its source code and implement error recovery when developing
    // production applications.
    sdmmc_card_t* card;
    esp_err_t ret = esp_vfs_fat_sdmmc_mount(SD_BASE_PATH, &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 format_if_mount_failed = true.");
        } else {
            ESP_LOGE(TAG, "Failed to initialize the card (%d). "
                "Make sure SD card lines have pull-up resistors in place.", ret);
        }
        vAssertCalled( __FILE__, __LINE__ );
    }

    // Card has been initialized, print its properties
    sdmmc_card_print_info(stdout, card);

    // Use POSIX and C standard library functions to work with files.
    // First create a file.
    strcpy(fname, SD_PATH);
    strcat(fname, "test.bin");
    ESP_LOGI(TAG, "Opening file %s", fname);
    file_write = fopen(fname, "wb");
    if (file_write == NULL) {
        ESP_LOGE(TAG, "Failed to open file for writing");
        vAssertCalled( __FILE__, __LINE__ );
    }
    ESP_LOGI(TAG, "File open");

    memset(data, 'a', sizeof(data));
    ESP_LOGW(TAG, "Write test starting...");
    uint32_t dataLength = 0;
    for (int count=0; count<LOOP_OUTER; count++) {
        uint32_t dataWrite = 0;
        startTick = xTaskGetTickCount();
        result = 1;
        for (int loop=0; (loop<LOOP_MID) && result; loop++) {
            for (int i=0; i<LOOP_INER; i++) {
                TickType_t writeTick = xTaskGetTickCount();
                result = sd_card_write(file_write, data, sizeof(data));
                endTick = xTaskGetTickCount();
                if ((endTick - writeTick) > (50))
                    ESP_LOGW(TAG, "Write Time %d on count:%d, loop:%d, i:%d, length:%d", endTick - writeTick, count, loop, i, dataLength);
                //else if ((endTick - writeTick) > (25))
                    ESP_LOGW(TAG, "Write time %d", (endTick - writeTick));
                dataLength += result;
                dataWrite += result;
            }
            vTaskDelay(1);		// Give the IDLE task time to do its thing.
        }
        endTick = xTaskGetTickCount();
        ESP_LOGW(TAG, "Write time %d, length %d, count %d", (endTick - startTick), dataWrite, count);
        ESP_LOGW(TAG, "Ave write time %fms", (endTick - startTick) / ((float)LOOP_MID * LOOP_INER));
        ESP_LOGW(TAG, "Bytes per sec %dkB/s", dataWrite / ((endTick - startTick) / 1000) / 1000);
    }
    fclose(file_write);
    ESP_LOGI(TAG, "File closed");
}
The SD card is identified as follows:
Name: SL32G
Type: SDHC/SDXC
Speed: default speed
Size: 29664MB
CSD: ver=1, sector_size=512, capacity=60751872 read_bl_len=9
SCR: sd_spec=2, bus_width=5

My intention is to write each 1424 byte block as I receive them to the SD card but I get random delays writing to the SD card that don't make sense. These long delays can be seconds apart or minutes apart.
At random intervals I will have the following, all times are in miliseconds:
W (25423) main: Write time 5
W (25428) main: Write time 5
W (25433) main: Write time 5
W (25438) main: Write time 5
W (25441) main: Write time 3
W (25780) main: Write Time 339 on count:5, loop:26, length:11303712
W (25780) main: Write time 339
W (26135) main: Write Time 354 on count:5, loop:27, length:11306560
W (26135) main: Write time 354
W (26692) main: Write Time 557 on count:5, loop:27, length:11309408
W (26693) main: Write time 557
W (26988) main: Write Time 295 on count:5, loop:27, length:11312256
W (26988) main: Write time 295
W (27694) main: Write Time 706 on count:5, loop:27, length:11315104
W (27694) main: Write time 706
W (28041) main: Write Time 347 on count:5, loop:27, length:11317952
W (28041) main: Write time 347
W (28081) main: Write time 40
W (28094) main: Write time 13
W (28107) main: Write time 13
W (28121) main: Write time 13
W (28134) main: Write time 13
W (28147) main: Write time 12
... 70 or 80 more write times of 10ms to 14ms with a few in the 20's as well
W (29155) main: Write time 14
W (29167) main: Write time 12
W (29180) main: Write time 12
W (29186) main: Write time 6
W (29191) main: Write time 5
W (29196) main: Write time 5
W (29201) main: Write time 5

Then it will return to 3ms to 6ms with a random longer time 15ms to 25ms which I can understand as the FAT needs to be adjusted at times.

Can someone please explain why the SD card driver needs 339ms, 354ms, 557ms, 295ms, 706ms, 347ms, 40ms to to write each 1424 byte block?
At times it get so bad that the IDLE (CPU 0) task watchdog gets triggered. The times quoted above are from one sample, there seems to be no correlation between the failures, see below:
W (3443) main: Write Time 522 on count:0, loop:33, length:956928
W (4258) main: Write Time 815 on count:0, loop:33, length:959776
W (4679) main: Write Time 421 on count:0, loop:33, length:962624
W (5230) main: Write Time 551 on count:0, loop:33, length:965472
W (5523) main: Write Time 292 on count:0, loop:34, length:968320

or

W (15103) main: Write Time 225 on count:2, loop:50, i:0, length:2819520
W (15442) main: Write Time 339 on count:2, loop:50, i:1, length:2820944
W (15706) main: Write Time 264 on count:2, loop:50, i:2, length:2822368
W (15985) main: Write Time 279 on count:2, loop:50, i:3, length:2823792
W (16171) main: Write Time 186 on count:2, loop:50, i:4, length:2825216
W (16287) main: Write Time 116 on count:2, loop:50, i:5, length:2826640

Thanks,
Charles

ESP_Sprite
Posts: 9764
Joined: Thu Nov 26, 2015 4:08 am

Re: SD Card random long write times

Postby ESP_Sprite » Tue Jun 05, 2018 10:58 am

SD cards can be really slow and high-latency, especially if you're only writing small blocks at a time. It's the nature of the beast, unfortunately, and it varies from SD-card to SD-card. Has something to do witht he fact that the SD's internal blocksize and erase-size may not be the same as the sector size the SD-card-interface is using, so it sometimes needs time to do something like read-modify-erase-write cycles, or internal wear leveling cleanups. Suggest decoupling the SD-card writing from the collection task and putting a buffer in between. Furthermore, writing larger buffers (4K or multiples thereof probably will work well) at a time can also speed things up a bit.

CharlesSeartech
Posts: 19
Joined: Fri Oct 06, 2017 10:27 am

Re: SD Card random long write times

Postby CharlesSeartech » Fri Jun 08, 2018 11:16 am

Thanks for reply, I implemented a large buffer and although the long delays are still present I can manage them now.

Regards,
Charles

Who is online

Users browsing this forum: jtroncin21 and 106 guests