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

[Jonas Hoefer]

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

[Sigurd]

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 ?

[Jonas Hoefer]

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));
}