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
  • Hi!

    I call it on the main thread not in an ISR

    Seems strange that the IRQ setup for ADC should effect this then.
    Could you do something like this, and print the back-trace ?

    cd build/app_name/ 

    west attach
    info threads
    thread apply all bt 

  • 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 ?

Reply Children
  • 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