Including ZMS makes a delayed Application ON time

[Sarma]

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

[Sarma]

SDK Version is 3.1.0. Logging is set to INF level. 

[Einar Thorsrud]

I see. But do you have any logging not in ZMS or any debug information that can shed some light on what is happening? I am very curious about what is taking two minutes.

[Sarma]

The Boot time is monitored without any timer or HW support by observation. As the logs were set to "INF", there was no detail in the log. Moving to "DBG" was further delaying. 

The Delay is measured between the start of the LED Toggle (high priority tasks) and the first INF log in the ZMS thread in the sample code attached. 

[Einar Thorsrud]

Hi,

Have you done any other debugging to see what is happening? Looking at your code, your LED blink thread has priority 4. This is lower than the main therad, which as a default priority of 0 (higher number = lower priority). And you have a lot of ZMS work being done in main. I suspect this is what takes time, and this will block your other lower priority threads.

[Sarma]

Hello Einar,
The ZMS activity is running in a low priority thread(Pri = 10). The code in the main thread is commented out (See line # 96 in main().)

Here's the code with the #ifdefs removed and GPIOs used to measure the actual time with LOGS removed.

/*
 * 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)
{
	static bool led_stat = false;  

	LOG_INF("App started\n");

	int err = dk_leds_init();
    dk_set_led(RUN_STATUS_LED, true);
	if (err) 
    {
		LOG_INF("LEDs init failed (err %d)\n", err);
		return 0;
	}
    dk_set_led(RUN_STATUS_LED, false);
	while (1) 
    {
        k_sleep(K_MSEC(25000));
    	dk_set_led(DK_LED2, led_stat);
        led_stat = !led_stat;
    }
	return 0;
}

void ledThread(void)
{
	static bool led_stat = false; 

    while (1) 
    {
        k_sleep(K_MSEC(RUN_LED_BLINK_INTERVAL));
    	dk_set_led(DK_LED3, 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);
	dk_set_led(RUN_STATUS_LED, true);
	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) 
	{
		dk_set_led(RUN_STATUS_LED, false);
		/* 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
		dk_set_led(RUN_STATUS_LED, true);
	}

	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 LOG mechanism prints the data on serial terminal via an ultra low priority thread. This clarifies the delay in logs since the LED toggles start, which I considered as actual delay.The first concern stands cleared!.
• I am still not clear with how to initiate GC from my code as I still see the ZMSThread not letting higher priority threads not execute (or starve) when its executing GC. This can be a problem for my application. 
• The available space for User data is not consistant with the large data values details given here: https://docs.nordicsemi.com/bundle/ncs-3.0.2/page/zephyr/services/storage/zms/zms.html#:~:text=Device%20lifetime%20calculation&text=The%20partition%20has%204%20sectors,moving%20blocks%20all%20the%20time.
  • In my example, I have used 10 sectors of 4096 byte to store data of length 12 byte (large data model). 
  • Expecting to save 1290 records without overwriting in the memory but was able to save only 1094 records. 
• The zms_mount() fails with an error. This is not consistant but when happens, the recovery path is not clear. 

Please advice. 

Best regards
Sarma

[Einar Thorsrud]

Hi Sarma,

There is no explicit way to trigger GC with ZMS. However, there are ways around this, explained under Triggering garbage collection.

For data larger than 8 byte (like your 12 byte data), you need to account for an additional 16 byte ATE header. See Large data values. Can you show how you calculated 1290 records?

The -22 (EINVAL) when calling zsm_mount(). I suggest narrowing down by debugging in the implementation to see which of the many checks there that can cause this return value (or enable logging so that you get a printout indicating which check failed).

Br,

Einar