Long wait after given semaphore

[Saketaram]

The main loop in our nRF9160 (NCS v1.8.0) is a typical main loop with semaphore following https://docs.zephyrproject.org/latest/kernel/services/threads/system_threads.html?highlight=writing main function#id2

static K_SEM_DEFINE(timer_semaphore, 0, 1);


static void rtc0_handler(nrfx_rtc_int_type_t int_type)
{
// [ some logic related to RTC count ]

  if(expired) {
    LOG_INF("Give timer semaphore");
    k_sem_give(&timer_semaphore);
  }
}

static int rtc_config(void)
{
  int32_t err_code = 0;
  nrfx_rtc_config_t config = NRFX_RTC_DEFAULT_CONFIG;
  config.prescaler = 4095;
  err_code = nrfx_rtc_init(&rtc0, &config, rtc0_handler);
// [ some error logic ]
  nrfx_rtc_tick_enable(&rtc0, true);
  nrfx_rtc_enable(&rtc0);
  return 0;
}

void main(void)
{
// [ some initializations ]
  rtc_config();
// [ other initializations ]

  while (1)
  {
    LOG_INF("Wait for timer semaphore");
    k_sem_take(&timer_semaphore, K_FOREVER);
    LOG_INF("A timer expired");
// [ sensor data collect and send ]
  }
}

 

But there is a huge delay between the time semaphore is given and taken.

Some typical log extract follows:

00> [00:12:54.485,198] <inf> : Wait for timer semaphore
00> [00:15:40.744,873] <inf> : Give timer semaphore
00> [00:17:04.000,000] <inf> : A timer expired

-> 84 seconds delay

00> [00:17:06.688,018] <inf> : Wait for timer semaphore
00> [00:18:40.744,873] <inf> : Give timer semaphore
00> [00:21:23.187,957] <inf> : A timer expired

-> 83 seconds delay

00> [00:21:26.028,198] <inf> : Wait for timer semaphore
00> [00:24:40.744,873] <inf> : Give timer semaphore
00> [00:25:36.000,000] <inf> : A timer expired

-> 56 seconds delay

‌

How is it possible to troubleshoot this kind of issue?

[Susheel Nuguru]

The switch between rtc0_handler (which is giving a semaphore) to main(lowest priority Thread context, which is taking the semaphore) is not fast enough if there are other higher priority contexts ready to be run after rtc0_handler returns.

To get a proper overview on what is happening during that delay, we need to know what other contexts are executing in between giving the semaphore and main being able to run after taking the semaphore.

[Saketaram]

We fixed our synchronization issues by using a workqueue (https://docs.zephyrproject.org/2.7.0/reference/kernel/threads/workqueue.html).

Thanks for your help!