flexcomm spi asynchroneous mode not working

[badevos]

I've tested spi on the NXP RW612 in both sync and async mode, which did not give the expected results.

When I use spi_transceive_cb I see that the the given callback is executed prior to the return of the function spi_transceive_cb itself.

The board uses this driver: spi_mcux_flexcomm.c

I've used Percepio TraceAlyzer to trace this:
I have added manual trace points, visible in 'yellow'
[app] spi-tx-beg: trace prior to call of function spi_transceive_cb
[app] spi-tx-end: trace right after the function spi_transceive_cb has returned
[app] spi-tx-cb: trace in the callback provided as argument to spi_transceive_cb

Synchronous:

Asynchronous: callback executed prior to the return point of spi_transceive_cb

In the screenshots I've also tried to measure the absolute timings, however due to the overhead of tracing itself this can be misleading. The actual data being sent out is the string "abcdefghijklmnopqrstuvwxyz" on 5Mhz, which takes about 41us. With the tracing overhead it's hard to find this particular timings.
On the other hand, +/- 300us seems quiete a lot, given the sitution that there is a trace less, and no interrupt context switch.

This has been tested on 4.0.0 as well as the current main, i.e. commit 4bb5ffd, both with zephyr sdk 0.17.0 on Linux/Ubuntu.

This is my test code:

#include <zephyr/kernel.h>
#include <zephyr/logging/log.h>
#include <zephyr/sys/printk.h>
#include <zephyr/shell/shell.h>
#include <zephyr/drivers/spi.h>

#ifdef CONFIG_PERCEPIO_TRACERECORDER
#include "trcRecorder.h"
#include "trcTypes.h"
traceString app_trace_channel;
#endif

LOG_MODULE_REGISTER(spi, LOG_LEVEL_DBG);

/* spi configuration */
static const struct device *spi_dev = DEVICE_DT_GET(DT_ALIAS(spi1));

static struct spi_config spi_cfg = {
    .frequency = DT_PROP(DT_ALIAS(spi1), clock_frequency),
    .operation = SPI_OP_MODE_MASTER | SPI_WORD_SET(8) | SPI_TRANSFER_MSB,
    .slave = 0,
    .cs = {
        .gpio = {NULL}, // No GPIO for CS
        .delay = 0,     // No delay
    },
};

static void spi_cb_done(const struct device * dev, int result, void * data);

/* spi shell commands */
static int cmd_spi_send(const struct shell *sh, size_t argc, char **argv)
{
    if (!device_is_ready(spi_dev))
    {
        LOG_ERR("Device SPI not ready, aborting test");
        return -ENODEV;
    }

    char *tx_buffer = argv[1];

    struct spi_buf tx_buf = {
        .buf = tx_buffer,
        .len = strlen(tx_buffer),
    };

    // LOG_DBG("SPI tx_buf.len = %d", tx_buf.len);

    struct spi_buf_set tx_bufs = { .buffers = &tx_buf, .count = 1 };

    // Send the string over SPI
    vTracePrint(app_trace_channel, "spi-tx-beg");
    int ret_val = spi_write(spi_dev, &spi_cfg, &tx_bufs);
    vTracePrint(app_trace_channel, "spi-tx-end");
    if (ret_val < 0)
    {
        shell_error(sh, "SPI write failed: %d", ret_val);
    }

    return ret_val;
}

static int cmd_spi_async(const struct shell *sh, size_t argc, char **argv)
{
    if (!device_is_ready(spi_dev))
    {
        LOG_ERR("Device SPI not ready, aborting test");
        return -ENODEV;
    }

    char *tx_buffer = argv[1];

    struct spi_buf tx_buf = {
        .buf = tx_buffer,
        .len = strlen(tx_buffer),
    };

    struct spi_buf_set tx_bufs = { .buffers = &tx_buf, .count = 1 };

    // Send the string over SPI
    vTracePrint(app_trace_channel, "spi-tx-beg");
    int ret_val = spi_transceive_cb(spi_dev, &spi_cfg, &tx_bufs, NULL, spi_cb_done, NULL);
    vTracePrint(app_trace_channel, "spi-tx-end");
    if (ret_val < 0)
    {
        shell_error(sh, "SPI write failed: %d", ret_val);
    }

    return ret_val;
}

void spi_cb_done(const struct device * dev, int result, void * data)
{
    vTracePrint(app_trace_channel, "spi-tx-cb");
}

SHELL_STATIC_SUBCMD_SET_CREATE(sub_spi_string,
    SHELL_CMD_ARG(send,  NULL, "SPI send",  cmd_spi_send,  2, 0),
    SHELL_CMD_ARG(async, NULL, "SPI async", cmd_spi_async, 2, 0),
SHELL_SUBCMD_SET_END);

SHELL_CMD_REGISTER(spi_string, &sub_spi_string, "SPI commands", NULL);

int main(void)
{
    app_trace_channel = xTraceRegisterString("app");

    while (1)
    {
        k_sleep(K_MSEC(1000));
    }
    return 0;
}

With the following prj.conf

CONFIG_SPI=y
CONFIG_SPI_ASYNC=y
CONFIG_CONSOLE=y
CONFIG_PRINTK=y
CONFIG_STDOUT_CONSOLE=y
CONFIG_LOG=y
CONFIG_SHELL=y
CONFIG_LOG_MODE_DEFERRED=y
CONFIG_DEBUG=y
CONFIG_SPI=y
CONFIG_DMA=y
CONFIG_SPI_MCUX_FLEXCOMM_DMA=y

CONFIG_TRACING=y
CONFIG_PERCEPIO_TRACERECORDER=y
CONFIG_PERCEPIO_TRC_START_MODE_START_AWAIT_HOST=y
CONFIG_PERCEPIO_TRC_CFG_ENTRY_SLOTS=1024
CONFIG_PERCEPIO_TRC_CFG_STACK_MONITOR_MAX_TASKS=32

Is this indeed a bug, or do I have the wrong expectation of spi_transceive_cb? In the latter case, how do I setup an asynchronous SPI transfer correctly?

[github-actions]

Hi @badevos! We appreciate you submitting your first issue for our open-source project. 🌟

Even though I'm a bot, I can assure you that the whole community is genuinely grateful for your time and effort. 🤖💙

[badevos]

I've analyzed some code myself and found this part in the driver:
https://github.com/zephyrproject-rtos/zephyr/blob/main/drivers/spi/spi_mcux_flexcomm.c#L691

		/* wait until TX FIFO is really empty */
		while (0U == (base->FIFOSTAT & SPI_FIFOSTAT_TXEMPTY_MASK)) {
		}

I tested my code without this check, and this has no effect.