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[bot]]

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.

[badevos]

Hi @dleach02,

I see you gave this a low priority.

Can you confirm that my reasoning is correct, and spi_transceive_cb should return earlier than execution of the completion callback?

[dleach02]

Sorry, this is a Zephyr Project rating and not an internal NXP rating. Zephyr Project tends to put issues that only affect one platform as low priority.

We have pulled the details of your ticket into our internal tracking system and reviewing it.

[DerekSnell]

Hi @badevos ,
I can confirm spi_transceive_cb() functions as expected, and may not return before the callback executes.

To test this, I ran the spi_loopback test on the FRDM-RW612 board using Zephyr v4.1. For this test to pass, the MOSI and MISO signals must be shorted externally, by shorting header J1 pins 2 and 4. This test also tests Async mode, and I enabled DMA to match your use-case.

The spi_loopback test calls spi_transceive_signal() for the async test, instead of spi_transceive_cb(). And that signal is used to trigger a thread function called spi_async_call_cb(). Similar to what you found, I see that the thread spi_async_call_cb() is triggered and executes before spi_transceive_signal() completes.

I modified the spi_loopback test with the attached patch spi_loopback-spi_transceive_cb.txt to use spi_transceive_cb() instead of spi_transceive_signal(). Apply this patch to v4.1, and this test still passes. I ran in a debugger with breakpoints instead of trace, but I see the same results: the callback spi_cb_done() is called before spi_transceive_cb() returns.

Below is a screenshot from the callstack when the callback spi_cb_done() breakpoint is triggered. You can see this callback is called within the interrupt context, in this case triggered by the DMA interrupt. With interrupts (or DMA) enabled, starting a SPI transfer will immediately trigger the TX interrupt to start filling the FIFOs from the TX buffers. Much of the driver is managed in an ISR, which preempts spi_transceive_cb(). The callback is also called within the ISR in the interrupt context. So depending on the length of the SPI transfer and what else is executing in the app, the callback could be called before the transceive API completes. To me, there is no requirement for spi_transceive_cb() that it must complete and return before the callback executes.

Since this does not appear to be a bug or an issue with the driver, I am converting this to a Discussion. If you have further questions, we can discuss further in that Discussion. Best regards

[decsny]

Derek is correct here that the API is not guaranteed to return before getting the call back, this just came up in #86900 also, cc @teburd

[badevos]

Whether spi_transceive_cb is ~ or is not ~ asynchronous, is irrelevant in my opinion. Activating CONFIG_SPI_ASYNC implies that the function is asynchronous. Anyhow our application requires an asynchronous implementation. Is there another async function call to use?

Anyhow we need a solution as our application requires quite some functionality in ISR context as well, including the launch of an SPI transfer.

Would it be possible to reconsider this given the fact that our application uses 'single' transfers only. I mean:

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

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

The argument tx_bufs to the call has it's member count set to 1, resulting in contiguous memory to be transferred by DMA. This might be easier to implement. A simple check on having a single buffer can then use an optimized implementation.

I understand that it would be a short-cut, but it will drastically improve the performance (given single transfers) of the system, which will be appreciated by everyone.

Can this be implemented please?

[decsny]

Whether spi_transceive_cb is ~ or is not ~ asynchronous, is irrelevant in my opinion. Activating CONFIG_SPI_ASYNC implies that the function is asynchronous. Anyhow our application requires an asynchronous implementation. Is there another async function call to use?

The API is not guaranteed to return before getting the notification. See discussion with maintainers and collaborators on #86900. It is possible for the calling thread to be preempted and waiting until the notification (which happens in IRQ context) happens. If you don't want it to happen this way then you need to change your application and system design so that either the thread calling the spi_transceive is a higher priority and/or the interrupt for the spi is disabled or locked until after you have exited the call.

Anyhow we need a solution as our application requires quite some functionality in ISR context as well, including the launch of an SPI transfer. Would it be possible to reconsider this given the fact that our application uses 'single' transfers only.

A solution to what exactly? And reconsider what?

The argument tx_bufs to the call has it's member count set to 1, resulting in contiguous memory to be transferred by DMA. This might be easier to implement. A simple check on having a single buffer can then use an optimized implementation. I understand that it would be a short-cut, but it will drastically improve the performance (given single transfers) of the system, which will be appreciated by everyone.

What is the "optimized implementation" that you are talking about? What you're saying is vague and hand-wavey. Have you looked at the current implementation? It already seems like it will be optimal if you transfer only one buffer because it transfers one buffer at a time. I don't see what improvement you want to do.

Can this be implemented please?

If you think you can optimize the driver in some way that is helping your application then you are free to do so, it is open source. If you want someone else to do the work for you, then you are free to specify it in a github enhancement request ticket following the template, but it needs to be a real request with clear context, reasoning, and specific technical requirement, not just a "just optimize the driver, should be easy to implement".

[teburd]

Whether spi_transceive_cb is ~ or is not ~ asynchronous, is irrelevant in my opinion. Activating CONFIG_SPI_ASYNC implies that the function is asynchronous. Anyhow our application requires an asynchronous implementation. Is there another async function call to use?

This isn't at all guaranteed to be asynchronous, and the updated docs reflect this reality. The way it was implemented unfortunately still requires serializing access to the spi bus through a semaphore. The call may block while ongoing transfers from other threads are taking place. It may very likely return after the callback takes place as well... making it difficult to chain SPI requests together in a callback driven state machine for multiple reasons.

[badevos]

@decsny I agree with me being a bit vague in my requests.

My original question was:

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?

The answer seems to be that I have the wrong expectation and that spi_transceive_cb is not necessarily asynchronous. I need to digest this further.

Thanks @decsny, @teburd and @DerekSnell for the analysis and feedback so far.

[badevos]

Alternatively we can consider using RTIO
What is the status of this feature on the RW612?

[badevos]

Since this uses the principle of a worker queue underneath ~ and thus involves a context switch ~ this is not our primary path.

[teburd]

Only with a fallback implementation does it use a worker queue. In the native implementation it treats the driver as an event driven state machine that can be given work (i/o) to do from any call context, and in the ideal implementation may only require one context swap on a DMA completion event. It is truly asynchronous though and behaves as such.

If you want this implemented natively by a vendor then that is something you would need to talk to the vendor about.