NVS read and write take very long time (in QEMU)

[kozmotronik]

In unit tests of a component I develop, one of the time constrained tests was failing. I happened to profile the code that touches the NVS library. I discovered that NVS get and set functions take incredibly huge amount of time to execute, even longer than the nvs_commit function. In fact, I was expecting the nvs_commit() to take longer time than others to execute, some tens of millisecond not much... But it turns out that it is the opposite.

For reference, this is the code that was profiled and executed under test:

Code: Select all

esp_err_t relay_chn_nvs_set_direction(uint8_t ch, relay_chn_direction_t direction)
{
    uint8_t direction_val;
    int64_t start_time = esp_timer_get_time();
    esp_err_t ret = nvs_get_u8(relay_chn_nvs, RELAY_CHN_KEY_DIR, &direction_val);
    int64_t end_time = esp_timer_get_time();
    int64_t elapsed_time0 = end_time - start_time;
    if (ret == ESP_ERR_NVS_NOT_FOUND) {
        // The key does not exist yet, set it to zero which is the default direction
        direction_val = RELAY_CHN_DIRECTION_DEFAULT;
    } else if (ret != ESP_OK) {
        ESP_RETURN_ON_ERROR(ret, TAG, "Failed to get direction from NVS with error: %s", esp_err_to_name(ret));
    }
    direction_val &= ~(1 << ch); // Clear the bit for the channel
    direction_val |= (((uint8_t) direction) << ch); // Set the new direction bit
    start_time = esp_timer_get_time();
    ret = nvs_set_u8(relay_chn_nvs, RELAY_CHN_KEY_DIR, direction_val);
    end_time = esp_timer_get_time();
    int64_t elapsed_time1 = end_time - start_time;
    ESP_RETURN_ON_ERROR(ret, TAG, "Failed to set direction for channel %d", ch);
    start_time = esp_timer_get_time();
    ret = nvs_commit(relay_chn_nvs);
    end_time = esp_timer_get_time();
    int64_t elapsed_time2 = end_time - start_time;
    ESP_LOGI(TAG, "Elapsed time for NVS get: %lld us, set: %lld us, commit: %lld us for channel %d", elapsed_time0, elapsed_time1, elapsed_time2, ch); // TODO delete 
    return ret;
}

Also for reference, here is a sample portion of the relevant test logs:

Code: Select all

I (5433) RELAY_CHN_NVS: Elapsed time for NVS get: 40481 us, set: 150013 us, commit: 500 us for channel 0
I (5603) RELAY_CHN_NVS: Elapsed time for NVS get: 32402 us, set: 124315 us, commit: 437 us for channel 1
I (5753) RELAY_CHN_NVS: Elapsed time for NVS get: 32995 us, set: 111235 us, commit: 387 us for channel 2
I (5903) RELAY_CHN_NVS: Elapsed time for NVS get: 30535 us, set: 115365 us, commit: 389 us for channel 3
I (6053) RELAY_CHN_NVS: Elapsed time for NVS get: 30004 us, set: 118955 us, commit: 412 us for channel 4
I (6203) RELAY_CHN_NVS: Elapsed time for NVS get: 31180 us, set: 107339 us, commit: 372 us for channel 5
I (6363) RELAY_CHN_NVS: Elapsed time for NVS get: 33461 us, set: 125485 us, commit: 454 us for channel 6
I (6513) RELAY_CHN_NVS: Elapsed time for NVS get: 31983 us, set: 110347 us, commit: 374 us for channel 7

EDIT
Sorry, I didn't mention the testing environment above. IDF target was esp32 and the tests executed in qemu. I think this detail affects the metrics a lot because later on, I run the tests on a real hardware (esp32-c3-devkitm-1) with almost same configuration except the channel count (5 channels) because of the limited GPIO count. Well there is a huge difference between the emulator and the real hardware. Here is the relevant test log showing the get, set, and commit durations respectively:

Code: Select all

I (9339) RELAY_CHN_NVS: Elapsed time for NVS get: 39 us, set: 285 us, commit: 6 us for channel 0
I (9339) RELAY_CHN_NVS: Elapsed time for NVS get: 112 us, set: 482 us, commit: 5 us for channel 1
I (9349) RELAY_CHN_NVS: Elapsed time for NVS get: 77 us, set: 429 us, commit: 6 us for channel 2
I (9349) RELAY_CHN_NVS: Elapsed time for NVS get: 80 us, set: 426 us, commit: 5 us for channel 3
I (9369) RELAY_CHN_NVS: Elapsed time for NVS get: 68 us, set: 3061 us, commit: 6 us for channel 4
I (9629) RELAY_CHN_NVS: Elapsed time for NVS get: 88 us, set: 10227 us, commit: 5 us for channel 0
I (9629) RELAY_CHN_NVS: Elapsed time for NVS get: 70 us, set: 434 us, commit: 6 us for channel 1
I (9629) RELAY_CHN_NVS: Elapsed time for NVS get: 80 us, set: 435 us, commit: 5 us for channel 2
I (9639) RELAY_CHN_NVS: Elapsed time for NVS get: 71 us, set: 435 us, commit: 6 us for channel 3
I (9659) RELAY_CHN_NVS: Elapsed time for NVS get: 80 us, set: 7205 us, commit: 5 us for channel 4

As can be seen, the elapsed times for nvs_set varies between 285 us to 10227 us. Well, in my opinion even 10.224 ms is a considerable amount of time to execute on the main thread.

The only solution I could find was to create a low-priority background task to handle NVS operations and separate this code from the main thread. However, I would appreciate any advice from ESP-IDF experts on how to deal with this more efficiently in time-constrained code. Thank you!

Regards