Main loop iterating too quickly. nrf_pwr_mgmt_run() returns in 1ms.

[Eliot Stock]

Hi. The main loop of my app is mostly doing SPI communication to a GPS receiver. I'd like it to do that every second or so and spend the rest of the time in system on but waiting for an event. I want nrf_pwr_mgmt_run() to block for about a second on each iteration of the main loop, so I create a repeated timer with 1 Hz frequency and a no-op handler. Instead I'm finding it returns very quickly every time - about every 1 ms.

Here's a fairly minimal test for my GPS receiver driver that reproduces the issue.

void test_gps_comms(void)
{
	// SDK 15.3.0, GPS test, working but inner loop iterating too quickly.
	NRF_LOG_INFO("test_gps_comms()");

	uint32_t err_code = 0;

	err_code = nrf_pwr_mgmt_init();
	APP_ERROR_CHECK(err_code);
	pwr_init();

	gps_init(test_on_gps_event);
	pwr_modem_gps_on();
	gps_power_on();

	log_int_priorities();

	// Create our 1 Hz timer and start it. This uses a no-op handler, since it's real purpose is to get nrf_pwr_mgmt_run() to return so that the loop iterates.
	APP_TIMER_DEF(timer_id);
	err_code = app_timer_create(&timer_id, APP_TIMER_MODE_REPEATED, empty_timeout_handler);
	APP_ERROR_CHECK(err_code);
	err_code = app_timer_start(timer_id, APP_TIMER_TICKS(1000), NULL); // 1s, no context
	APP_ERROR_CHECK(err_code);

	// Create our comms timeout timer and start it. Let's give it 5s because the first 2.7s are spent on booting up.
	APP_TIMER_DEF(gps_comms_timout_timer_id);
	err_code = app_timer_create(&gps_comms_timout_timer_id, APP_TIMER_MODE_SINGLE_SHOT, test_gps_comms_timeout_handler);
	APP_ERROR_CHECK(err_code);
	err_code = app_timer_start(gps_comms_timout_timer_id, APP_TIMER_TICKS(5000), NULL); // 5s, no context
	APP_ERROR_CHECK(err_code);

	m_gps_comms_timed_out = false;

	while (!m_gps_comms_timed_out)
	{
		gps_run();

		// TODO (P1): We'd like events to happen only every second here. Instead, they're happening every millisecond. The GPS driver has created a bunch of other timers, but none of them fire that quickly. Is it the SPI driver that's generating the events? Why?
		nrf_pwr_mgmt_run();
	}

	gps_power_off();
	pwr_modem_gps_off();
	pwr_uninit();

	if (gps_got_sentences())
	{
		NRF_LOG_INFO("PASS test_gps_comms() Got NMEA sentences within time");
	}
	else
	{
		// Timer timed out without us seeing any NMEA sentences. Fail.
		NRF_LOG_ERROR("FAIL test_gps_comms() No NMEA sentences in time");
	}
}

The implementation of gps_run() is a bit long but here's a cut down version of it.

void gps_run()
{
	switch (m_gps.state)
	{
	case GPS_STATE_NOT_INITED:
		break;
	case GPS_STATE_INITED:
		break;
	case GPS_STATE_POWERED_ON:
		{
		// How long has it been since we got power? If it's less than GPS_BOOT_TIME_MS, wait till the next main loop iteration before we try to send commands.
		uint32_t counter_now = app_timer_cnt_get();
		uint32_t counter_diff = app_timer_cnt_diff_compute(counter_now, m_gps.counter_at_power_on);
		uint32_t delay_ms = app_timer_ms(counter_diff);

		if (delay_ms < GPS_BOOT_TIME_MS)
		{
			// TODO (P1): The main loop is running too often at the moment and this is too noisy. Put it back once we figure out how to slow down the main loop.
			// NRF_LOG_DEBUG("Time since power on: %dms", delay_ms);
			return;
		}

		// Omitted: here we send about seven commands to the receiver over SPI.

		// We should now be getting just the NMEA sentences we asked for, at the rate we asked for them.
		m_gps.state++;

		// Start our no fix timer, because we can't possibly have a fix yet.
		ret_code_t err_code = app_timer_start(m_gps_no_fix_timer_id, GPS_NO_FIX_TIMEOUT, NULL);
		APP_ERROR_CHECK(err_code);

		// TELEMETRY LOGGING: Name: SV, value: 00.
		// Don't change this without also changing the code in the Android app.
		NRF_LOG_RAW_INFO("TSV00\n");

		NRF_LOG_DEBUG("Started");

#ifdef BUILD_TEST_DESK
		led_orange();
#endif

		}
		break;
	case GPS_STATE_NO_FIX:
		// Our job in this state is to provide verbose logging about satellites in view to aid in fixing any TTFF issues.
		m_gps.last_gpgsv_in_set_seen = false;
		uint8_t rx_counts = 0;

		while (!m_gps.last_gpgsv_in_set_seen)
		{
			gps_rx();
			rx_counts++;

			// Let's not get stuck here forever if the last GPGSV sentence in the set is never seen.
			if (rx_counts > GPS_MAX_RX_CALLS_PER_TICK)
			{
				// TODO (P1): The main loop is running too often at the moment and this is too noisy. Put it back once we figure out how to slow down the main loop.
				// NRF_LOG_WARNING("Too many RX calls");
				break;
			}
		}

		// Omitted: Send a zero position in an event for the client (state machine or test code).

		if (!is_zero(m_gps.gpgga))
		{
			// We have a fix. Move on.
			m_gps.state++;

#ifdef BUILD_TEST_DESK
			led_green();
#endif

			// If this is the first fix since we powered on, measure how long it took. Don't do this if we've already had a fix then lost it and now we have it back again.
			if (!m_gps.got_first_fix)
			{
				m_gps.got_first_fix = true;
				uint32_t counter_at_first_fix = app_timer_cnt_get();
				uint32_t counter_diff = app_timer_cnt_diff_compute(counter_at_first_fix, m_gps.counter_at_power_on);

				m_gps.ttff_seconds = app_timer_ms(counter_diff) / 1000;
				NRF_LOG_INFO("TTFF: %d s.\n", (int)m_gps.ttff_seconds);
			}

			// We can now do without the GPGSV sentences. We still need the other types.
			gps_tx_command(GPS_COMMAND_GSV_OFF);

			// Stop our no fix timer so that we don't go into sys off when it times out.
			ret_code_t err_code = app_timer_stop(m_gps_no_fix_timer_id);
			APP_ERROR_CHECK(err_code);

			NRF_LOG_INFO("Got fix");
		}

		break;

	case GPS_STATE_FIX:
		// Receive up to 255 bytes of sentences from the receiver.
		gps_rx();

		if (is_zero(m_gps.gpgga))
		{
			// We lost our fix. Move back.
			m_gps.state--;

#ifdef BUILD_TEST_DESK
			led_orange();
#endif

			// Omitted: Change sentences

			// Restart our no fix timer, which will time out in an hour unless stopped before then.
			ret_code_t err_code = app_timer_start(m_gps_no_fix_timer_id, GPS_NO_FIX_TIMEOUT, NULL);
			APP_ERROR_CHECK(err_code);

			NRF_LOG_INFO("Lost fix");
		}

		break;
	}

	// Omitted: log the time from the GPS.
}

Although there are SPI comms happening here, I can run this on the PCA10040 DK board (that has no GPS receiver, obvs) and it will still run OK, it just doesn't get anything back on the SPI. The same timing issue happens on my own custom board.

How can I get a better idea of what event it was that caused nrf_pwr_mgmt_run() to return?

[Edit]

I added some code right before the loop to figure out which peripherals are enabled. Here's what it showed.

[00:00:00.020,507] D util Peripherals enabled:
[00:00:00.021,484] D util   POWER: 0
[00:00:00.021,484] D util   CLOCK: 0
[00:00:00.021,484] D util   RADIO: 0
[00:00:00.021,484] D util   UARTE0: 0
[00:00:00.021,484] D util   UART0: 0
[00:00:00.022,460] D util   SPIM0: 0
[00:00:00.022,460] D util   SPIS0: 0
[00:00:00.022,460] D util   TWIM0: 0
[00:00:00.022,460] D util   TWIS0: 0
[00:00:00.022,460] D util   SPI0: 0
[00:00:00.023,437] D util   TWI0: 0
[00:00:00.023,437] D util   SPIM0: 0
[00:00:00.023,437] D util   SPIS0: 0
[00:00:00.023,437] D util   TWIM1: 0
[00:00:00.023,437] D util   TWIS1: 0
[00:00:00.023,437] D util   SPI1: 0
[00:00:00.024,414] D util   TWI1: 0
[00:00:00.024,414] D util   NFCT: 0
[00:00:00.024,414] D util   GPIOTE: -2147483648
[00:00:00.025,390] D util   SAADC: 2
[00:00:00.025,390] D util   TIMER0: 0
[00:00:00.026,367] D util   TIMER1: 0
[00:00:00.026,367] D util   TIMER2: 0
[00:00:00.026,367] D util   RTC0: 0
[00:00:00.026,367] D util   TEMP: 0
[00:00:00.026,367] D util   RNG: 0
[00:00:00.027,343] D util   ECB: 0
[00:00:00.027,343] D util   CCM: 0
[00:00:00.027,343] D util   AAR: 0
[00:00:00.027,343] D util   WDT: 0
[00:00:00.027,343] D util   RTC1: 65536
[00:00:00.027,343] D util   QDEC: 0
[00:00:00.029,296] D util   COMP: 0
[00:00:00.029,296] D util   LPCOMP: 0
[00:00:00.029,296] D util   EGU0: 0
[00:00:00.029,296] D util   EGU1: 0
[00:00:00.029,296] D util   EGU2: 0
[00:00:00.030,273] D util   EGU3: 0
[00:00:00.030,273] D util   EGU4: 0
[00:00:00.030,273] D util   EGU5: 0
[00:00:00.030,273] D util   TIMER3: 0
[00:00:00.030,273] D util   TIMER4: 0
[00:00:00.031,250] D util   PWM0: 0
[00:00:00.031,250] D util   PDM: 0
[00:00:00.031,250] D util   MWU: 0
[00:00:00.031,250] D util   PWM1: 0
[00:00:00.032,226] D util   PWM2: 0
[00:00:00.033,203] D util   SPIM2: 64
[00:00:00.033,203] D util   SPIS2: 64
[00:00:00.033,203] D util   SPI2: 64
[00:00:00.033,203] D util   RTC2: 0
[00:00:00.033,203] D util   I2C: 0

Are there any non-zero values here that are unexpected for this test code above?

Here's the code for the logging, just using the INTENSET field on each peripheral (not all of them have an INTEN field):

void log_peripherals_enabled(void)
{
	NRF_LOG_DEBUG("Peripherals enabled:");

	// List from /usr/local/nRF5_SDK_15.3.0_59ac345/modules/nrfx/mdk/nrf52.h, search: "Peripheral declaration".
	// From the Product Specification, section 15.8:
	//   "Some peripherals implement only INTENSET and INTENCLR, and the INTEN register is not available on those peripherals. Refer to the individual chapters for details. In all cases, however, reading back the INTENSET or INTENCLR register returns the same information as in INTEN."
	// The following peripherals are omitted eblow because they don't have an INTENSET field on the struct in the SDK.
	//   NRF_BPROT
	//   NRF_SWI0
	//   NRF_SWI1
	//   NRF_SWI2
	//   NRF_SWI3
	//   NRF_SWI4
	//   NRF_SWI5
	//   NRF_NVMC
	//   NRF_PPI
	//   NRF_FPU
	//   NRF_P0
	NRF_LOG_DEBUG("  POWER: %d", NRF_POWER->INTENSET);
	NRF_LOG_DEBUG("  CLOCK: %d", NRF_CLOCK->INTENSET);
	NRF_LOG_DEBUG("  RADIO: %d", NRF_RADIO->INTENSET);
	NRF_LOG_DEBUG("  UARTE0: %d", NRF_UARTE0->INTENSET);
	NRF_LOG_DEBUG("  UART0: %d", NRF_UART0->INTENSET);
	NRF_LOG_DEBUG("  SPIM0: %d", NRF_SPIM0->INTENSET);
	NRF_LOG_DEBUG("  SPIS0: %d", NRF_SPIS0->INTENSET);
	NRF_LOG_DEBUG("  TWIM0: %d", NRF_TWIM0->INTENSET);
	NRF_LOG_DEBUG("  TWIS0: %d", NRF_TWIS0->INTENSET);
	NRF_LOG_DEBUG("  SPI0: %d", NRF_SPI0->INTENSET);
	NRF_LOG_DEBUG("  TWI0: %d", NRF_TWI0->INTENSET);
	NRF_LOG_DEBUG("  SPIM0: %d", NRF_SPIM1->INTENSET);
	NRF_LOG_DEBUG("  SPIS0: %d", NRF_SPIS1->INTENSET);
	NRF_LOG_DEBUG("  TWIM1: %d", NRF_TWIM1->INTENSET);
	NRF_LOG_DEBUG("  TWIS1: %d", NRF_TWIS1->INTENSET);
	NRF_LOG_DEBUG("  SPI1: %d", NRF_SPI1->INTENSET);
	NRF_LOG_DEBUG("  TWI1: %d", NRF_TWI1->INTENSET);
	NRF_LOG_DEBUG("  NFCT: %d", NRF_NFCT->INTENSET);
	NRF_LOG_DEBUG("  GPIOTE: %d", NRF_GPIOTE->INTENSET);
	NRF_LOG_DEBUG("  SAADC: %d", NRF_SAADC->INTENSET);
	NRF_LOG_DEBUG("  TIMER0: %d", NRF_TIMER0->INTENSET);
	NRF_LOG_DEBUG("  TIMER1: %d", NRF_TIMER1->INTENSET);
	NRF_LOG_DEBUG("  TIMER2: %d", NRF_TIMER2->INTENSET);
	NRF_LOG_DEBUG("  RTC0: %d", NRF_RTC0->INTENSET);
	NRF_LOG_DEBUG("  TEMP: %d", NRF_TEMP->INTENSET);
	NRF_LOG_DEBUG("  RNG: %d", NRF_RNG->INTENSET);
	NRF_LOG_DEBUG("  ECB: %d", NRF_ECB->INTENSET);
	NRF_LOG_DEBUG("  CCM: %d", NRF_CCM->INTENSET);
	NRF_LOG_DEBUG("  AAR: %d", NRF_AAR->INTENSET);
	NRF_LOG_DEBUG("  WDT: %d", NRF_WDT->INTENSET);
	NRF_LOG_DEBUG("  RTC1: %d", NRF_RTC1->INTENSET);
	NRF_LOG_DEBUG("  QDEC: %d", NRF_QDEC->INTENSET);
	NRF_LOG_DEBUG("  COMP: %d", NRF_COMP->INTENSET);
	NRF_LOG_DEBUG("  LPCOMP: %d", NRF_LPCOMP->INTENSET);
	NRF_LOG_DEBUG("  EGU0: %d", NRF_EGU0->INTENSET);
	NRF_LOG_DEBUG("  EGU1: %d", NRF_EGU1->INTENSET);
	NRF_LOG_DEBUG("  EGU2: %d", NRF_EGU2->INTENSET);
	NRF_LOG_DEBUG("  EGU3: %d", NRF_EGU3->INTENSET);
	NRF_LOG_DEBUG("  EGU4: %d", NRF_EGU4->INTENSET);
	NRF_LOG_DEBUG("  EGU5: %d", NRF_EGU5->INTENSET);
	NRF_LOG_DEBUG("  TIMER3: %d", NRF_TIMER3->INTENSET);
	NRF_LOG_DEBUG("  TIMER4: %d", NRF_TIMER4->INTENSET);
	NRF_LOG_DEBUG("  PWM0: %d", NRF_PWM0->INTENSET);
	NRF_LOG_DEBUG("  PDM: %d", NRF_PDM->INTENSET);
	NRF_LOG_DEBUG("  MWU: %d", NRF_MWU->INTENSET);
	NRF_LOG_DEBUG("  PWM1: %d", NRF_PWM1->INTENSET);
	NRF_LOG_DEBUG("  PWM2: %d", NRF_PWM2->INTENSET);
	NRF_LOG_DEBUG("  SPIM2: %d", NRF_SPIM2->INTENSET);
	NRF_LOG_DEBUG("  SPIS2: %d", NRF_SPIS2->INTENSET);
	NRF_LOG_DEBUG("  SPI2: %d", NRF_SPI2->INTENSET);
	NRF_LOG_DEBUG("  RTC2: %d", NRF_RTC2->INTENSET);
	NRF_LOG_DEBUG("  I2C: %d", NRF_I2S->INTENSET);
}

[Edit 2]

I turned the SAADC off. It helps, but isn't sufficient. I now have my main loop iterating once every 5ms or so, up from once every 1ms. I don't understand how or why.

[Edit 3]

It's the SPI that's causing the events. Here's some updated logging:

[00:00:00.020,507] D util Peripherals enabled:
[00:00:00.020,507] D util   POWER int:     0
[00:00:00.020,507] D util   CLOCK int:     0
[00:00:00.021,484] D util   RADIO int:     0
[00:00:00.021,484] D util   UARTE0 enable: 0
[00:00:00.021,484] D util   UART0 enable:  0
[00:00:00.021,484] D util   SPIM0 enable:  0
[00:00:00.021,484] D util   SPIS0 enable:  0
[00:00:00.022,460] D util   TWIM0 enable:  0
[00:00:00.022,460] D util   TWIS0 enable:  0
[00:00:00.022,460] D util   SPI0 enable:   0
[00:00:00.022,460] D util   TWI0 enable:   0
[00:00:00.022,460] D util   SPIM0 enable:  0
[00:00:00.023,437] D util   SPIS0 enable:  0
[00:00:00.024,414] D util   TWIM1 enable:  0
[00:00:00.024,414] D util   TWIS1 enable:  0
[00:00:00.024,414] D util   SPI1 enable:   0
[00:00:00.024,414] D util   TWI1 enable:   0
[00:00:00.025,390] D util   NFCT int:      0
[00:00:00.025,390] D util   GPIOTE int:    -2147483648
[00:00:00.025,390] D util   SAADC enable:  0
[00:00:00.025,390] D util   TIMER0 int:    0
[00:00:00.025,390] D util   TIMER1 int:    0
[00:00:00.026,367] D util   TIMER2 int:    0
[00:00:00.026,367] D util   RTC0 int:      0
[00:00:00.027,343] D util   TEMP int:      0
[00:00:00.027,343] D util   RNG int:       0
[00:00:00.027,343] D util   ECB int:       0
[00:00:00.028,320] D util   CCM enable:    0
[00:00:00.028,320] D util   AAR enable:    0
[00:00:00.028,320] D util   WDT int:       0
[00:00:00.028,320] D util   RTC1 int:      65536
[00:00:00.028,320] D util   QDEC enable:   0
[00:00:00.029,296] D util   COMP enable:   0
[00:00:00.029,296] D util   LPCOMP enable: 0
[00:00:00.029,296] D util   EGU0 int:      0
[00:00:00.030,273] D util   EGU1 int:      0
[00:00:00.030,273] D util   EGU2 int:      0
[00:00:00.031,250] D util   EGU3 int:      0
[00:00:00.031,250] D util   EGU4 int:      0
[00:00:00.031,250] D util   EGU5 int:      0
[00:00:00.031,250] D util   TIMER3 int:    0
[00:00:00.031,250] D util   TIMER4 int:    0
[00:00:00.033,203] D util   PWM0 enable:   0
[00:00:00.033,203] D util   PDM enable:    0
[00:00:00.033,203] D util   MWU int:       0
[00:00:00.033,203] D util   PWM1 enable:   0
[00:00:00.033,203] D util   PWM2 enable:   0
[00:00:00.034,179] D util   SPIM2 enable:  0
[00:00:00.034,179] D util   SPIS2 enable:  0
[00:00:00.034,179] D util   SPI2 enable:   0
[00:00:00.034,179] D util   RTC2 int:      0
[00:00:00.034,179] D util   I2C enable:    0

This shows the value of the ENABLE field for each peripheral that has one, or the INTENSET for those that don't. I tried not enabling my GPIOTE peripheral but it made no difference. So I tried not enabling the SPI master. The main loop slowed down to one iteration per second.

What is the SPI doing every ms? This is testing on the DK, where there's nothing on the other end of the SPI pins but thin air. It behaves the same way on my custom board, which does have a GPS receiver there.

[Jørgen Holmefjord]

Hi,

You could possibly use a trace tool like Segger J-Trace to track the function calls. If you do not have this available, I would recommend that you check the peripheral register to see if any unused peripherals have been enabled and are generating events.

If I remember correctly, you have updated to app_timer_v2, and this did not solve the issue? Are you able to reproduce this in a minimal example, or do you only see the issue in your test code for the full project?

Best regards,
Jørgen

[Eliot Stock]

A J-Trace would be really nice, but they're pretty pricey. I'll consider it if I exhaust all other options.

Can you give more detail on the peripheral register approach?

Yes, I tried moving to app_timer_v2 and it didn't help. The test code I have above is pretty minimal but I'll look at minimising it further to the point where I can add the whole project here. It already repro's on a DK.

[Eliot Stock]

Added an edit above for the peripheral register approach. Let me know if this sheds any light on it. If not, I'll put the time into minimising the project as much as possible.

[Jørgen Holmefjord]

I would also recommend that you check the ENABLE register in all peripherals where this is available. nrf_pwr_mgmt_run() calls __WFE internally, which means that any event can wake the CPU, regardless if interrupts are enabled or not.

[Eliot Stock]

I see what you mean. I made another edit above - it's the SPI.