execution profiling

[paul]

Hi, 

     we are developing on the nrf52840 using SES and SDK 15.0. This is a custom board. Softdevice is s140_nrf52_6.0.0_softdevice.hex

We are sampling distance with vl53l0x chips. The chips are sampled in a loop and the results smoothed and then written to a service characteristic. The aim is to achieve the cycle within 20ms/50hz. We have an implementation working on another chipset but are having trouble porting to the nrf52.

for(;;) {
//int32_t tick_st = rtc_get_tick();
       startTime = RTC_TICKS_TO_MS(rtc_get_tick(), RTC_FREQ_TICK);
       if (sched_get_state() != SCHED_TOP_ST_SAMPLING) {
           NRF_LOG_INFO("NOT IN SAMPLING STATE");
           break;
       }
       // enter loop every 20ms 
       if (lastTime_ == 0)
          lastTime_ = startTime;
       if (startTime >= lastTime_ + 20 ) {
flex_DebugData(2, startTime - lastTime_);
          /*
          ** get the range data from the chip
          */
       } 
}

The real time counter - rtc functions above - is set to milliseconds.

#define RTC_FREQ_TICK 1000

/** @brief Function initialization and configuration of RTC driver instance for ticks.
 */
void rtc_config_tick(void)
{
    uint32_t err_code;

    if (!is_uninit) {
       nrfx_rtc_disable(&rtc);
       nrfx_rtc_uninit(&rtc);
    } 

    // get the crystal buzzing
    /// The clock is also used by the softdevice. Depending on what else is started we may or may not have to start it
    if (!nrfx_clock_lfclk_is_running())
       lfclk_config();

    //Initialize RTC instance
    nrfx_rtc_config_t config = NRFX_RTC_DEFAULT_CONFIG;
    config.prescaler = RTC_FREQ_TO_PRESCALER(RTC_FREQ_TICK);
    err_code = nrfx_rtc_init(&rtc, &config, rtc_handler);
    APP_ERROR_CHECK(err_code);
    is_uninit = false;

    //Enable tick event & interrupt
    nrfx_rtc_tick_enable(&rtc,true);

    // enable over flow event
    nrfx_rtc_overflow_enable(&rtc, true); 
	
    //set the counter to 0
    nrfx_rtc_counter_clear(&rtc);

    //Power on RTC instance
    nrfx_rtc_enable(&rtc);
}

The measurement point at flex_DebugData(2, startTime - lastTime_) shows a time of 37 to 38ms. It is unclear where the extra 17 - 18ms is used. It should be noted that on a test run, this value starts at 20ms and then slowly creeps up until it sits fairly steady at the 37 to 38ms. 

While in the loop there are a steady stream of writes to a service characteristic. This characteristic is set with notify enabled. You also have a bunch of writes to another characteristic with notify enabled for debug writes.

I am not sure how to track down where the extra 17-18ms is coming from - I would guess the softdevice servicing the characteristic writes but am not sure.

Any pointers would be greatly appreciated.

Cheers Paul

[Edvin]

Hello Paul,

It is a bit difficult to say without knowing what you do inside your flex_DebugData(), and what other tasks your application is doing. Is there any more relevant information you can share?

While in the loop there are a steady stream of writes to a service characteristic.

Where are you sending data over BLE?

Without knowing anything about your application, from a power consumption point of view, it doesn't look like you ever let your chip go to sleep. I don't know whether this is a concern for you.

 

Best regards,

Edvin

[paul]

hi Edvin,

                In trying to resolve this I simplified the code down. The for loop is not timer/interrupt driven - just normal flow of execution. It should enter the third if statement every 20ms unless something that is timer/interrupt driven is taking a long time. The flex_debugdata call simply writes that value - lastTime_ - startTime to a characteristic for debug purposes. It should be 20. However at steady state it is 37 - 38 hence the 17 to 18 ms lost. 

I finally found where this extra time was going. Seems I had a couple of SDH logs enabled. With these switched off, the measurement timing comes back to 51.2hz or ~20ms

Thanks for your help

Paul

-