nRF SPI CS control: CS set / release delay is longer than configured

[etterli]

Describe the bug
When executing a spi_transceive() on the nRF52840 DK the delay between CS going low and the start of SPI communication and the delay from the end of the SPI communication till CS is going back high does not match the configured delay at all (see picture below) resulting in a reduced throughput as in my application the CS has to return back to high between two transfers.

Legend to picture:

• Yellow / gold: CS
• Green: SCK
• Blue: MOSI
• Red: MISO

The SPI communication is working as expected. However, in this case the delay is set to spi_cs_ctrl.delay = 0 (0us) but resulting is a delay of t_d_start = 3.6us and t_d_end = 12.9us, respectively. These delays are pretty constant over multiple measurements (+-0.05us).

When setting the spi_cs_ctrl.delay to longer delays the effective delays are extended by the configured value. So the mechanism to delay the CS change does work properly but the general SPI overhead is quite "slow".

Can someone explain why the SPI implementation is causing these delays and whether the undesired delay can be shortened in any way?

To Reproduce
Steps to reproduce the behavior:

• connect a SPI hardware (e.g. a sensor like Kionix KN134-1211) to nrf52840dk_nrf52840 board SPI 1 interface as defined in zephyr/boards/arm/nrf52840dk_nrf52840/nrf52840dk_nrf52840.dts with CS connected to P0.29
• setup an empty Zephyr application (everything is executed in the main thread) with a prj.conf like:

CONFIG_SERIAL=y
CONFIG_SPI=y
CONFIG_GPIO=y

• get SPI_1 and GPIO_0 device
• configure SPI with following settings:

struct spi_cs_control *spi_cs_ctrl = &(struct spi_cs_control) {
    .gpio_dev = /* insert gpio0_dev here */,
    .delay = 0,
    .gpio_pin = /* insert CS pin number here, in this case 29 */,
    .gpio_dt_flags = GPIO_ACTIVE_LOW
};
struct spi_config spi_cfg = {
    .operation = SPI_OP_MODE_MASTER | SPI_WORD_SET(8) | SPI_TRANSFER_MSB | SPI_MODE_CPOL | SPI_MODE_CPHA,
    .frequency = 8000000,
    .slave = 0,
    .cs = spi_cs_ctrl
};

• create SPI rx / tx buffers with 2x1Byte each (SPI transfers 2 Bytes)

uint8_t address[2] = {(1<<7) | reg_addr, 0x00}; // sensor specific
uint8_t rx_buffer[2] ;
  
const struct spi_buf tx_buf = {
  .buf = address,
  .len = sizeof(address)
};
const struct spi_buf_set tx = {
  .buffers = &tx_buf,
  .count = 1
};
struct spi_buf rx_buf = {
  .buf = rx_buffer,
  .len = sizeof(rx_buffer),
};
const struct spi_buf_set rx = {
  .buffers = &rx_buf,
  .count = 1
};

• execute spi_transceive(spi_dev, spi_cfg, &tx, &rx);
• measure time t_d_start from CS going low to start of SPI communication
• measure time t_d_end from end of SPI communication to CS going high
• compare delays with configured delay
• repeat test with spi_cs_ctrl.delay = 1 or any other valid value

Expected behavior
The delay between CS change and SPI transaction is approximately the configured delay and not off by that much for short delays.

Impact
It's a showstopper because the additional delay reduces the possible SPI throughput significantly as after each access the CS has to return high for at least one clock cycle for the used sensor. The desired data throughput cannot be achieved.

Logs and console output
n/a

Environment (please complete the following information):

• OS: Linux, Ubuntu 20.04
• Toolchain Zephyr SDK
• Zephyr Commit SHA used: 3704a40
• Nordic nRF52840-DK

Additional context
When configuring two SPI transfer at once (see picture below) there is a similar delay of t_d_2 = 14us between them. However, the end delay is reduced to t_d_end = 7.6us whereas the start delay remains the same (t_d_start = 3.6us).

(Ignore wrong SPI value interpretation, this is because of my oscilloscope is not able to parse it over this duration.)
SPI configuration (only code for tx shown):

const struct spi_buf tx_buf = {
  .buf = address,
  .len = sizeof(address)
};
const struct spi_buf tx_buf2 = {
  .buf = address,
  .len = sizeof(address)
};
const struct spi_buf tx_bufArr[2] = {
  tx_buf, tx_buf2
};
const struct spi_buf_set tx = {
  .buffers = tx_bufArr,
  .count = 2
};

[etterli]

@anangl Any estimation when you will have a look into this?

[anangl]

@etterli These additional delays are caused by the adaptation of the nrfx_spi driver to the Zephyr API that is done in the spi_nrfx_spi shim, in particular, by handling of the scattered buffers that this API permits. The CS line must stay active for potentially multiple SPI transfers so that one call to spi_transceive() results in one SPI transaction. That's why the CS line is activated and deactivated in the spi_nrfx_spi shim which then requests particular transfers to be performed by the nrfx_spi driver. Even for a single transfer, if the CS line was changed in the nrfx_spi driver, the CS line changes could be closer to the actual SPI communication, but anyway the whole transaction realized by spi_transceive() would take the same amount of time. Yet additional delay is caused by handling of the SPI interrupt that signals that the nrfx_spi driver finished a transfer (the CS line is deactivated after that interrupt handler is called and when there are no more transfers to be performed). As I checked, for the single transfer transaction, it takes about 4 us after the READY event (and consequently the interrupt) is generated by the SPI peripheral until the interrupt handler in the nrfx_spi driver gets called.
It's actually not a bug that those delays are longer than the value specified in the spi_cs_control structure. It would be a bug, if they were shorter than this value. But of course, I understand and agree that the overhead of the whole transaction is an issue in specific applications. For your application, since the transactions are short, I think it would be better to use the nrfx_spi driver directly and actually use it without interrupts, in a blocking manner, to avoid the context switching.
You can try with the following in prj.conf:

CONFIG_NRFX_SPI1=y

and code like this (after including <nrfx_spi.h>:

	#define SPI_NODE  DT_NODELABEL(spi1)

	static const nrfx_spi_t spi = NRFX_SPI_INSTANCE(1);
	nrfx_err_t err;

	nrfx_spi_config_t config = NRFX_SPI_DEFAULT_CONFIG(
		DT_PROP(SPI_NODE, sck_pin),
		DT_PROP(SPI_NODE, mosi_pin),
		DT_PROP(SPI_NODE, miso_pin),
		NRF_DT_GPIOS_TO_PSEL(SPI_NODE, cs_gpios));
	config.frequency = NRF_SPI_FREQ_8M;
	config.mode = NRF_SPI_MODE_3;

	err = nrfx_spi_init(&spi, &config, NULL, NULL);
	if (err != NRFX_SUCCESS) {
		printk("Failed to initialize SPI: 0x%08X\n", err);
		/* handle the error */
	}

	nrfx_spi_xfer_desc_t xfer_desc = {
		.p_tx_buffer = address,
		.tx_length = sizeof(address),
		.p_rx_buffer = rx_buffer,
		.rx_length = sizeof(rx_buffer),
	};
	err = nrfx_spi_xfer(&spi, &xfer_desc, 0);
	if (err != NRFX_SUCCESS) {
		printk("Transfer failed: 0x%08X\n", err);
		/* handle the error */
	}

If you want to use the Zephyr SPI driver for other instances (and you keep CONFIG_SPI=y in prj.conf), you need to disable spi1 in devicetree so that the Zephyr driver does not touch it.

If you would like to use the interrupts, you'll need to define an event handler:

static K_SEM_DEFINE(done, 0, 1);
static void event_handler(const nrfx_spi_evt_t *p_event, void *p_context)
{
	if (p_event->type == NRFX_SPI_EVENT_DONE) {
		k_sem_give(&done);
	}
}

and install the interrupt for it:

	IRQ_CONNECT(DT_IRQN(SPI_NODE), DT_IRQ(SPI_NODE, priority),
	 	    nrfx_spi_1_irq_handler, 0, 0);

or maybe better (since the SPI communication is performance-critical):

	IRQ_DIRECT_CONNECT(DT_IRQN(SPI_NODE), DT_IRQ(SPI_NODE, priority),
			   nrfx_spi_1_irq_handler, 0);

then change the driver initialization to:

	err = nrfx_spi_init(&spi, &config, event_handler, NULL);

and after calling nrfx_spi_xfer(), wait for the semaphore from the event handler:

	k_sem_take(&done, K_FOREVER);

When using the interrupts, it would make more sense to switch from SPI to SPIM (so that there is only one interrupt per transfer). You'll basically need to replace all above occurrences of NRFX_SPI with NRFX_SPIM and nrfx_spi with nrfx_spim.

[carlescufi]

Changed from Bug to Question since this is expected, although a problem for the user. A workaround has been provided, so @etterli I would be grateful if you could check @anangl 's suggested alternative and close this issue if that works for you.

[etterli]

@anangl Thank you for explaining the reason for the additional delay and proposing a solution.

I haven't tested your solution but found another way to come along with the delays and therefore close this issue.