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.
