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

[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]

The SPI transfer functions are only called within gps_run(). I send some commands at the start (TX) and then it's all RX from then on, in every call to gps_run().

I hooked another logic analyser channel up and set it high at the start of my gps_run() function, low at the end. Here's what I saw.

I had suspected that an SPI event was happening *after* the end of gps_run(), causing nrf_pwr_mgmt_run() to return and the main loop to iterate straight away. But the logic analyser shows no events happening in between executions of gps_run(). This leads me to conclude the event causing nrf_pwr_mgmt_run() to return is not an SPI event, but some other one. But keep in mind that the only peripherals I have enabled for this test are: SPIM2, RTC1, and GPIOTE.

For the RTC1, you can see in the test code above I'm setting up a couple of timers. There are a few more in the GPS driver. They're all either single shot, or for the recurring ones the interval is at least APP_TIMER_TICKS(1000).

[Jørgen Holmefjord]

Have you checked if any events are generated from the other peripherals (RTC1/GPIOTE) while the CPU is sleeping?

Do you see any difference in behavior if you call WFE() directly, instead of the nrf_pwr_mgmt_run() function?

__WFE();
// Clear the internal event register.
__SEV();
__WFE();

[Eliot Stock]

I hooked the PPI stuff up to check the following events:

NRF_RTC1->EVENTS_TICK

NRF_RTC1->EVENTS_OVRFLW

NRF_RTC1->EVENTS_COMPARE[0]

NRF_RTC1->EVENTS_COMPARE[1]

NRF_RTC1->EVENTS_COMPARE[2]

NRF_RTC1->EVENTS_COMPARE[3]

NRF_GPIOTE->EVENTS_IN[0]

NRF_GPIOTE->EVENTS_IN[1]

NRF_GPIOTE->EVENTS_IN[2]

NRF_GPIOTE->EVENTS_IN[3]

NRF_GPIOTE->EVENTS_IN[4]

NRF_GPIOTE->EVENTS_IN[5]

NRF_GPIOTE->EVENTS_IN[6]

NRF_GPIOTE->EVENTS_IN[7]

Here's what I saw for the first three of them:

Only the RTC1 compare event is happening and it's happening exactly as I would expect: once a second. (I'm actually a little confused as to why the TICK event *doesn't* fire, but it's good that it doesn't in my case so never mind that for now.)

None of the other events fired at all.

I tried replacing the nrf_pwr_mgmt_run() call with __WFE(); __SEV(); __WFE(); but alas, no difference.

[Jørgen Holmefjord]

That is strange. Have you ruled out if the SPIM peripheral is waking the chip up by itself, by replacing the call to gps_run() with toggling of a GPIO?

[Eliot Stock]

My goodness. With gps_run() commented out, the main loop toggles a GPIO every second.

I'm wasn't sure how to reconcile that with my earlier PPI discovery that no SPI events are occurring outside the scope of gps_run().

I started commenting out smaller and smaller parts of gps_run(). Before I start my SPI RX, I start a timer:

// Stop the SPI timeout timer, ignoring any error because it will only be that we haven't started it yet the first time, then start it again.
app_timer_stop(m_gps_spi_timeout_timer_id);
err_code = app_timer_start(m_gps_spi_timeout_timer_id, GPS_OUTPUT_TIMEOUT, NULL);
APP_ERROR_CHECK(err_code);

Just in case the SPI RX never happens, for example if the GPS receiver is dead or playing up, I only wait for it until that timer times out:

// Wait here until gps_spi_event_handler() is called by the SPI driver, or it times out.
// The SPI is running with priority of SPIM2_SPIS2_SPI2: 6 in our case. This is "higher" priority than the app timer.
while (!m_gps.spi_transfer_done)
{
	if (m_gps.spi_transfer_timed_out)
	{
		NRF_LOG_ERROR("SPI transfer timed out.");
		break;
	}

	// See above.
	nrf_pwr_mgmt_run();
}

Then I stop the timer:

// Stop the timeout timer, whether we timed out or not. If we did time out, this is harmless.
m_gps.spi_transfer_timed_out = false;
app_timer_stop(m_gps_spi_timeout_timer_id);

Now, I would expect that no events are generated outside the scope of gps_run() because of this timer stuff. But when I comment it all out, low and behold I get a nice one second interval between main loop iterations.

I still don't know which event it is though. I checked all the RTC1 ones above. Can you see the problem here? Is there a better way to time out on the SPI stuff?