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]

where are you writing the data. It seems like the nvs is restarting and reinitializing garbage collection and other pages mostly because it does not find any traces of those initialized in those pages. Can you upload your sample so that I can reproduce it here?

[Joyop]

Thanks for your reply!

I'll make a sample and upload it here.

[Susheel Nuguru]

Supert, Thanks

[Joyop]

nvs_test.7znvs_test_log.txt

Here are sample code and problem log.

This sample reboots every 3 seconds. Before reboot, it reads flash and if the item is found it will print the item, otherwise, it will print "No address found, adding 192.168.1.1 at id 1" or  "No slot found, adding it at id 2." and write flash.

Since this problem is probabilistic occurred, please test long enough to reproduce it(at least more than 1 hour). You can also refer to the 'nvs_test_log.txt' I uploaded.

Thank you for your help!

[Susheel Nuguru]

I am able to reproduce this. Looking into it now.