nrf52 SPIM spi_transceive function occasionally doesn't return

[nwsetec]

Describe the bug
Occasionally a call to spi_transceive() doesn't return. When this happens the system has to be reset to function again. Sometimes when this occurs the Bluetooth submodule (which is also used in this project) and the shell continues to operate and other times they have both stopped working.

What have you tried to diagnose or workaround this issue?
I've looked at the each thread stack usage and there doesn't seem to be an issue there. I've got the CONFIG_STACK_SENTINEL=y and CONFIG_STACK_CANARIES=y and neither of these detect failures while running. I've tried increasing and decreasing the priority of the thread that contains the spi_transceive call to above and below the Bluetooth threads but that didn't help.

After searching through Zephyr issues I noticed issue #12342 and PR #12400 and wondered if this is related so I tried to cherry pick those commits to the 1.13.0 release, I got as far as the first 2 commits but the third (845e383) had too many changes since 1.13.0 to be easy to apply. The two commits I could apply plus configuring CONFIG_SWAP_NONATOMIC=y didn't fix the issue.

To Reproduce

CONFIG_SPI=y
CONFIG_SPI_INIT_PRIORITY=70
CONFIG_SPI_0=y
CONFIG_SPI_0_NAME="SPI_0"
CONFIG_SPI_0_OP_MODES=1
CONFIG_SPI_0_IRQ_PRI=7
CONFIG_SPI_NRFX=y
CONFIG_SPI_0_NRF_SPIM=y
CONFIG_SPI_0_NRF_SCK_PIN=14
CONFIG_SPI_0_NRF_MOSI_PIN=16
CONFIG_SPI_0_NRF_MISO_PIN=11
CONFIG_SPI_0_NRF_ORC=0x00

`
static struct spi_buf stSpi_tx_buffs[3];
static struct spi_buf stSpi_rx_buffs[3];

static const struct spi_buf_set stSpi_tx_buff_array = {
.buffers = stSpi_tx_buffs,
.count = 3
};

static const struct spi_buf_set stSpi_rx_buff_array = {
.buffers = stSpi_rx_buffs,
.count = 3
};

void app_spi_init(void)
{

stSpim_dma = device_get_binding(SPIM_DRV_NAME);

stConfig_chipSelect.gpio_dev = stGpio_dev;
stConfig_chipSelect.gpio_pin = SPI_CS_PIN;
stConfig_chipSelect.delay = 0;

stConfig_Spim.frequency = 1000000;
stConfig_Spim.operation = (SPI_OP_MODE_MASTER | SPI_TRANSFER_MSB
		| SPI_WORD_SET(8));
stConfig_Spim.slave = 0;
stConfig_Spim.cs = &stConfig_chipSelect;

uint8_t *au8_tx_data;
uint8_t *au8_rx_data;

au8_tx_data = (uint8_t*)&SPIS_stuMData;
au8_rx_data = (uint8_t*)&SPIS_stuSData;

stSpi_tx_buffs[0].buf = &au8_tx_data[0];
stSpi_tx_buffs[0].len = 200;
stSpi_tx_buffs[1].buf = &au8_tx_data[200];
stSpi_tx_buffs[1].len = 200;
stSpi_tx_buffs[2].buf = &au8_tx_data[2 * 200];
stSpi_tx_buffs[2].len = 200;

stSpi_rx_buffs[0].buf = &au8_rx_data[0];
stSpi_rx_buffs[0].len = 200;
stSpi_rx_buffs[1].buf = &au8_rx_data[200];
stSpi_rx_buffs[1].len = 200;
stSpi_rx_buffs[2].buf = &au8_rx_data[2 * 200];
stSpi_rx_buffs[2].len = 200;

}

`

The spi_transceive() call is happening at 20ms intervals.
spi_transceive(stSpim_dma, &stConfig_Spim, &stSpi_tx_buff_array, &stSpi_rx_buff_array);

Expected behavior
I've observed it on the CRO and can see that the SPIM operation completes (SS pin goes high, SPI clk signal stops) but a pin (used for debugging) that is set to high before the transfer and low after the transfer completes goes high and normally low afterwards but when the issue occurs it never goes low.

After up to an hour of operation the code stops working.

Impact
Showstopper

Screenshots or console output

In the above screenshot the blue falling pulse on the left shows a successful call to spi_transceive() and the one in the middle shows a successful transfer but no return to the calling thread. The blue trace shows the SS line. The green shows some post processing after the transfer is complete. The yellow shows the debug pin described above going high just before the transfer and low afterwards. Note the yellow trace also goes high and low again immediately after the transfer in the pulse on the left (redundantly showing the same information as the green trace).

Environment (please complete the following information):

• OS: Windows 7
• Toolchain: gcc-arm-none-eabi-7-2018-q2-update-win32-sha2.exe
• Zephyr 1.13.0

Additional context
We're using the nrf52832 SoC.
Bluetooth is configured as a peripheral and observer. It is configured to always be passively scanning.

[carlescufi]

@nwsetec Thanks for the detailed report. It would really help if you could try to narrow down where inside spi_transcieve the code is blocked. You can use your blue debug pin for that, or another one.

[DeclanTraill]

On further investigation, the call to spi_context_wait_for_completion() never returns.
Within this function it is the call to k_sem_take(&ctx->sync, K_FOREVER); that never returns.

If the sync semaphore give and take are replaced with a global volatile boolean flag, then there is no problem & the code runs (tested up to 2.5 hours so far with no problem).

e.g.

In spi_context_wait_for_completion(), instead of k_sem_take(&ctx->sync, K_FOREVER); do this:

while (!spim_done) k_sleep(1);

And in spi_context_complete(), instead of k_sem_give(&ctx->sync); do this:

spim_done = true;

Where spim_done is defined as:

volatile bool spim_done = false;

Also: shouldn't all semaphore variables that are shared between ISRs and Threads be declare as volatile, otherwise a thread may be waiting on a cached variable, rather than the actual value changed in an ISR?

Regards,
Declan Traill

[DeclanTraill]

... Oh, and at the start of transfer_next_chunk(), add spim_done = false;

BTW: I tried just changing both the lock and sync semaphore variables (but still use the sync semaphore) in struct spi_context to volatile (which generated about 20 compiler warnings as Zephyr Macros are not expecting the volatile keyword, so drop it). This seemed to make the timing of the SPI processing more reliable (we were getting occasional CRC errors before) and I didn't see any CRC errors, but the code still stopped on the k_sem_take(&ctx->sync, K_FOREVER); 25 minutes later.

[nwsetec]

@carlescufi if you hadn't already guessed Declan and I are working on the same issue :)

[nwsetec]

@carlescufi I checked also and added pin toggles either side of spi_context_wait_for_completion() in the transceive() function and I see the toggle before but not after.

[nwsetec]

For clarity I've removed the junk initialisation code (raw register access) that the nrf SPI driver would have overridden.

[DeclanTraill]

My test using a volatile global flag instead of a semaphore has been running without problems for 20.5 hours, so it is a workaround for the time being, but not a proper solution as when I do a sleep(1) after checking the done flag, the check won't be performed again for ~6 msec. This could delay the post processing of the SPI data where a semaphore would cause the context switch to occur when the DMA has actually completed (or shortly thereafter).

[nwsetec]

Which reminds me that our system clock tick is currently set as CONFIG_SYS_CLOCK_TICKS_PER_SEC=333 which explains the 6ms delay mentioned in Delcan's comment above (x2 3ms periods).
I changed CONFIG_SYS_CLOCK_TICKS_PER_SEC back to 50 (20ms period) and the issue still happened at the same spot.

[DeclanTraill]

Further to earlier tests, I have determined that the k_sem_give(&ctx->sync); in spi_conext complete() DOES get executed prior to the failure, but the k_sem_take(&ctx->sync, K_FOREVER); never receives it.

Here is the console output from a test resulting in the failure:

0 1 2 3 6 1 2 3 1 2 3 1 4 5 7
0 1 2 3 6 1 2 3 1 2 3 1 4 5 7
0 1 2 3 6 1 2 3 1 2 3 1 4 5 7
0 1 2 3 6 1 2 3 1 2 3 1 4 5 7
0 1 2 3 6 1 2 3 1 2 3 1 4 5 7
0 1 2 3 6 1 2 3 1 2 3 1 4 5 7
0 1 2 3 6 1 2 3 1 2 3 1 4 5 7
0 1 2 3 6 1 2 3 1 2 3 1 4 5 7
0 1 2 3 6 1 2 3 1 2 3 1 4 5 7
0 1 2 3 6 1 2 3 1 2 3 1 4 5 7
0 1 2 3 6 1 2 3 1 2 3 1 4 5 7
0 1 2 3 6 1 2 3 1 2 3 1 4 5

The numbers printed out are stages of the process: Here is the code that generated them:

`static int transceive(struct device *dev,
const struct spi_config *spi_cfg,
const struct spi_buf_set *tx_bufs,
const struct spi_buf_set *rx_bufs)
{
struct spi_nrfx_data *dev_data = get_dev_data(dev);
int error;

printk("0 ");
error = configure(dev, spi_cfg);
if (error == 0) {
dev_data->busy = true;

	spi_context_buffers_setup(&dev_data->ctx, tx_bufs, rx_bufs, 1);
	spi_context_cs_control(&dev_data->ctx, true);

	transfer_next_chunk(dev);

printk("6 ");
error = spi_context_wait_for_completion(&dev_data->ctx);
printk("7\r\n");
}

spi_context_release(&dev_data->ctx, error);

return error;

}

static void transfer_next_chunk(struct device *dev)
{
struct spi_nrfx_data *dev_data = get_dev_data(dev);
const struct spi_nrfx_config *dev_config = get_dev_config(dev);
struct spi_context *ctx = &dev_data->ctx;
int error = 0;

printk("1 ");

size_t chunk_len = spi_context_longest_current_buf(ctx);

if (chunk_len > 0) {

printk("2 ");
nrfx_spim_xfer_desc_t xfer;
nrfx_err_t result;
const u8_t *tx_buf = ctx->tx_buf;
#if (CONFIG_SPI_NRFX_RAM_BUFFER_SIZE > 0)
if (spi_context_tx_buf_on(ctx) && !nrfx_is_in_ram(tx_buf)) {
if (chunk_len > sizeof(dev_data->buffer)) {
chunk_len = sizeof(dev_data->buffer);
}

		memcpy(dev_data->buffer, tx_buf, chunk_len);
		tx_buf = dev_data->buffer;
	}

#endif
if (chunk_len > dev_config->max_chunk_len) {
chunk_len = dev_config->max_chunk_len;
}

	dev_data->chunk_len = chunk_len;

	xfer.p_tx_buffer = tx_buf;
	xfer.tx_length   = spi_context_tx_buf_on(ctx) ? chunk_len : 0;
	xfer.p_rx_buffer = ctx->rx_buf;
	xfer.rx_length   = spi_context_rx_buf_on(ctx) ? chunk_len : 0;
	result = nrfx_spim_xfer(&dev_config->spim, &xfer, 0);

printk("3 ");
if (result == NRFX_SUCCESS) {
return;
}

printk("* ");
error = -EIO;
}

spi_context_cs_control(ctx, false);

SYS_LOG_DBG("Transaction finished with status %d", error);

printk("4 ");
spi_context_complete(ctx, error);
dev_data->busy = false;
}

static inline void spi_context_complete(struct spi_context ctx, int status)
{
#ifdef CONFIG_SPI_ASYNC
if (!ctx->asynchronous) {
ctx->sync_status = status;
k_sem_give(&ctx->sync);
} else {
if (ctx->signal) {
#ifdef CONFIG_SPI_SLAVE
if (spi_context_is_slave(ctx) && !status) {
/ Let's update the status so it tells
* about number of received frames.
/
status = ctx->recv_frames;
}
#endif / CONFIG_SPI_SLAVE */
k_poll_signal(ctx->signal, status);
}

	if (!(ctx->config->operation & SPI_LOCK_ON)) {
		k_sem_give(&ctx->lock);
	}
}

#else
k_sem_give(&ctx->sync);
printk("5 ");
#endif /* CONFIG_SPI_ASYNC */
}

`