NRF_TWIM_IS_BUSY is taking up to 12ms to return

[paul]

Hi,

      I am using an nrf52840 on a custom board with the 6.0 softdevice and 15.0 sdk. The I2C bus is running at 400khz.

I am reading 4 bytes on the i2c bus. The initial write to pass the register address takes about 90us for the bus to not be busy. The read takes about 6ms the first time and then subsequent times the time slowly grows to around 12plus milliseconds. I assume that I have stuffed up something in preparing the read.

Timing was done by toggling a GPIO pin high (GPIO_debug_on(true)) and low (GPIO_debug_on(false)) and then measuring the time with an CRO.

The I2C initilialisation:

void twim_init(void) {
static bool started = false;
  if (!started) {
      ret_code_t err_code;
      nrfx_twim_config_t twi_config = NRFX_TWIM_DEFAULT_CONFIG;
      twi_config.scl = TWI_SCL;
      twi_config.sda = TWI_SDA;
      err_code = nrfx_twim_init(&m_twim, &twi_config,  twi_handler, NULL);
      APP_ERROR_CHECK(err_code);
      nrfx_twim_enable(&m_twim);
      started = true;
  }
}

The read code:

/** @brief low level read byte from a register
*** @param[in] chip_addr is the i2c accress of the chip
*** @param[in] reg is the register address
*** @param[out] data is a pointer to a buffer for the results 
*** @param[in] count is size of buffer
*** @returns error code of the api read calls
*/
ret_code_t byte_read_multi_twi( uint8_t chip_addr, uint8_t reg, uint8_t *data, uint8_t count) {
ret_code_t err_code;
static rtc_mgt_t mgt; 



  startTimeout(&mgt, I2C_TIMEOUT);

  // handle time out and busy
  // prepare and write our reg on the bus that the chip will return the value in reg

  err_code = wait_for_busy(&mgt);

  if (err_code != NRF_SUCCESS) return err_code;

  // write the reg we want to read to the wire and the contents will come back
  err_code = nrfx_twim_tx(
      &m_twim, 
      chip_addr,
      &reg, 
      1, 
      false);

  if (err_code != NRF_SUCCESS) {
       
     //  APP_ERROR_CHECK(err_code);
  }   

  // prepare and read the data coming back. note that the state is changed in the handler on a successful write to idle
  err_code = wait_for_busy(&mgt);  
  if (err_code != NRF_SUCCESS) {
      // APP_ERROR_CHECK(err_code);
  }

  
  err_code = nrfx_twim_rx(
      &m_twim,
      chip_addr,
      data,
      count); 

  if (err_code != NRF_SUCCESS) 
       APP_ERROR_CHECK(err_code);
  }

  // wait for the stuff to come back
  err_code = wait_for_busy(&mgt);  

  return err_code;
}

the wait for busy code that has the nrfx_twim_is_busy call

/** @brief waits for the i2c channel to be free while monitoring timeout
*** @param[in] mgt is the real time clock management structure for this timer
*** @returns bad transfer, timeout or success
*/
ret_code_t wait_for_busy(rtc_mgt_t *mgt) {

 // while (nrfx_twim_is_busy(&m_twim) || !checkTimeoutExpired(mgt)) {

 while (1) {
GPIO_debug_on(true); 
    if (!nrfx_twim_is_busy(&m_twim))
       break;
GPIO_debug_on(false);
 /*
    if (checkTimeoutExpired(mgt)) 
       break;*/
     // yield();
  }

Any help would be gratefully received

Cheers Paul

[Einar Thorsrud]

Hi,

I am not able to see from the question where the unexpected delay is. Can you clarify? Is it some function that returns NRF_TWIM_IS_BUSY, but waits for too long before returning it? Which function? Or something else?

[paul]

hi Einar,

              as far as I can see, the chip itself does the following:

1) reads the value

2) sets a flag on the chip to say it is done

3) I then do the read of the results

4) this read steadily gets longer.

for what its worth, the chip is an ST vl53l0x time of flight or distance measurerer.

Cheers Paul

[Einar Thorsrud]

I see. But I do not understand what is causing this, so it would be interesting to see what is actually happening on the TWI lines. Do you have a logic analyzer trace showing this? It would be even better if you could include the debug GPIO pin you toggle before and after nrfx_twim_is_busy() in the same trace.

[paul]

Hi Einar,

              we don't own a logic analyser however we have done the following testing:

1) replicated the problem with an LP5018 LED controller on the same bus and using the same code. It also stretches out to around 13ms

2) We watched the transaction on the cro with the result:

     a) 2 bytes written

     b) 12 bytes returned

Total time activity on the bus is about 400us. It then takes the rest of the about 13ms in the handler or the wait for busy to say we are not busy.  I have attached a couple of photos.

<code>

while(1) {

GPIO_debug_on(true);
byte_read_multi_twi( 0x28, 3, buf, 12);
GPIO_debug_on(false);
nrf_delay_ms(1);
}

</code>

the following picture shows the full transaction. The bottom trace is the GPIO pin going high before the call and going low afterwards. The dip is the 1ms delay put in just to make it easier to see where the cycle starts.

The top trace shows the data line on the i2c bus. As you can see it starts soon after the timing period and then stops and there is a long time of no activity. The actual transation - ie data on the bus - takes 400us which was our rule of thumb expectation it would take.

This trace shows the activity on the i2c bus. The bottom trace is the clock at 400khz. The top is the data line. This looks like an address, then register, then 12 bytes coming back.

This trace shows the stop condition at the end of the transfer with both the clock and data line going high.

We are using nrf_malloc in the twim event handler to copy out the data returned. This is taking the 13ms. Removing the malloc produces this with a 100us delay between reads.

I guess the question is whether nrf_malloc should be taking up to 13ms to run? At this stage, I have removed the offending code and my sampling cycle has gone down to my target timing.

Cheers Paul

[Einar Thorsrud]

Hi Paul,

I was wondering if the slave did clock stretching, but it does not seem like this delay is directly related to TWI or the driver. Rather, you say that you do some work in the event handler (callback), and that could definitely explain this, since the driver waits with setting the internal busy flag to false until after executing the callback.

It is generally is bad practice to spend much time in the event handlers in the SDK. If you need to much work at this point it is typically better to defer the execution of the work to the main/thread context, for instance using an app scheduler or a simple volatile synchronization variable. This way it will not run in interrupt priority, and the event handler (which is essentially part of the TWI interrupt handling) is made as short as possible.

[paul]

Thanks Einar,

                      yeah I am aware of that issue, been bitten before. I believed I needed to copy the data out so needed something to put it in. What was worse it turns out was that I was never actually looking at the value and so never freeing it.  As the unfreed buffer count mounted the timing stretched out. This is one of the easy mistakes to do when doing event driven since things happen in many different places.

Your suggestion to trace it was what finally cracked the problem.

Many thanks

Paul