NRF_NVMC->CONFIG hangs on setting NRF_NVMC_MODE_WRITE in Zephyr (without Softdevice)

I am using the Zephyr NVS Settings module. In some cases this happens: I try to save a value with `settings_save_one()`, which internally calls `nvs_write()`.
I debugged it down to `nrf_nvmc_mode_set()`, which is trying to set the `NRF_NVMC->CONFIG` register to `NRF_NVMC_MODE_WRITE`.
But it keeps hanging there.

NCS 2.1.4
Zephyr 3.1.99
Custom Board with nRF52832

Enabled features:
- PWM
- ADC (SAADC)
- ESB Shockburst
- NVS Settings
- UART
- CONFIG_PM=y
- CONFIG_MPU_ALLOW_FLASH_WRITE=y
- CONFIG_DEBUG=y


Things that I have tried/checked:
  • There is no softdevice in the flash
  • I am not using BLE (but ESB Shockburst, maybe this is a problem?)
  • Settings partition is at 0x7c000 (0x4000 size), `CONFIG_SETTINGS_NVS_SECTOR_COUNT=2`
  • I call it on the main thread not in an ISR
  • Zephyr workers and other threads are still running
  • Application is not overlapping (size is around 0x489F0)

I have added some debug prints to the SDK to trace down the spot where it fails. See the logs at the bottom.
This is the code snippet where it fails:
The "Finished" is never printed

---------------
nrf_nvmc_mode_set(NRF_NVMC, NRF_NVMC_MODE_WRITE);

// ...

NRF_STATIC_INLINE void nrf_nvmc_mode_set(NRF_NVMC_Type *p_reg,
                                         nrf_nvmc_mode_t mode)
{
    printk("BPROT CONFIG0: 0x%08x\n", NRF_BPROT->CONFIG0);
    printk("BPROT CONFIG1: 0x%08x\n", NRF_BPROT->CONFIG1);
    printk("NRF_NVMC->READY: 0x%08x\n", NRF_NVMC->READY);

    printk("FICR FLASH: %lu kB\n", NRF_FICR->INFO.FLASH);
    printk("FICR RAM: %lu kB\n", NRF_FICR->INFO.RAM);

    unsigned int key = irq_lock();
    printk("nrf_nvmc_mode_set: Set mode %d\n", mode);

    p_reg->CONFIG = (uint32_t)mode;
    irq_unlock(key);
    printk("nrf_nvmc_mode_set: Finished\n");
}




nvs_write: Enter while #1
nvs_write: Exit while #1
nvs_write: Enter while #2
nvs_write: Enter nvs_flash_wrt_entry
nvs_flash_wrt_entry: Writing entry id 49153 at offset 8 len 4
nvs_flash_wrt_entry: Writing data at 8
nvs_flash_al_wrt: Writing 4 bytes at 7c008
soc_flash_nrf: write addr 0x0007c008 len 4
write_op: context 0x20005190
write_op: Enter write 4-byte aligned data
write_op: Write 4 bytes at flash addr 0x0007c008 from data addr 0x20001efc
nvmc_word_write: addr 0x0007c008, value 0x0000001e
nvmc_write_mode_set: Set write mode
BPROT CONFIG0: 0x00000000
BPROT CONFIG1: 0x00000000
NRF_NVMC->READY: 0x00000001
FICR FLASH: 512 kB
FICR RAM: 64 kB
nrf_nvmc_mode_set: Set mode 1



Parents Reply Children
  • This is captured at the point where settings_save_one is called:

    -exec info threads
      Id   Target Id                                                Frame 
      3    Thread 536877128 (idle UNKNOWN PRIO 15)                  arch_cpu_idle () at ./zephyr-firmware/zephyr/arch/arm/core/aarch32\cpu_idle.S:129
      4    Thread 536876920 (logging PENDING PRIO 14)               arch_swap (key=key@entry=0) at ./zephyr-firmware/zephyr/arch/arm/core/aarch32/swap.c:53
    * 5    Thread 536877488 (sysworkq RUNNING PRIO 255)             Settings::_save_all_internal (work=<optimized out>) at ../src/settings/settings.cpp:127
      6    Thread 536874472 (shockburst_tx_thread SUSPENDED PRIO 5) arch_swap (key=key@entry=0) at ./zephyr-firmware/zephyr/arch/arm/core/aarch32/swap.c:53
    
    -------------
    -exec thread apply all bt 
    
    Thread 6 (Thread 536874472):
    #0  arch_swap (key=key@entry=0) at ./zephyr-firmware/zephyr/arch/arm/core/aarch32/swap.c:53
    #1  0x00039408 in z_swap_irqlock (key=0) at ./zephyr-firmware/zephyr/kernel/include/kswap.h:185
    #2  z_swap (key=..., lock=0x200031b4 <sched_spinlock>) at ./zephyr-firmware/zephyr/kernel/include/kswap.h:196
    #3  z_tick_sleep (ticks=<optimized out>) at ./zephyr-firmware/zephyr/kernel/sched.c:1432
    #4  0x00039472 in z_impl_k_sleep (timeout=...) at ./zephyr-firmware/zephyr/kernel/sched.c:1464
    #5  0x000133f8 in k_sleep (timeout=...) at zephyr/include/generated/syscalls/kernel.h:100
    #6  ShockburstIoController::tx_thread () at ../src/hardware/io/shockburst_io_controller.cpp:306
    #7  0x00027f48 in z_thread_entry (entry=0x1332d <ShockburstIoController::tx_thread(void*, void*, void*)>, p1=<optimized out>, p2=<optimized out>, p3=<optimized out>) at ./zephyr-firmware/zephyr/lib/os/thread_entry.c:36
    #8  0xaaaaaaaa in ?? ()
    Backtrace stopped: previous frame identical to this frame (corrupt stack?)
    
    Thread 5 (Thread 536877488):
    #0  Settings::_save_all_internal (work=<optimized out>) at ../src/settings/settings.cpp:127
    #1  0x000382ea in work_queue_main (workq_ptr=0x200019b0 <k_sys_work_q>, p2=<optimized out>, p3=<optimized out>) at ./zephyr-firmware/zephyr/kernel/work.c:668
    #2  0x00027f48 in z_thread_entry (entry=0x38259 <work_queue_main>, p1=<optimized out>, p2=<optimized out>, p3=<optimized out>) at ./zephyr-firmware/zephyr/lib/os/thread_entry.c:36
    #3  0xaaaaaaaa in ?? ()
    Backtrace stopped: previous frame identical to this frame (corrupt stack?)
    
    Thread 4 (Thread 536876920):
    #0  arch_swap (key=key@entry=0) at ./zephyr-firmware/zephyr/arch/arm/core/aarch32/swap.c:53
    #1  0x00038ea4 in z_swap_irqlock (key=0) at ./zephyr-firmware/zephyr/kernel/include/kswap.h:185
    #2  z_swap (key=..., lock=0x200031a0 <lock>) at ./zephyr-firmware/zephyr/kernel/include/kswap.h:196
    #3  z_pend_curr (lock=lock@entry=0x200031a0 <lock>, key=..., wait_q=wait_q@entry=0x20000d10 <log_process_thread_sem>, timeout=...) at ./zephyr-firmware/zephyr/kernel/sched.c:842
    #4  0x00037fe0 in z_impl_k_sem_take (sem=sem@entry=0x20000d10 <log_process_thread_sem>, timeout=...) at ./zephyr-firmware/zephyr/kernel/sem.c:143
    #5  0x0002a274 in k_sem_take (timeout=..., sem=0x20000d10 <log_process_thread_sem>) at zephyr/include/generated/syscalls/kernel.h:1054
    #6  log_process_thread_func (dummy1=<optimized out>, dummy2=<optimized out>, dummy3=<optimized out>) at ./zephyr-firmware/zephyr/subsys/logging/log_core.c:681
    #7  0x00027f48 in z_thread_entry (entry=0x2a21d <log_process_thread_func>, p1=<optimized out>, p2=<optimized out>, p3=<optimized out>) at ./zephyr-firmware/zephyr/lib/os/thread_entry.c:36
    #8  0xaaaaaaaa in ?? ()
    Backtrace stopped: previous frame identical to this frame (corrupt stack?)
    
    Thread 3 (Thread 536877128):
    #0  arch_cpu_idle () at ./zephyr-firmware/zephyr/arch/arm/core/aarch32\cpu_idle.S:129
    #1  0x000379a4 in k_cpu_idle () at ./zephyr-firmware/zephyr/include/zephyr/kernel.h:5616
    #2  idle (unused1=<optimized out>, unused2=<optimized out>, unused3=<optimized out>) at ./zephyr-firmware/zephyr/kernel/idle.c:83
    #3  0x00027f48 in z_thread_entry (entry=0x37991 <idle>, p1=<optimized out>, p2=<optimized out>, p3=<optimized out>) at ./zephyr-firmware/zephyr/lib/os/thread_entry.c:36
    #4  0xaaaaaaaa in ?? ()
    Backtrace stopped: previous frame identical to this frame (corrupt stack?)
    
    

  • So it seems you are stuck here:

    #0  Settings::_save_all_internal (work=<optimized out>) at ../src/settings/settings.cpp:127
    How does the function at settings.cpp:127 look like ?

  • It's basically a loop which calls settings_save_one for multiple items but it keeps hanging on the first one.

  • Jonas Hoefer said:
    It's basically a loop which calls settings_save_one for multiple items but it keeps hanging on the first one.

    Could you post some code that shows how that function looks like ?

  • This is the relevant code:

    /// Settings
    vector<IntSettingsItem> Settings::int_items;
    vector<FloatSettingsItem> Settings::float_items;
    vector<StringSettingsItem> Settings::string_items;
    vector<BoolSettingsItem> Settings::bool_items;
    
    int Settings::init() {
      int err = 0;
    
      // ..
    
      err = settings_subsys_init();
      if (err) {
        return err;
      }
    
      err = settings_register(&handler_config);
      if (err) {
        if (err == -EEXIST) {
          LOG_WRN("settings_register failed (err: %d) - already registered", err);
        } else {
          LOG_ERR("settings_register failed (err: %d)", err);
          return err;
        }
      }
    
      err = settings_load();
      if (err) {
        LOG_ERR("settings_load failed (err: %d)", err);
        return err;
      }
    
      // ...
    
      return 0;
    }
    
    void Settings::_save_all_internal(struct k_work* work) {
      int err = 0;
    
      for (size_t i = 0; i < int_items.size(); i++) {
        if (int_items[i].saved_value != *int_items[i].pointer) {
          LOG_DBG("Saving %s", int_items[i].name.c_str());
          err =
              settings_save_one(get_full_setting_name(&int_items[i]),
                                int_items[i].pointer, sizeof(int_items[i].pointer));
          if (err) {
            LOG_ERR("settings_save_one failed (err: %d)", err);
          }
          int_items[i].saved_value = *int_items[i].pointer;
        }
      }
    
      for (size_t i = 0; i < float_items.size(); i++) {
        if (!almost_equal(float_items[i].saved_value, *float_items[i].pointer)) {
          LOG_DBG("Saving %s", float_items[i].name.c_str());
          err = settings_save_one(get_full_setting_name(&float_items[i]),
                                  float_items[i].pointer,
                                  sizeof(float_items[i].pointer));
          if (err) {
            LOG_ERR("settings_save_one failed (err: %d)", err);
          }
          float_items[i].saved_value = *float_items[i].pointer;
        }
      }
    
      for (size_t i = 0; i < string_items.size(); i++) {
        if (string_items[i].saved_value != *string_items[i].pointer) {
          LOG_DBG("Saving %s", string_items[i].name.c_str());
          err = settings_save_one(get_full_setting_name(&string_items[i]),
                                  string_items[i].pointer,
                                  sizeof(string_items[i].pointer));
          if (err) {
            LOG_ERR("settings_save_one failed (err: %d)", err);
          }
          string_items[i].saved_value = *string_items[i].pointer;
        }
      }
    
      for (size_t i = 0; i < bool_items.size(); i++) {
        if (bool_items[i].saved_value != *bool_items[i].pointer) {
          LOG_DBG("Saving %s", bool_items[i].name.c_str());
          err = settings_save_one(get_full_setting_name(&bool_items[i]),
                                  bool_items[i].pointer,
                                  sizeof(bool_items[i].pointer));
          if (err) {
            LOG_ERR("settings_save_one failed (err: %d)", err);
          }
          bool_items[i].saved_value = *bool_items[i].pointer;
        }
      }
    
      if (err) {
        LOG_ERR("_save_all_internal failed (err: %d)", err);
      }
    }
    
    K_WORK_DELAYABLE_DEFINE(delayed_saving_work, Settings::_save_all_internal);
    
    void Settings::save_all(void) {
      k_work_reschedule(&delayed_saving_work, K_SECONDS(2));
    }

Related