This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

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

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.

Fullscreen
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
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);
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

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

Fullscreen
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
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;
}
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

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.

Fullscreen
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
[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
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

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):

Fullscreen
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
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);
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

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

Fullscreen
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
[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
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

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.