Hi List,
I am using ZMS to log data. While performing stress tests, I see few issues:
- Including zms in the projects makes the application boot time delayed. The delay is ~2 minutes which is not acceptable for the application.
- The zms_mount() is failing with a return value of -22. This is happening ~3 in 10 attempts and executes successfully the remaining attempts. What can be done to ensure zms_mount() succeds next time after a failure?
- The GC operation is blocking the low priority threads in application. Is there a reference on how to control GC? I prefer initiating GC by the application rather than ZMS doing it in the background. But if its not possible, how can I ensure that the garbage collection (GC) is not blocking other threads.
my prj.conf is as follows:
CONFIG_FLASH=y
CONFIG_FLASH_MAP=y
CONFIG_ZMS=y
CONFIG_LOG=y
CONFIG_LOG_BLOCK_IN_THREAD=y
CONFIG_PM_PARTITION_SIZE_ZMS_STORAGE=0x10000
CONFIG_ZMS_LOG_LEVEL_INF=y
CONFIG_LOG=y
# Hardware
CONFIG_DK_LIBRARY=y
CONFIG_ZMS_DATA_CRC=y
I have modified the <zephyr/samples/subsys/fs/zms> sample.
/*
* Copyright (c) 2024 BayLibre SAS
*
* SPDX-License-Identifier: Apache-2.0
*
* ZMS Sample for Zephyr using high level API.
*
*/
#include <zephyr/kernel.h>
#include <zephyr/sys/reboot.h>
#include <zephyr/device.h>
#include <string.h>
#include <zephyr/drivers/flash.h>
#include <zephyr/storage/flash_map.h>
#include <zephyr/fs/zms.h>
#include <zephyr/logging/log.h>
#include <dk_buttons_and_leds.h>
#define ZMS_PARTITION storage_partition
#define ZMS_PARTITION_DEVICE FIXED_PARTITION_DEVICE(ZMS_PARTITION)
#define ZMS_PARTITION_OFFSET FIXED_PARTITION_OFFSET(ZMS_PARTITION)
#define IP_ADDRESS_ID 1
#define KEY_VALUE_ID 0xbeefdead
#define CNT_ID 2
#define LONG_DATA_ID 3
#define THREAD_LED_PRIORITY (4)
#define THREAD_ZVS_PRIORITY (10)
#define RUN_LED_BLINK_INTERVAL (15000) //Second
#define RUN_STATUS_LED DK_LED1
#define THREAD0_STACKSIZE (4096)
LOG_MODULE_REGISTER(main, LOG_LEVEL_INF);
static struct zms_fs fs;
static int delete_and_verify_items(struct zms_fs *fs, uint32_t id)
{
int rc = 0;
rc = zms_delete(fs, id);
if (rc) {
LOG_ERR("Error while deleting item rc=%d\n", rc);
return rc;
}
rc = zms_get_data_length(fs, id);
if (rc > 0) {
LOG_ERR("Error, Delete failed item should not be present\n");
return -1;
}
return 0;
}
static int delete_basic_items(struct zms_fs *fs)
{
int rc = 0;
rc = delete_and_verify_items(fs, IP_ADDRESS_ID);
if (rc) {
LOG_INF("Error while deleting item %x rc=%d\n", IP_ADDRESS_ID, rc);
return rc;
}
rc = delete_and_verify_items(fs, KEY_VALUE_ID);
if (rc) {
LOG_INF("Error while deleting item %x rc=%d\n", KEY_VALUE_ID, rc);
return rc;
}
rc = delete_and_verify_items(fs, CNT_ID);
if (rc) {
LOG_INF("Error while deleting item %x rc=%d\n", CNT_ID, rc);
return rc;
}
rc = delete_and_verify_items(fs, LONG_DATA_ID);
if (rc) {
LOG_INF("Error while deleting item %x rc=%d\n", LONG_DATA_ID, rc);
}
return rc;
}
int main(void)
{
LOG_INF("App started\n");
int err = dk_leds_init();
if (err)
{
LOG_INF("LEDs init failed (err %d)\n", err);
return 0;
}
#if 0
/* define the zms file system by settings with:
* sector_size equal to the pagesize,
* 3 sectors starting at ZMS_PARTITION_OFFSET
*/
fs.flash_device = ZMS_PARTITION_DEVICE;
if (!device_is_ready(fs.flash_device)) {
LOG_INF("Storage device %s is not ready\n", fs.flash_device->name);
return 0;
}
fs.offset = ZMS_PARTITION_OFFSET;
rc = flash_get_page_info_by_offs(fs.flash_device, fs.offset, &info);
if (rc) {
LOG_INF("Unable to get page info, rc=%d\n", rc);
return 0;
}
fs.sector_size = info.size;
fs.sector_count = 100U;
time_stamp = k_uptime_get();
rc = zms_mount(&fs);
delta_time = k_uptime_delta(&time_stamp);
if (rc)
{
LOG_INF("Storage Init failed, rc=%d\n", rc);
k_sleep(K_SECONDS(5));
return 0;
}
else
{
LOG_INF("ZMS initialized in %lu ms", delta_time);
}
free_space = zms_calc_free_space(&fs);
if (free_space < 0)
{
LOG_INF("Error while computing free space, rc=%d\n", free_space);
return 0;
}
LOG_INF("Free space in storage is %u bytes\n", free_space);
uint8_t rec[12];
LOG_INF("Rec size %u bytes\n", sizeof(rec));
i = 0; // write count
time_stamp = k_uptime_get();
while (1)
{
/* fill all storage */
*(uint32_t*)&rec[0] = i++;
rc = zms_write(&fs, id, rec, sizeof(rec));
// k_sleep(K_MSEC(10));
if (i % 10000 == 0)
{
printk("freespace=%u, data length of %d=%u", zms_calc_free_space(&fs), id, zms_get_data_length(&fs, id));
}
if ((i != 0) && (i % 50000 == 0))
{
delta_time = k_uptime_delta(&time_stamp);
printk("Filled %u records in %lu ms\n", i, delta_time);
time_stamp = k_uptime_get();
rc = zms_read_hist(&fs, id, read_buf[0], sizeof(rec), 100);
rc = zms_read_hist(&fs, id, read_buf[1], sizeof(rec), 99);
rc = zms_read_hist(&fs, id, read_buf[2], sizeof(rec), 98);
rc = zms_read_hist(&fs, id, read_buf[3], sizeof(rec), 97);
rc = zms_read_hist(&fs, id, read_buf[4], sizeof(rec), 96);
delta_time = k_uptime_delta(&time_stamp);
printk("\tRead 5 hist_record in %lu ms\n", delta_time);
LOG_HEXDUMP_INF(read_buf[0], sizeof(read_buf[0]), "100:");
LOG_HEXDUMP_INF(read_buf[1], sizeof(read_buf[1]), "99:");
LOG_HEXDUMP_INF(read_buf[2], sizeof(read_buf[2]), "98:");
LOG_HEXDUMP_INF(read_buf[3], sizeof(read_buf[3]), "97:");
LOG_HEXDUMP_INF(read_buf[4], sizeof(read_buf[4]), "96:");
// printk("freespace=%u, data length of %d=%u", zms_calc_free_space(&fs), id, zms_get_data_length(&fs, id));
time_stamp = k_uptime_get();
}
// i++;
// LOG_INF("Writing record with id %u, rc=%d\n", id, rc);
if (rc < 0) {
break;
}
id++;
id %= 2;//Limit to only 2 records
}
LOG_INF("Total recs filled, id=%u, rc=%d\n", id, rc);
LOG_INF("Profiling: total allocated: %u. Free space according to ZMS %u. Used for records of size %u: %u (Total bytes: %u) \n",
fs.sector_size*fs.sector_count, free_space, sizeof(rec), id, id * sizeof(rec));
if (rc == -ENOSPC)
{
/* Calculate free space and verify that it is 0 */
free_space = zms_calc_free_space(&fs);
if (free_space < 0) {
LOG_INF("Error while computing free space, rc=%d\n", free_space);
return 0;
}
if (free_space > 0) {
LOG_INF("Error: free_space should be 0, computed %u\n", free_space);
return 0;
}
LOG_INF("Memory is full let's delete all items\n");
/* Now delete all previously written items */
for (uint32_t n = 0; n < id; n++) {
rc = delete_and_verify_items(&fs, n);
if (rc) {
LOG_INF("Error deleting at id %u\n", n);
return 0;
}
}
}
/*
* Let's compute free space in storage. But before doing that let's Garbage collect
* all sectors where we deleted all entries and then compute the free space
*/
for (i = 0; i < fs.sector_count; i++)
{
rc = zms_sector_use_next(&fs);
if (rc)
{
LOG_INF("Error while changing sector rc=%d\n", rc);
}
}
free_space = zms_calc_free_space(&fs);
if (free_space < 0) {
LOG_INF("Error while computing free space, rc=%d\n", free_space);
return 0;
}
LOG_INF("Free space in storage is %u bytes\n", free_space);
/* Let's clean the storage now */
rc = zms_clear(&fs);
if (rc < 0) {
LOG_INF("Error while cleaning the storage, rc=%d\n", rc);
}
LOG_INF("Sample code finished Successfully\n");
#else
static bool led_stat = false;
while (1)
{
k_sleep(K_MSEC(25000));
dk_set_led(DK_LED2, led_stat);
led_stat = !led_stat;
}
#endif
return 0;
}
void ledThread(void)
{
static bool led_stat = false;
while (1)
{
k_sleep(K_MSEC(RUN_LED_BLINK_INTERVAL));
dk_set_led(RUN_STATUS_LED, led_stat);
led_stat = !led_stat;
}
}
void zvsTestThread(void)
{
int rc = 0;
uint64_t time_stamp;
int64_t delta_time;
uint32_t i;
uint32_t id = 0;
ssize_t free_space = 0;
struct flash_pages_info info;
uint8_t read_buf[5][16] = {0};
/* define the zms file system by settings with:
* sector_size equal to the pagesize,
* 3 sectors starting at ZMS_PARTITION_OFFSET
*/
fs.flash_device = ZMS_PARTITION_DEVICE;
if (!device_is_ready(fs.flash_device)) {
LOG_INF("Storage device %s is not ready\n", fs.flash_device->name);
return 0;
}
fs.offset = ZMS_PARTITION_OFFSET;
rc = flash_get_page_info_by_offs(fs.flash_device, fs.offset, &info);
if (rc) {
LOG_INF("Unable to get page info, rc=%d\n", rc);
return 0;
}
fs.sector_size = info.size;
fs.sector_count = 10U;
time_stamp = k_uptime_get();
rc = zms_mount(&fs);
delta_time = k_uptime_delta(&time_stamp);
if (rc)
{
LOG_INF("Storage Init failed, rc=%d\n", rc);
k_sleep(K_SECONDS(5));
return 0;
}
else
{
LOG_INF("ZMS initialized in %lu ms", delta_time);
}
free_space = zms_calc_free_space(&fs);
if (free_space < 0)
{
LOG_INF("Error while computing free space, rc=%d\n", free_space);
return 0;
}
LOG_INF("Free space in storage is %u bytes\n", free_space);
uint8_t rec[12];
LOG_INF("Rec size %u bytes\n", sizeof(rec));
i = 0; // write count
time_stamp = k_uptime_get();
while (1)
{
/* fill all storage */
*(uint32_t*)&rec[0] = i++;
rc = zms_write(&fs, id, rec, sizeof(rec));
// k_sleep(K_MSEC(10));
if (i % 10000 == 0)
{
printk("\tfreespace=%u, data length[%d]=%u\n\r", zms_calc_free_space(&fs), id, zms_get_data_length(&fs, id));
}
if ((i != 0) && (i % 50000 == 0))
{
delta_time = k_uptime_delta(&time_stamp);
printk("Filled %u records in %lu ms\n\r", i, delta_time);
time_stamp = k_uptime_get();
rc = zms_read_hist(&fs, id, read_buf[0], sizeof(rec), 100); // Read last 100th record. 0 being the last record.
rc = zms_read_hist(&fs, id, read_buf[1], sizeof(rec), 99); // Read last 100th record. 0 being the last record.
rc = zms_read_hist(&fs, id, read_buf[2], sizeof(rec), 98); // Read last 100th record. 0 being the last record.
rc = zms_read_hist(&fs, id, read_buf[3], sizeof(rec), 97); // Read last 100th record. 0 being the last record.
rc = zms_read_hist(&fs, id, read_buf[4], sizeof(rec), 96); // Read last 100th record. 0 being the last record.
delta_time = k_uptime_delta(&time_stamp);
printk("\tRead 5 hist_record in %lu ms\n", delta_time);
LOG_HEXDUMP_INF(read_buf[0], sizeof(read_buf[0]), "100:");
LOG_HEXDUMP_INF(read_buf[1], sizeof(read_buf[1]), "99:");
LOG_HEXDUMP_INF(read_buf[2], sizeof(read_buf[2]), "98:");
LOG_HEXDUMP_INF(read_buf[3], sizeof(read_buf[3]), "97:");
LOG_HEXDUMP_INF(read_buf[4], sizeof(read_buf[4]), "96:");
// printk("freespace=%u, data length of %d=%u", zms_calc_free_space(&fs), id, zms_get_data_length(&fs, id));
time_stamp = k_uptime_get();
}
// i++;
// LOG_INF("Writing record with id %u, rc=%d\n", id, rc);
if (rc < 0) {
break;
}
id++;
id %= 2;//Limit to only 2 records
}
LOG_INF("Total recs filled, id=%u, rc=%d\n", id, rc);
LOG_INF("Profiling: total allocated: %u. Free space according to ZMS %u. Used for records of size %u: %u (Total bytes: %u) \n",
fs.sector_size*fs.sector_count, free_space, sizeof(rec), id, id * sizeof(rec));
if (rc == -ENOSPC)
{
/* Calculate free space and verify that it is 0 */
free_space = zms_calc_free_space(&fs);
if (free_space < 0) {
LOG_INF("Error while computing free space, rc=%d\n", free_space);
return 0;
}
if (free_space > 0) {
LOG_INF("Error: free_space should be 0, computed %u\n", free_space);
return 0;
}
LOG_INF("Memory is full let's delete all items\n");
/* Now delete all previously written items */
for (uint32_t n = 0; n < id; n++) {
rc = delete_and_verify_items(&fs, n);
if (rc) {
LOG_INF("Error deleting at id %u\n", n);
return 0;
}
}
}
/*
* Let's compute free space in storage. But before doing that let's Garbage collect
* all sectors where we deleted all entries and then compute the free space
*/
for (i = 0; i < fs.sector_count; i++)
{
rc = zms_sector_use_next(&fs);
if (rc)
{
LOG_INF("Error while changing sector rc=%d\n", rc);
}
}
free_space = zms_calc_free_space(&fs);
if (free_space < 0) {
LOG_INF("Error while computing free space, rc=%d\n", free_space);
return 0;
}
LOG_INF("Free space in storage is %u bytes\n", free_space);
/* Let's clean the storage now */
rc = zms_clear(&fs);
if (rc < 0) {
LOG_INF("Error while cleaning the storage, rc=%d\n", rc);
}
LOG_INF("Sample code finished Successfully\n");
}
K_THREAD_DEFINE(ledThread_id, THREAD0_STACKSIZE, ledThread, NULL, NULL, NULL, THREAD_LED_PRIORITY, 0, 0);
K_THREAD_DEFINE(rramThread_id, THREAD0_STACKSIZE, zvsTestThread, NULL, NULL, NULL, THREAD_ZVS_PRIORITY, 0, 0);This source is initializing ZMS in a low priority thread. Though this reduces the boot time, ZMS memory is not available to the application after the boot. It takes few (hundred) seconds before data can be logged to ZMS.
I'ld appreciate any suggestions or comments on handling the ZMS data logging mechanism.
Project Setup: nrf54L15DK, VScode, nRF Connect SDK, Zephyr
Best regards
Sarma
