Why does NVS sometimes erase sector during initialization?

[Joyop]

Hi,

I've met a problem. It seems NVS sometimes erases sector during initialization.

As shown in following log, I wrote 2 datas(address, slot) in NVS. Normally, I can read both of these data after a reset. But sometimes, the data will be erased as log shown.

00> *** Booting Zephyr OS build v2.7.99-ncs1-1  ***
00> 
00> [00:00:00.004,516] <inf> main: ** Example start **
00> [00:00:00.009,338] <inf> pal_interrupt: Set up button IRQ at GPIO_0 pin 13
00> [00:00:00.016,235] <inf> pal_interrupt: Set up dw3k IRQ at GPIO_1 pin 9.
00> [00:00:00.022,979] <inf> pal_spi: SPI INIT DONE: SCK 4, MISO 5, MOSI 6, CS: 7.
00> [00:00:00.030,487] <dbg> fs_nvs.nvs_recover_last_ate: Recovering last ate from sector 1
00> [00:00:00.045,166] <inf> fs_nvs: 6 Sectors of 4096 bytes
00> [00:00:00.050,445] <inf> fs_nvs: alloc wra: 1, fe0
00> [00:00:00.055,175] <inf> fs_nvs: data wra: 1, 10
00> [00:00:00.060,577] <inf> sdc_hci_driver: SoftDevice Controller build revision: 
00>                                          0e e7 c5 66 67 18 3c ac  b3 d2 cc 81 a3 dc f1 c0 |...fg.<. ........
00>                                          c0 36 02 22                                      |.6."             
00> [00:00:00.092,895] <inf> bt_hci_core: No ID address. App must call settings_load()
00> [00:00:00.100,463] <inf> ble_utils: Bluetooth initialized
00> [00:00:00.112,792] <inf> nvs_utils: Offset: 0xfa000
00> [00:00:00.117,645] <dbg> fs_nvs.nvs_recover_last_ate: Recovering last ate from sector 1
00> [00:00:00.134,033] <inf> fs_nvs: No GC Done marker found: restarting gc
00> [00:00:00.140,625] <dbg> fs_nvs.nvs_flash_erase_sector: Erasing flash at fb000, len 4096
00> [00:00:00.314,178] <dbg> fs_nvs.nvs_gc: Moving 49153, len 16
00> [00:00:00.334,899] <dbg> fs_nvs.nvs_gc: Moving 2, len 2
00> [00:00:00.341,949] <dbg> fs_nvs.nvs_gc: Moving 1, len 12
00> [00:00:00.349,243] <dbg> fs_nvs.nvs_gc: Moving 32768, len 2
00> [00:00:00.356,658] <dbg> fs_nvs.nvs_gc: Moving 32769, len 7
00> [00:00:00.364,715] <dbg> fs_nvs.nvs_add_gc_done_ate: Adding gc done ate at fc8
00> [00:00:00.372,558] <dbg> fs_nvs.nvs_flash_erase_sector: Erasing flash at fa000, len 4096
00> [00:00:00.521,759] <inf> fs_nvs: 2 Sectors of 4096 bytes
00> [00:00:00.527,038] <inf> fs_nvs: alloc wra: 1, fc0
00> [00:00:00.531,768] <inf> fs_nvs: data wra: 1, 2c
00> Id: 1, Address: 192.168.1.1
00> 
00> Id: 2, SLOT: 0xabcd.
00> 
00> *** Booting Zephyr OS build v2.7.99-ncs1-1  ***
00> 
00> [00:00:00.004,516] <inf> main: ** Example start **
00> [00:00:00.009,338] <inf> pal_interrupt: Set up button IRQ at GPIO_0 pin 13
00> [00:00:00.016,235] <inf> pal_interrupt: Set up dw3k IRQ at GPIO_1 pin 9.
00> [00:00:00.023,010] <inf> pal_spi: SPI INIT DONE: SCK 4, MISO 5, MOSI 6, CS: 7.
00> [00:00:00.030,578] <dbg> fs_nvs.nvs_recover_last_ate: Recovering last ate from sector 0
00> [00:00:00.042,114] <inf> fs_nvs: No GC Done marker found: restarting gc
00> [00:00:00.048,706] <dbg> fs_nvs.nvs_flash_erase_sector: Erasing flash at fa000, len 4096
00> [00:00:00.142,974] <dbg> fs_nvs.nvs_add_gc_done_ate: Adding gc done ate at ff0
00> [00:00:00.150,817] <dbg> fs_nvs.nvs_flash_erase_sector: Erasing flash at fb000, len 4096
00> [00:00:00.245,117] <inf> fs_nvs: 6 Sectors of 4096 bytes
00> [00:00:00.250,396] <inf> fs_nvs: alloc wra: 0, fe8
00> [00:00:00.255,126] <inf> fs_nvs: data wra: 0, 0
00> [00:00:00.259,735] <inf> sdc_hci_driver: SoftDevice Controller build revision: 
00>                                          0e e7 c5 66 67 18 3c ac  b3 d2 cc 81 a3 dc f1 c0 |...fg.<. ........
00>                                          c0 36 02 22                                      |.6."             
00> [00:00:00.292,114] <inf> bt_hci_core: No ID address. App must call settings_load()
00> [00:00:00.299,682] <inf> ble_utils: Bluetooth initialized
00> [00:00:00.312,072] <inf> nvs_utils: Offset: 0xfa000
00> [00:00:00.317,016] <dbg> fs_nvs.nvs_recover_last_ate: Recovering last ate from sector 0
00> [00:00:00.335,632] <inf> fs_nvs: 2 Sectors of 4096 bytes
00> [00:00:00.340,911] <inf> fs_nvs: alloc wra: 0, fc8
00> [00:00:00.345,642] <inf> fs_nvs: data wra: 0, 2c
00> No address found, adding 192.168.1.1 at id 1
00> 
00> No slot found, adding it at id 2.

Why does this happen? How can I fix it?

NCS version: 1.9.1

Looking forward to your reply.

Joyop

[Susheel Nuguru]

It seems something is not correct in terms of writing to the page and doing a systemreset right after (with some delay).

I  have edited your nvs_test function to read just after write and i do not see that behavior.

//NVS test
#if 1
#define ADDRESS_ID 1
#define SLOT_ID 2
#define ANTD_ID 3
void nvs_test(void)
{
    int rc = 0;
    char buf[16];
    uint16_t slot = 0;
    uint16_t antd = 0;
    // uint8_t slot[8] = {0};
    // uint8_t antd[8] = {0};

	/* ADDRESS_ID is used to store an address, lets see if we can
	 * read it from flash, since we don't know the size read the
	 * maximum possible
	 */
	rc = nvs_read(&fs, ADDRESS_ID, &buf, sizeof(buf));
	if (rc > 0) { /* item was found, show it */
		printk("Id: %d, Address: %s\n", ADDRESS_ID, buf);
	} else   {/* item was not found, add it */
		strcpy(buf, "192.168.1.1");
		printk("No address found, adding %s at id %d\n", buf,
		       ADDRESS_ID);
		(void)nvs_write(&fs, ADDRESS_ID, &buf, strlen(buf)+1);
	}	
    rc = nvs_read(&fs, SLOT_ID, &slot, sizeof(slot));
	if (rc > 0) { /* item was found, show it */
		printk("Id: %d, SLOT: 0x%x.", SLOT_ID, slot);
		printk("\n");
	} else   {/* item was not found, add it */
		printk("No slot found, adding it at id %d.\n", SLOT_ID);
		slot = 0xabcd;
		(void)nvs_write(&fs, SLOT_ID, &slot, sizeof(slot));

	    printk("Second attempt to read slot_id and address, should NOT fail \n");
		rc = nvs_read(&fs, ADDRESS_ID, &buf, sizeof(buf));
		if (rc > 0) { /* item was found, show it */
			printk("Id: %d, Address: %s\n", ADDRESS_ID, buf);
		} else   {/* item was not found, add it */
			LOG_ERR("No address found, adding %s at id %d\n", buf, ADDRESS_ID);
		}	

		rc = nvs_read(&fs, SLOT_ID, &slot, sizeof(slot));
		if (rc > 0) { /* item was found, show it */
			printk("Id: %d, SLOT: 0x%x.", SLOT_ID, slot);
			printk("\n");
		} else   {/* item was not found, add it */
			LOG_ERR("No slot found, adding it at id %d.\n", SLOT_ID);
		}
	}

	k_sleep(K_MSEC(3000));
	NVIC_SystemReset();
}

[Joyop]

Thanks for your help!

However, what I'm more interested in is why does it erase the flash sometimes like here:

00> [00:00:00.217,010] <dbg> fs_nvs.nvs_flash_erase_sector: Erasing flash at fc000, len 4096

Because I want to store some important settings in flash, without which my product cant work. So I don't want the risk of my product losing these settings after a reboot.

I don't know if I make my requirement clear . Looking forward to further discussion.

[Susheel Nuguru]

My guess is that doing a system reset right after flash write might be cause some strange behavior from garbage collection. I have run overnight your project with my suggested changes and I cannot see any erasing of your data.

[Joyop]

Okay. So a flash reading should come after each flash writing to make sure it doesn't considered garbage, is that so?

[Susheel Nuguru]

Joyop said:

So a flash reading should come after each flash writing to make sure it doesn't considered garbage

 We just make sure that the data is actually written. the gc (garbage collector) seems to be behaving strange in this case. We normally should not have to do this read just after write, but this seems to work as a workaround for now.

[Joyop]

All right, thank you!