Execution time of nrfx_spim_xfer

Question

I am using slightly modified master SPI example from here which is running on nRF5340 to communicate with slave device, which is RHD2216. SPI frequency is NRF_SPIM_FREQ_4M. Everything works fine, ie. I am sending 16 bit command and receiving 16bit data correctly.

The problem is execution time of nrfx_spim_xfer, which I measure using hardware timer and capturing its value. The execution time is ~12-13us, which seems to me a bit to much, because I expect 16bits/4MHz = 4us + some overhead.
I am getting almost three times bigger then expected values. Any ideas why is this happening?

Here's the modified example:

//main on SPI master
#include <zephyr.h>
#include "nrf.h"
#include <nrfx_spim.h>
#include <nrfx_clock.h>
#include <nrfx_gpiote.h>
#include <drivers/nrfx_errors.h>
#include <sys/printk.h>
#include <string.h>
#include <nrfx_timer.h>


#define SPI_INSTANCE 1
static const nrfx_spim_t spim = NRFX_SPIM_INSTANCE(SPI_INSTANCE);
const nrfx_timer_t timer1 = NRFX_TIMER_INSTANCE(1);
#define SPIM_SCK_PIN                (47U)
#define SPIM_MISO_PIN               (46U)
#define SPIM_MOSI_PIN               (45U)
#define SPIM_CS_PIN                 (44U)

#define NRFX_CUSTOM_ERROR_CODES 0 //used in nrfx_errors.h

static nrfx_spim_config_t spim_config =
	NRFX_SPIM_DEFAULT_CONFIG(SPIM_SCK_PIN, SPIM_MOSI_PIN, SPIM_MISO_PIN, SPIM_CS_PIN);

static uint8_t m_tx_buf[2];
static uint8_t m_rx_buf[2];
static const uint8_t m_length = sizeof(m_tx_buf);

static void manual_isr_spim_setup()
{
#if defined(NRF5340_XXAA)
    IRQ_DIRECT_CONNECT(SPIM1_SPIS1_TWIM1_TWIS1_UARTE1_IRQn, 0,
        nrfx_spim_1_irq_handler, 0);
    irq_enable(SPIM1_SPIS1_TWIM1_TWIS1_UARTE1_IRQn);
#endif
}

static void timer1_callback(nrf_timer_event_t event_type, void* p_context)
{
    // Empty
}

void main(void)
{
    //nrfx_clock_divider_set(NRF_CLOCK_DOMAIN_HFCLK, NRF_CLOCK_HFCLK_DIV_1);
    /*************************timer init*****************************/
    nrfx_timer_config_t timer1_config =
        {
            .frequency          = NRF_TIMER_FREQ_1MHz,
            .mode               = NRF_TIMER_MODE_TIMER,
            .bit_width          = NRF_TIMER_BIT_WIDTH_32,
            .interrupt_priority = NRFX_TIMER_DEFAULT_CONFIG_IRQ_PRIORITY,
            .p_context          = NULL
        };
    nrfx_timer_init(&timer1, &timer1_config, timer1_callback);
    nrfx_timer_enable(&timer1);
    /*************************timer init end*************************/

    /**************************SPI init******************************/

	m_tx_buf[0] = 0b11000000 | 40U;
    m_tx_buf[1] = 0b00000000;
	nrfx_spim_xfer_desc_t xfer_desc = NRFX_SPIM_XFER_TRX(m_tx_buf, m_length, m_rx_buf, m_length);

    nrfx_err_t err_code = nrfx_spim_init(&spim, &spim_config, NULL, NULL);
    if (NRFX_SUCCESS != err_code)
    {
        printk("nrfx_spim_init failed\n");
    }
    else
    {
        manual_isr_spim_setup();
    }
    /**************************SPI init end**************************/
	while(1)
    {
		memset(m_rx_buf, 0, m_length);

        uint32_t start_measuring = nrfx_timer_capture(&timer1, NRF_TIMER_CC_CHANNEL0);
        nrfx_err_t err_code = nrfx_spim_xfer(&spim, &xfer_desc, 0);
        uint32_t end_measuring = nrfx_timer_capture(&timer1, NRF_TIMER_CC_CHANNEL0);
        printk("Execution time: %u\n", end_measuring - start_measuring);

		if (err_code == NRFX_ERROR_BUSY) {
			printk("SPI busy\n");
		}

		else if (err_code != NRFX_SUCCESS){
			printk("Error code = %d\n", err_code);
		}

		k_sleep(K_MSEC(1000));

	}
}

Execution time of nrfx_spim_xfer

Top Replies