sd_app_evt_wait() behavior

[ves]

Hi

In my app i need to keep in sync client/server communication, which means no packet is sent in any direction until the sender got the confirmation from receiver for the previous packet.

I’m doing this using a cmd/resp protocol. Client(Android) is driving the communication sending commands and the GATT server (52832/s132) send messages either as response to commands or unsolicited messages if the client enable this feature.

Server messages are indications sent using sd_ble_gatts_hvx() and each message has to be confirmed by a BLE_GATTS_EVT_HVC event. If BLE_GATTS_EVT_HVC is not received within 500 msec the assumption is the BLE packet is lost and server will retry sending the message. If retry fails 5 times the server considers client is dead and disconnects itself.

To monitor the HVCs I have a global variable: wait_for_hvc and an app timer: hvc_timer

hvc_timer handler clears wait_for_hvc and increments hvc_unack variable.

Before calling sd_ble_gatts_hvx() I check wait_for_hvc and if ‘1’ I need to wait until it gets 0 either by BLE_GATTS_EVT_HVC or by hvc_timer handler.

To wait for this event I implemented my sleep function, based on sd_app_evt_wait() and an additional app timer: sleep_timer

Here is the code for the sleep function, timer functions and the part of the application using sleep function

APP_TIMER_DEF(sleep_timer_id);
APP_TIMER_DEF(m_hvc_timer_id);
static uint8_t sleep_timeout;
timer_func()
	{
	...
	err_code = app_timer_create(&sleep_timer_id, APP_TIMER_MODE_SINGLE_SHOT, sleep_timeout_handler);
	APP_ERROR_CHECK(err_code);
	sleep_timer = sleep_timer_id;
	...
	
	err_code = app_timer_create(&m_hvc_timer_id, APP_TIMER_MODE_SINGLE_SHOT, hvc_timeout_handler);
	APP_ERROR_CHECK(err_code);
	hvc_timer = m_hvc_timer_id;
	}

void sleep_timeout_handler(void *p_context)
  {
  sleep_timeout = 1;
  }

void hvc_timeout_handler(void *p_context)
  {
  wait_for_hvc = 0;
  hvc_unack++;
  NRF_LOG_INFO("hvc timeout: %x", hvc_unack);
  if(hvc_unack > HVC_UNACK_MAXCOUNT)
    sd_ble_gap_disconnect(m_conn_handle, BLE_HCI_REMOTE_DEV_TERMINATION_DUE_TO_POWER_OFF);
  }


void sleep(uint32_t msec2sleep)
  {
  uint32_t err_code;
  sleep_timeout = 0;
  err_code = app_timer_start(sleep_timer, APP_TIMER_TICKS(msec2sleep), NULL);
  APP_ERROR_CHECK(err_code);
  while(!sleep_timeout)
    {
    sd_app_evt_wait();
    nrf_sdh_evts_poll();
    } 
  }
  
/* code in the application */
while(wait_for_hvc) // wait until wait_for_hvc = 0
	{
    NRF_LOG_INFO("auth-request: wait_for_HVC still 1");
    sleep(10);
    }
err_code = sd_ble_gatts_hvx(m_service.conn_handle, &hvx_params);
if(err_code == NRF_SUCCESS)
	{
  // open HVC window
    APP_ERROR_CHECK(app_timer_start(hvc_timer, APP_TIMER_TICKS(HVC_TIMEOUT), NULL)); 
    wait_for_hvc = 1;
  //--------------------------------------------
    }

The issue comes with sleep function. The moment this function is called (once 20-30 messages) it loops for ever because sleep_timeout is never set by sleep_timeout_handler which is never invoked. If I force a break in the loop after some 500000 iteration then the breakpoint in the sleep_timeout)_handler is hit.

My expectation here is sd_app_evt_wait to return on app timer expiration which will invoke sleep_timer_handler, which will set sleep_timeout, causing the loop in sleep function to break… but this does not happen 

More, I measured the duration of a loop cycle, which is test sleep_timeout, call and wait for return sd_app_evt_wait, call and wait for return of nrf_sdh_evts_poll. This is roughly 22usec … Don’t know which event can cause sd_app_evt_wait to return so frequently, but this is another story.

According to the comments in this ticket https://devzone.nordicsemi.com/f/nordic-q-a/71852/wake-up-sd_app_evt_wait-from-application/302009#302009, it should work as expected but it doesn’t.

There is a note in sd_app_evt_wait documentation

@note If an application interrupt has happened since the last time sd_app_evt_wait was
* called this function will return immediately and not go to sleep. This is to avoid race
* conditions that can occur when a flag is updated in the interrupt handler and processed
* in the main loop.

which is pretty confusing to me

[Edvin]

Hello,

There is a lot of information to wrap my head around here, but I think you started off with some lack of information. All BLE packets are retransmitted according to the specification.

 

If retry fails 5 times the server considers client is dead and disconnects itself.

 Basically, this is implemented in the softdevice. The limit is not 5, and not a number, really, but if the packet is not acknowledged within the supervision timeout, the link is disconnected. Actually, BLE will send empty packets if they don't have any useful payload to send. If one device hasn't received any packets for the duration of the supervision timeout, the link is considered disconnected. Any packet that contains payload, that is not Acknowledged by the connected device needs to be retransmitted until it is acknowledged (it is not discarded unless the link is disconnected).

So while your logic may work, it is not necessary in BLE.

I am not sure what the question is. Is the timer not working? Try declaring your sleep_timeout as a volatile parameter:

volatile uint8_t sleep_timeout;

Then you are sure that the compiler will not assume that it already knows the value of sleep_timeout, but actually checks whether or not it is updated before using it. This can happen sometimes when optimization is used. The main() function will assume that it knows sleep_timeout, because it was set in that function.

Best regards,

Edvin

[ves]

Hi Edvin

Thx for your reply.

Yes i know the retransmission protocol in BLE, but i'm trying to take this up to the app level in android (…i'm not there yet ).  I'm not concerned too much about nrf device, but about android. And that was only the background story.

My question is about sd_app_evt_wait behavior. As soon as the sleep function is hit, it loops for ever in the while loop (I tried also with volatile, same result).

sd_app_evt_wait returns immediately and the loop cycle rate is ~22usec.

sleep_timeout_handler is never executed.

I did an experiment breaking the loop after 0x80000 cycles. At this point the bkp in sleep_timeout_handler is hit.

So it looks even i call app_timer_start the timer does not start... or it starts but counting is stopped by the loop?!?

[Edvin]

I have seen a lot of users trying to implement their own sleep cycle, and most of the times they tend to go back to the default structure that is used in our examples (having sd_app_evt_wait() in the while loop of the main() function. You should consider it unless you have a particular reason to have it like this.

Either way, from a support point of view:

Where is this located?

/* code in the application */
while(wait_for_hvc) // wait until wait_for_hvc = 0
	{
    NRF_LOG_INFO("auth-request: wait_for_HVC still 1");
    sleep(10);
    }
err_code = sd_ble_gatts_hvx(m_service.conn_handle, &hvx_params);
if(err_code == NRF_SUCCESS)
	{
  // open HVC window
    APP_ERROR_CHECK(app_timer_start(hvc_timer, APP_TIMER_TICKS(HVC_TIMEOUT), NULL)); 
    wait_for_hvc = 1;
  //--------------------------------------------
    }

Is it called from an interrupt, or is this in your main-loop?

Although I don't recommend it in the end (that depends on several things), does the behavior change if you replace sleep(10) by nrf_delay_ms(10)?

It may not make a difference, but I suspect you are seeing some interrupt priority issues. If I understand your implementation correctly, you are starting a timer, and when that timer times out, you set wait_for_hvc to false. 

If you are starting this timer from the same priority, or higher, as the app_timer, then the app_timer's timeout handler will never be able to execute, because it is blocked. 

If this is the case, you need to "release" your current interrupt, by returning that interrupt function. Perhaps you can do the next part, err_code = sd_ble_gatts_hvx()... from your application timeout handler?

Best regards,

Edvin

[ves]

I have 2 places in the code where sleep() function is called and both are in interrupt context one is in RTC1_IRQHandler() context and the second is in SWI2_EGU2_IRQHandler() (according to call stack in the debugger)

But in the first case there are already 2 timers running in parallel: notification_timer and hvc_timer., which i can confirm are running fine. Here is the full timers initialization function

void timers_init()
  {
  // Initialize timer module.
  ret_code_t err_code;
  //-------------- app timer -------------------------------
  err_code = app_timer_init();
  APP_ERROR_CHECK(err_code);
  
  // ------- notification timer --> send updated values to client --------------
  err_code = app_timer_create(&m_notification_timer_id, APP_TIMER_MODE_REPEATED, notification_timeout_handler);
  APP_ERROR_CHECK(err_code);
  notification_tid = m_notification_timer_id;

  // ------- cmd/req window timer --------------
  err_code = app_timer_create(&m_cmdreq_timer_id, APP_TIMER_MODE_SINGLE_SHOT, cmdreq_timeout_handler);
  APP_ERROR_CHECK(err_code);
  cmdreq_timer = m_cmdreq_timer_id;

  // ------- HVC window timer --------------
  err_code = app_timer_create(&m_hvc_timer_id, APP_TIMER_MODE_SINGLE_SHOT, hvc_timeout_handler);
  APP_ERROR_CHECK(err_code);
  hvc_timer = m_hvc_timer_id;

  // ------- sleep timer --------------
  err_code = app_timer_create(&sleep_timer_id, APP_TIMER_MODE_SINGLE_SHOT, sleep_timeout_handler);
  APP_ERROR_CHECK(err_code);
  sleep_timer = sleep_timer_id;
  sleep_in_progress = 0;
  }
  
  void notification_timeout_handler(void * p_context)
  {
  UNUSED_PARAMETER(p_context);
  ret_code_t err_code;
    
  // Increment the value of m_custom_value before notifying it.
  if (board_state == CONNECTED && m_conn_handle != BLE_CONN_HANDLE_INVALID)
    {
    m_custom_value++;
    // here in timer_value_update() hvc_timer is started
    err_code = timer_value_update(m_custom_value);
    APP_ERROR_CHECK(err_code);
    }
  }

Why starting a 3rd timer will create additional problems?

if in the sleep function loop i add this check

while(!sleep_timeout)
    {
    if(!wait_for_hvc)
        break;

    ....
    }

then the loop breaks after few thousands iteration. So both notification and hvc timers are running fine with hvc timer started in the interrupt context of timeout handler

Using nrf_delay_ms() i get into same situation and the reason i try to implement my sleep function is this comment

"nrf_delay should be used basically never.  I think they put it in there to keep people happy who still remember basic. The nrf_delay operates by executing a series of __nop (ie, no operation opcode). Since this just hangs up the processor during the delay it won't service your interrupt depending on the interrupt priority" in Case ID: 209870

[Edvin]

I agree with the comment, but trying to understand what's going on, testing this could be useful.

What I wanted to know wasn't actually answered. Let me try again:

In your original post you say that you are "stuck in the while loop". What while loop is that? Is it the while (!sleep_timeout)?

If so, where is the while(!sleep_timeout) loop? Is it in your main() function? Or is it called from an interrupt?

I suspect that we will go back and forth a few times before this is resolved. Consider just uploading the entire main.c file if that is where this is happening.

FYI, there is an API to check your current interrupt priority:

current_int_priority_get()

NRF_LOG_INFO("IRQ priority %d", current_int_priority_get());

What interrupt priority is your while(!sleep_timeout) running in?

[ves]

Sorry i could not make it more clear for you...

Edvin said:

In your original post you say that you are "stuck in the while loop". What while loop is that? Is it the while (!sleep_timeout)?

• Yes is the while(!sleep_timeout)

Edvin said:

If so, where is the while(!sleep_timeout) loop? Is it in your main() function? Or is it called from an interrupt?

• It is called from an Interrupt. This is the call stack

void sleep(unsigned int msec2sleep=0x00000064)
uint32_t timer_value_update(unsigned char val2update=0x04)
void notification_timeout_handler(void* p_context = 0x00000000)
_Boot timer_expire(app_timer_t* p_timer(0x20005568)
void on_compare_evt(const drv_rtc_t* p_instance=0x2000228c)
void rtc_irq(const drv_rtc_t* p_instance=0x2000228c)
void RTC1_IRQHandler()

sleep function is called in RTC1_IRQHandler context triggered by notification timer (see line 10 in timers initialization function)

• current_int_priority_get() returns 6 in sleep function and same in notification_timeout_handler (line 31 in timers initialization function)

Regarding my previous comment

ves said:

But in the first case there are already 2 timers running in parallel: notification_timer and hvc_timer., which i can confirm are running fine. Here is the full timers initialization function

I need to withdraw it. I dont know if second timer is running. wait_for_hvc variable can be set to 0, either by hvc_timeout_handler, or by HVC_EVT received by the the soft device from client.

Edvin said:

Consider just uploading the entire main.c file if that is where this is happening.

Its more than 1 file to upload, i need to give you my entire project. I can do it if you think is necessary.

Will try to explain again the flow

1. Notification is started in repeated mode with 700 msec timeout value
2. in notification timeout handler app is sending a value to client
   1. first check if it received the HVC for previous value (wait_for_hvc = 0)
   2. if wait_for_hvc == 0, waits until it gets 0 using sleep function
3. after wait_for_hvc = 0 sends the indication with the new value -> sd_ble_gatts_hvx()...
4. starts hvc_timer

Here at 2.b execution gets stuck

Hopefully is more clear now. If not let me know and will send the project.