nrf_delay_ms not working?

[Robin]

Hello Nordic Pros,

Doing some debugging using RTT Viewer and an nRF51822 under SDK12.3.  Here is the code lines of interest:

...
    NRF_LOG_INFO("IPHONE 'PPM' RECEIVED @ %d mS\r\n", m_life_count_msec);
    nrf_delay_ms(2000);
    NRF_LOG_INFO("ID QUERY '?' SENT AT: %d\r\n", m_life_count_msec);
...

And here are the log messages:

iDrink::INFO:IPHONE 'PPM' RECEIVED @ 683250 mS
iDrink::INFO:ID QUERY '?' SENT AT: 683250

m_life_count_msec is a copy of an app timer count in mSec that is set up to inc ~ every 50 mSec.

Here is the timer setup code:

...
  app_timer_create(&m_app_timer_id, APP_TIMER_MODE_REPEATED, timeout_handler);  //create and start timer...
  app_timer_start(m_app_timer_id, APP_TIMER_TIMEOUT_TICKS, (void*) 0);
...

And here is the timeout code showing the assignment to m_life_count_msec:

...
void timeout_handler(void * context)
{
...
  m_life_count_msec   += APP_TIMER_MS_COUNT;
...

Obviously the questions is, why is there not a 2000 mSec delay between the two log messages?

Does nrf_delay_ms() suspend m_app_timer while it is counting?

Help, please!

Robin @ TL

[Robin]

Hello again, Kenneth, Nguyen,

So, I have made the variable "volatile"

...
static volatile uint32_t m_life_count_msec = 0;
...

I access it in a function called by the timeout handler:

...
void timeout_handler(void * context)
{
  connect_chk_count += APP_TIMER_MS_COUNT;
  board_life_chk_count += APP_TIMER_MS_COUNT;
  m_timer_msec        += APP_TIMER_MS_COUNT;
  m_counter_msec      += APP_TIMER_MS_COUNT;
  m_life_count_msec   += APP_TIMER_MS_COUNT;
  
  if (board_life_chk_count >= BOARD_LIFE_CHK_PERIOD)
  {
    board_life_chk_count = 0;
    board_life_chk();
  }
  switch (m_app_mode)
  {
    case APP_CONNECT_CHK:
      if (connect_chk_count >= 500)
      {
        connect_chk_count = 0;
        connect_check();
      }
    break;
...

I then print the variable before and after the delay using RTT Viewer:

...
void connect_check(void)
{
//    sprintf(message_buffer, "?");
//    m_send_string(message_buffer);
  static uint8_t check_count = 0;
  
  if (iphone_connect)
  {
    NRF_LOG_INFO("DELAY TEST 1: %d mSec\r\n", m_life_count_msec);
    nrf_delay_ms(2000);
    NRF_LOG_INFO("DELAY TEST 2: %d mSec\r\n", m_life_count_msec);
    NRF_LOG_INFO("IPHONE CONNECT @ %d mSec\r\n", m_life_count_msec);
    NRF_LOG_INFO("CHECK COUNT = %d\r\n", check_count);
...

Yet still, the variable is not updated while the delay is happening, (and it does appear to be happening if I manually time between the two prints:

iDrink::INFO:DELAY TEST 1: 272600 mSec
iDrink::INFO:DELAY TEST 2: 272600 mSec

So it appears that this delay function does suspend any app delay functionality while it runs.

Do you know of a way to use both functions successfully?

Thanks

Robin @ TL

[Nguyen Hoan Hoang]

does the connect_check get called from a BLE event ? If that is the case, it is likely be at higher priority or from an other event that has higher priority then your timer timeout would never get serviced during the delay.  

[Robin]

Hi Nguyen,

• Yes, the handler is exited, I only showed the case that makes the call.  Note the break followed by ...

There are several other cases below for other cases below.

Robin @ TL

[Mojo]

As Nguyen Hoan Hoang said the connect_check was called within the timeout_handler.  You never exited the handler, so the counter can't be updated by the timer.

[RK]

No the handler is only exited after you've done the 2 second delay, that nrf_delay_ms (as I told you) is just a spin on the CPU so it doesn't get past that line until the 2 seconds is finished and thus stays in the timeout handler. You are literally blocking your own code. While you're there hundreds or thousands of timeout interrupts occur, but you're in the timer ISR and none of them are taken until you finally exit and get one update. And this is what Kenneth asked you about in his first reply when he suggested you are calling the log (and delay) in an interrupt handler and thus blocking the variable update, that is exactly what you're doing. 

[Robin]

Hi Everyone,

So apparently I don't understand the context of this interrupt.  Please suggest how it could be done outside the interrupt context.  It seems like a catch 22 situation.  

Thanks for your help.

[RK]

Not sure what you're not understanding here. timeout_handler() is called from the timer interrupt. I suggested earlier that you attach a debugger and break there, then you'll see the stack trace which will start with TIMER1_IRQHandler or something similar. Until you finish running your LOG/delay/LOG code, you're still in the ISR. 

Neither do I understand what you're trying to do. Why are you logging, spinning the CPU for 2 seconds, then logging again? What's the purpose behind that code? If it's to delay the sending of a packet by approximately 2 seconds, you are accomplishing that, however at the cost of breaking your time counter. You're mixing sychronous (nrf_delay_ms) and asynchronous (timeout_handler) code. The obvious way to do this is .. be asynchronous. Set up a state machine, after your first log line, capture the current timer and move to a waiting state in your state machine, then exit the handler. Each time through the timeout_handler work out if 2 seconds have elapsed yet if you are in waiting state, if they have execute your second LOG line and the code which comes after it and move to another state. 

Or start another timer at the first LOG line which calls a different handler when it times out 2 seconds later. You can have more than one timer, put the second half of the code in the other handler. 

It's not a hard and fast rule, but usually if you're using nrf_delay_*() for anything other than a micro delay, a few cycles perhaps, often you're doing the wrong thing. 

So state machine or second timer, get rid of the synchronous delays. 

[Robin]

So let me try to get this straight...Even though the handler is getting called every 50 mSec, because the function I call is within the handler, the variable does not get updated?  That sounds, to me, like the app timer is being blocked by the delay function.  I was unaware that the delay was a "synchronous" function, so that explains it.  I guess I should have looked deeper into the code I I was using, rather than assume it was asynchronous.  

The silly thing here is... all I was trying to do, was confirm that the delay was happening.  At some level, I would thought ( or maybe more appropriately, hoped) that anything named with "delay" in it would have a very similar structure.  

Thank you all for an embarrassingly basic lesson.

Obviously this embedded coding stuff has not been my first engineering task in life.

Thanks again,

Robin @ TL

[RK]

I'd put it slightly differently, the handler is not getting called every 50ms, the timer is raising an interrupt isevery 50ms. If the processor is running anything with lower priority, then it takes the interrupt and runs the handler, else the interrupt just pends. When the processor returns from the interrupt handler it was running, then it runs the next handler for the highest priority pended interrupt. 

If the ISR doesn't return quickly, the interrupt keeps firing and firing and firing, but the processor cannot interrupt itself for something of equal or lower priority, so those interrupts just pend and coalesce into one which does get called when the first handler call finally returns. 

In your case the first call of the handler didn't return for about 2 seconds because it was stuck in nrf_delay_ms which is basically a carefully implemented in assembler for-loop designed to keep the processor spinning for a number of milliseconds. As soon as it did return, the handler would have been called again as there were missed interrupts, 40 of them, but by then you've done both LOGs and exited and your counter has missed 2 seconds of counts.