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,

              the following code takes 12ms:

while (1) {
    GPIO_debug_on(true);
    if (!nrfx_twim_is_busy(&m_twim))
       break;
   GPIO_debug_on(false);

}

All the GPIO_debug_on does is toggle a gpio pin attached to a cathode ray oscilloscope. The switching of the gpio pin allows measurement of the time taken.

Cheers Paul

[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