program crashes on nvs sample

[kruenheck]

using the nvs sample from here: https://github.com/nrfconnect/sdk-zephyr/tree/v3.4.99-ncs1-1/samples/subsys/nvs and configured for my board, the program crashes on the 323rd reboot (see terminal output below).

When I try to reflash at the point, the same thing happens. I can recover by configuring the app for a different board, like the 96b_notrogen/nrf52832, and flashing that. Then reconfigure for my board and flash, and it's good for another 522 reboots.

Rebooting in ...5...4...3...2...1

*** Booting nRF Connect SDK v3.0.2-89ba1294ac9b ***

*** Using Zephyr OS v4.0.99-f791c49f492c ***

[00:00:00.276,580] <dbg> fs_nvs: nvs_recover_last_ate: Recovering last ate from sector 0

[00:00:00.289,581] <inf> fs_nvs: 3 Sectors of 4096 bytes

[00:00:00.295,928] <inf> fs_nvs: alloc wra: 0, 5a8

[00:00:00.301,727] <inf> fs_nvs: data wra: 0, 5a8

Id: 1, Address: 192.168.1.1

Id: 2, Key: ff fe fd fc fb fa f9 f8

Id: 3, Reboot_counter: 322

Id: 5, Longarray: 0 1 2 3 4 5 6 7 8 9 a b c d e f 10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 20 21 22 23 24 25 26 27 28 29 2a 2b 2c 2d 2e 2f 30 31 32 33 34 35 36 37 38 39 3a 3b 3c 3d 3e 3f 40 41 42 43 44 45 46 47 48 49 4a 4b 4c 4d 4e 4f 50 51 52 53 54 55 56 57 58 59 5a 5b 5c 5d 5e 5f 60 61 62 63 64 65 66 67 68 69 6a 6b 6c 6d 6e 6f 70 71 72 73 74 75 76 77 78 79 7a 7b 7c 7d 7e 7f

Reboot counter history: ...322...321...320...319...318...317...316...315...314...313...312...311...310...309...308...307...306...305...304...303...302...301...300...299...298...297...296...295...294...293...292...291...290...289...288...287...286...285...284...283...282...281...280...279...278...277...276...275...274...273...272...271...270...269...268...267...266...265...264...263...262...261...260...259...258...257...256...255...254...253...252...251...250...249...248...247...246...245...244...243...242...241...240...239...238...237...236...235...234...233...232...231...230...229...228...227...226...225...224...223...222...221...220...219...218...217...216...215...214...213...212...211...210...209...208...207...206...205...204...203...202...201...200...199...198...197...196...195...194...193...192...191...190...189...188...187...186...185...184...183...182...181...180...179...178...177...176...175...174...173...172...171...170...169...168...167...166...165...164...163...162...161...160...159...158...157...156...155...154...153...152...151...150...149...148...147...146...145...144...143...142...141...140...139...138...137...136...135...134...133...132...131...130...129...128...127...126...125...124...123...122...121...120...119...118...117...116...115...114...113...112...111...110...109...108...107...106...105...104...103...102...101...100...99...98...97...96...95...94...93...92...91...90...89...88...87...86...85...84...83...82...81...80...79...78...77...76...75...74...73...72...71...70...69...68...67...66...65...64...63...62...61...60...59...58...57...56...55...54...53...52...51...50...49...48...47...46...45...44...43...42...41...40...39...38...37...36...35...34...33...32...31...30...29...28...27...26...25...24...23...22...21...20...19...18...17...16...15...14...13...12...11...10...9...8...7...6...5...4...3...2...1...0

Oldest reboot counter: 0

Rebooting in ...5...4...3...2...1

[00:00:01.472,717] <err> os: ***** MPU FAULT *****

[00:00:01.478,363] <err> os:   Stacking error (context area might be not valid)

[00:00:01.486,602] <err> os:   Data Access Violation

[00:00:01.492,401] <err> os:   MMFAR Address: 0x200013b8

[00:00:01.498,596] <err> os: r0/a1:  0x00000000  r1/a2:  0x00000000  r2/a3:  0x00000000

[00:00:01.507,568] <err> os: r3/a4:  0x00000000 r12/ip:  0x00000000 r14/lr:  0x00000000

[00:00:01.516,510] <err> os:  xpsr:  0x01000000

[00:00:01.521,881] <err> os: Faulting instruction address (r15/pc): 0x000068e0

[00:00:01.530,059] <err> os: >>> ZEPHYR FATAL ERROR 2: Stack overflow on CPU 0

[00:00:01.538,177] <err> os: Current thread: 0x200006e8 (unknown)

[00:00:01.545,166] <err> os: Halting system

Thoughts?

[Vidar Berg]

Hello,

It seems that the main stack is too small for the NVS garbage collection process, which runs after the sectors are full (I assume this is what happens after the 322nd reboot). Please try doubling the stack size in your project to see if it fixes it (CONFIG_MAIN_STACK_SIZE=2048). 

You may also enable the thread analyzer  to monitor the stack usage though this would have been more useful if the app did not contentiously reboot.

Best regards,

Vidar

[kruenheck]

That worked, thank you.

[kruenheck]

Vidar,

One more question. Your suggested change solved the problem for this test (400 reboots). But will this problem resurface in production, with potentially many more reboots?

[Vidar Berg]

The peak stack usage should be when NVS performs garbage collection after every 322 reboots. After that, it should return to normal until the next garbage collection 322 reboots later. Therefore, whether the test runs for 400 or 4000 reboots shouldn’t make any difference in terms of max. stack usage.  But for the final application it will be important to profile the stack usage for each thread (+main stack) and not just for NVS in main(). You can use the thread analyzer as mentioned earlier to help with this.The stacks are also initialized to 0xAA with the config below enabled.

 

[kruenheck]

Vidar,

My question is related to your ticket "NVS not compatible with MCUBOOT". There you recommend using the CUSTOMER register in UICR. I'm able to write and read to a register with nrfjprog, but I don't know how to read from it programmatically (in C). Is there an example of that, where it's clear how to specify the register address?

thank you,

[Vidar Berg]

If you include the <soc.h> you will be able to access the register definitions directly.

#include <soc.h>

void foo(void)
{
    uint32_t var = NRF_UICR->CUSTOMER[0];
}

[kruenheck]

That works, thank you.

[kruenheck]

Vidar,

I'd like to allow the customer to rewrite their (serial) number if they make a mistake. But that requires 'nrfjprog –eraseuicr' before another 'nrfjprog --memwr' is allowed. However, 'nrfjprog –eraseuicr' appears to erase program memory, because I need to re-flash after that operation. Is there another way to allow re-writes to that register?

Thank you

[Vidar Berg]

UICR is good for keeping one time configurations such as serial numbers and mac addresses, but for anything that needs to be updated during the lifetime of the product it is usually best to store it in internal flash using NVS or similar. This is assuming the values are to be updated programmatically. Will the end user have access to re-program the chip through the debug interface using nrfjprog or similar?