Skip to content

tests: spi_loopback: nxp_lpspi: Increase latency acceptance for DMA #92862

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 1 commit into
base: main
Choose a base branch
from

Conversation

decsny
Copy link
Member

@decsny decsny commented Jul 8, 2025

The DMA-based LPSPI driver is inherently going to have a high latency due to the requirement for setting up the DMA transfer and the actual DMA driver may be extremely bloated, this is no fault of the spi driver and not relevant to the test. The driver we want to test for latency is the CPU-based one, the DMA-based one is more prioritizing bandwidth over latency.

Fixes #92492

@decsny decsny requested review from hakehuang and DerekSnell July 8, 2025 19:37
@github-actions github-actions bot added the area: SPI SPI bus label Jul 8, 2025
@github-actions github-actions bot requested review from tbursztyka and teburd July 8, 2025 19:38
@decsny decsny added this to the v4.2.0 milestone Jul 8, 2025
@decsny decsny added Trivial Changes that can be reviewed by anyone, i.e. doc changes, minor build system tweaks, etc. size: XS A PR changing only a single line of code labels Jul 8, 2025
teburd
teburd previously approved these changes Jul 8, 2025
Copy link
Contributor

@teburd teburd left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There's definitely a cost to need to program the DMA indirectly with the DMA API. And that's not great in cases like this to be frank.

In some cases maybe that API makes sense, but in many cases I've become more skeptical not less over time. It's maybe too low level and the behavior varies greatly for applications. It's maybe too high level and indirect for drivers.

At least in one case I added a Kconfig threshold for when to use DMA for a transfer.

The actual hardware NXP has for this stuff is quite nice and easy to use from my experience elsewhere.

File an RFC and we can discuss in the architecture meeting about what to do if you want. I'm open to it, really!

@decsny
Copy link
Member Author

decsny commented Jul 8, 2025

The actual hardware NXP has for this stuff is quite nice and easy to use from my experience elsewhere.

Part of the problem for this particular driver right now is that it is not optimized by using scatter-gather mode of edma, which would save a lot of time and hiccups since right now it's having to stop in the middle of the transfer to reprogram over and over. It's just nobody has got around to that yet. To be honest, this measurement causing the test fail right now might not actually be a result of a high "latency" but more precisely, a low bandwidth for a small transfer. Perhaps making the test send a larger buffer would make more sense in order to rule out issues with bandwidth in general.

@hakehuang
Copy link
Contributor

hakehuang commented Jul 9, 2025

@decsny on my board testing for mximrt1180 and frdm_ke17z, I see the same issue

 - FLAKY - [spi_loopback.test_spi_complete_multiple_timed] - (Failed 1 of 2 attempts) - duration = 0.031 seconds

other cases are OK.

*** Booting Zephyr OS build v4.2.0-rc2-1-g18a0c68d88ac ***
SPI test on buffers TX/RX 0x200044c0/0x200044a0, frame size = 8, DMA enabled (without CONFIG_NOCACHE_MEMORY)
Polling...Running TESTSUITE spi_extra_api_features
===================================================================
START - test_spi_hold_on_cs
E: SPI CS hold on feature is not supported on this platform.
SPI hold on CS not supported SKIP - test_spi_hold_on_cs in 0.009 seconds
===================================================================
START - test_spi_lock_release
 PASS - test_spi_lock_release in 0.002 seconds
===================================================================
TESTSUITE spi_extra_api_features succeeded
Running TESTSUITE spi_extra_api_features
===================================================================
START - test_spi_hold_on_cs
E: SPI CS hold on feature is not supported on this platform.
SPI hold on CS not supported SKIP - test_spi_hold_on_cs in 0.009 seconds
===================================================================
START - test_spi_lock_release
 PASS - test_spi_lock_release in 0.002 seconds
===================================================================
TESTSUITE spi_extra_api_features succeeded
Running TESTSUITE spi_loopback
===================================================================
Testing loopback spec: SLOW
START - test_nop_nil_bufs
 PASS - test_nop_nil_bufs in 0.001 seconds
===================================================================
START - test_spi_async_call
 PASS - test_spi_async_call in 0.172 seconds
===================================================================
START - test_spi_complete_large_transfers
 PASS - test_spi_complete_large_transfers in 0.170 seconds
===================================================================
START - test_spi_complete_loop_mode_0
 PASS - test_spi_complete_loop_mode_0 in 0.002 seconds
===================================================================
START - test_spi_complete_loop_mode_1
 PASS - test_spi_complete_loop_mode_1 in 0.002 seconds
===================================================================
START - test_spi_complete_loop_mode_2
 PASS - test_spi_complete_loop_mode_2 in 0.002 seconds
===================================================================
START - test_spi_complete_loop_mode_3
 PASS - test_spi_complete_loop_mode_3 in 0.002 seconds
===================================================================
START - test_spi_complete_multiple
 PASS - test_spi_complete_multiple in 0.002 seconds
===================================================================
START - test_spi_complete_multiple_timed
Transfer took 1435 us vs theoretical minimum 864 us
Latency measurement: 571 us
 PASS - test_spi_complete_multiple_timed in 0.009 seconds
===================================================================
START - test_spi_concurrent_transfer_different_spec
 PASS - test_spi_concurrent_transfer_different_spec in 0.005 seconds
===================================================================
START - test_spi_concurrent_transfer_same_spec
 PASS - test_spi_concurrent_transfer_same_spec in 0.005 seconds
===================================================================
START - test_spi_deinit
  zephyr,user miso-gpios or mosi-gpios are not defined
 SKIP - test_spi_deinit in 0.006 seconds
===================================================================
START - test_spi_null_rx_buf_set
 PASS - test_spi_null_rx_buf_set in 0.001 seconds
===================================================================
START - test_spi_null_tx_buf
 PASS - test_spi_null_tx_buf in 0.001 seconds
===================================================================
START - test_spi_null_tx_buf_set
 PASS - test_spi_null_tx_buf_set in 0.001 seconds
===================================================================
START - test_spi_null_tx_rx_buf_set
 PASS - test_spi_null_tx_rx_buf_set in 0.001 seconds
===================================================================
START - test_spi_rx_bigger_than_tx
 PASS - test_spi_rx_bigger_than_tx in 0.001 seconds
===================================================================
START - test_spi_rx_every_4
 PASS - test_spi_rx_every_4 in 0.002 seconds
===================================================================
START - test_spi_rx_half_end
 PASS - test_spi_rx_half_end in 0.002 seconds
===================================================================
START - test_spi_rx_half_start
 PASS - test_spi_rx_half_start in 0.001 seconds
===================================================================
START - test_spi_same_buf_cmd
 PASS - test_spi_same_buf_cmd in 0.002 seconds
===================================================================
START - test_spi_word_size_16
 PASS - test_spi_word_size_16 in 0.002 seconds
===================================================================
START - test_spi_word_size_24
 PASS - test_spi_word_size_24 in 0.004 seconds
===================================================================
START - test_spi_word_size_32
 PASS - test_spi_word_size_32 in 0.005 seconds
===================================================================
START - test_spi_word_size_7
 PASS - test_spi_word_size_7 in 0.002 seconds
===================================================================
START - test_spi_word_size_9
 PASS - test_spi_word_size_9 in 0.002 seconds
===================================================================
START - test_spi_write_back
 PASS - test_spi_write_back in 0.002 seconds
===================================================================
TESTSUITE spi_loopback succeeded
Running TESTSUITE spi_loopback
===================================================================
Testing loopback spec: FAST
START - test_nop_nil_bufs
 PASS - test_nop_nil_bufs in 0.001 seconds
===================================================================
START - test_spi_async_call
 PASS - test_spi_async_call in 0.056 seconds
===================================================================
START - test_spi_complete_large_transfers
 PASS - test_spi_complete_large_transfers in 0.054 seconds
===================================================================
START - test_spi_complete_loop_mode_0
 PASS - test_spi_complete_loop_mode_0 in 0.001 seconds
===================================================================
START - test_spi_complete_loop_mode_1
 PASS - test_spi_complete_loop_mode_1 in 0.001 seconds
===================================================================
START - test_spi_complete_loop_mode_2
 PASS - test_spi_complete_loop_mode_2 in 0.001 seconds
===================================================================
START - test_spi_complete_loop_mode_3
 PASS - test_spi_complete_loop_mode_3 in 0.001 seconds
===================================================================
START - test_spi_complete_multiple
 PASS - test_spi_complete_multiple in 0.002 seconds
===================================================================
START - test_spi_complete_multiple_timed
Transfer took 758 us vs theoretical minimum 27 us
Latency measurement: 731 us

    Assertion failed at WEST_TOPDIR/zephyr/tests/drivers/spi/spi_loopback/src/spi.c:359: spi_loopback_test_spi_complete_multiple_timed: (time_spent_us <= expected_transfer_time_us * CONFIG_SPI_IDEAL_TRANSFER_DURATION_SCALING is false)
Very high latency
 FAIL - test_spi_complete_multiple_timed in 0.031 seconds
===================================================================
START - test_spi_concurrent_transfer_different_spec
 PASS - test_spi_concurrent_transfer_different_spec in 0.004 seconds
===================================================================
START - test_spi_concurrent_transfer_same_spec
 PASS - test_spi_concurrent_transfer_same_spec in 0.004 seconds
===================================================================
START - test_spi_deinit
  zephyr,user miso-gpios or mosi-gpios are not defined
 SKIP - test_spi_deinit in 0.006 seconds
===================================================================
START - test_spi_null_rx_buf_set
 PASS - test_spi_null_rx_buf_set in 0.001 seconds
===================================================================
START - test_spi_null_tx_buf
 PASS - test_spi_null_tx_buf in 0.001 seconds
===================================================================
START - test_spi_null_tx_buf_set
 PASS - test_spi_null_tx_buf_set in 0.001 seconds
===================================================================
START - test_spi_null_tx_rx_buf_set
 PASS - test_spi_null_tx_rx_buf_set in 0.001 seconds
===================================================================
START - test_spi_rx_bigger_than_tx
 PASS - test_spi_rx_bigger_than_tx in 0.001 seconds
===================================================================
START - test_spi_rx_every_4
 PASS - test_spi_rx_every_4 in 0.002 seconds
===================================================================
START - test_spi_rx_half_end
 PASS - test_spi_rx_half_end in 0.001 seconds
===================================================================
START - test_spi_rx_half_start
 PASS - test_spi_rx_half_start in 0.001 seconds
===================================================================
START - test_spi_same_buf_cmd
 PASS - test_spi_same_buf_cmd in 0.001 seconds
===================================================================
START - test_spi_word_size_16
 PASS - test_spi_word_size_16 in 0.001 seconds
===================================================================
START - test_spi_word_size_24
 PASS - test_spi_word_size_24 in 0.002 seconds
===================================================================
START - test_spi_word_size_32
 PASS - test_spi_word_size_32 in 0.002 seconds
===================================================================
START - test_spi_word_size_7
 PASS - test_spi_word_size_7 in 0.001 seconds
===================================================================
START - test_spi_word_size_9
 PASS - test_spi_word_size_9 in 0.001 seconds
===================================================================
START - test_spi_write_back
 PASS - test_spi_write_back in 0.001 seconds
===================================================================
TESTSUITE spi_loopback failed.

------ TESTSUITE SUMMARY START ------

SUITE PASS - 100.00% [spi_extra_api_features]: pass = 1, fail = 0, skip = 1, total = 2 duration = 0.011 seconds
 - SKIP - [spi_extra_api_features.test_spi_hold_on_cs] duration = 0.009 seconds
 - PASS - [spi_extra_api_features.test_spi_lock_release] duration = 0.002 seconds

SUITE FAIL -  96.15% [spi_loopback]: pass = 25, fail = 1, skip = 1, total = 27 duration = 0.429 seconds
 - PASS - [spi_loopback.test_nop_nil_bufs] duration = 0.001 seconds
 - PASS - [spi_loopback.test_spi_async_call] duration = 0.172 seconds
 - PASS - [spi_loopback.test_spi_complete_large_transfers] duration = 0.170 seconds
 - PASS - [spi_loopback.test_spi_complete_loop_mode_0] duration = 0.002 seconds
 - PASS - [spi_loopback.test_spi_complete_loop_mode_1] duration = 0.002 seconds
 - PASS - [spi_loopback.test_spi_complete_loop_mode_2] duration = 0.002 seconds
 - PASS - [spi_loopback.test_spi_complete_loop_mode_3] duration = 0.002 seconds
 - PASS - [spi_loopback.test_spi_complete_multiple] duration = 0.002 seconds
 - FLAKY - [spi_loopback.test_spi_complete_multiple_timed] - (Failed 1 of 2 attempts) - duration = 0.031 seconds
 - PASS - [spi_loopback.test_spi_concurrent_transfer_different_spec] duration = 0.005 seconds
 - PASS - [spi_loopback.test_spi_concurrent_transfer_same_spec] duration = 0.005 seconds
 - SKIP - [spi_loopback.test_spi_deinit] duration = 0.006 seconds
 - PASS - [spi_loopback.test_spi_null_rx_buf_set] duration = 0.001 seconds
 - PASS - [spi_loopback.test_spi_null_tx_buf] duration = 0.001 seconds
 - PASS - [spi_loopback.test_spi_null_tx_buf_set] duration = 0.001 seconds
 - PASS - [spi_loopback.test_spi_null_tx_rx_buf_set] duration = 0.001 seconds
 - PASS - [spi_loopback.test_spi_rx_bigger_than_tx] duration = 0.001 seconds
 - PASS - [spi_loopback.test_spi_rx_every_4] duration = 0.002 seconds
 - PASS - [spi_loopback.test_spi_rx_half_end] duration = 0.002 seconds
 - PASS - [spi_loopback.test_spi_rx_half_start] duration = 0.001 seconds
 - PASS - [spi_loopback.test_spi_same_buf_cmd] duration = 0.002 seconds
 - PASS - [spi_loopback.test_spi_word_size_16] duration = 0.002 seconds
 - PASS - [spi_loopback.test_spi_word_size_24] duration = 0.004 seconds
 - PASS - [spi_loopback.test_spi_word_size_32] duration = 0.005 seconds
 - PASS - [spi_loopback.test_spi_word_size_7] duration = 0.002 seconds
 - PASS - [spi_loopback.test_spi_word_size_9] duration = 0.002 seconds
 - PASS - [spi_loopback.test_spi_write_back] duration = 0.002 seconds

------ TESTSUITE SUMMARY END ------

===================================================================
RunID: bf41ea9b570a52e8afb5db2da7fd6909
PROJECT EXECUTION FAILED

@decsny
Copy link
Member Author

decsny commented Jul 9, 2025

@hakehuang the log you shared shows the time was 28x more than theoretical minimum, which is less than the 40 specified on this PR, and I am not seeing this fail, so probably you are running a different testcase which is not getting the config applied. Which testcase (from testcase.yaml) are you running ?

nashif
nashif previously approved these changes Jul 9, 2025
@nashif nashif assigned tbursztyka and unassigned tbursztyka Jul 9, 2025
@hakehuang
Copy link
Contributor

@hakehuang the log you shared shows the time was 28x more than theoretical minimum, which is less than the 40 specified on this PR, and I am not seeing this fail, so probably you are running a different testcase which is not getting the config applied. Which testcase (from testcase.yaml) are you running ?

the test case is tests/drivers/spi/spi_loopback/drivers.spi.loopback. the build command line is:

west build -b mimxrt1180_evk/mimxrt1189/cm33

could this be DMA enabled (without CONFIG_NOCACHE_MEMORY) we should test with NOCACHE?

The DMA-based LPSPI is inherently going to have a high latency due to
the requirement for setting up the DMA transfer and the DMA driver may
be extremely bloated, this is no fault of the spi driver and not
relevant to the test. The driver we want to test for latency is the
CPU-based one, the DMA-based one is more prioritizing bandwidth over
latency.

Signed-off-by: Declan Snyder <declan.snyder@nxp.com>
@decsny decsny dismissed stale reviews from nashif and teburd via 7c5272b July 15, 2025 14:33
@decsny decsny force-pushed the fix/lpspi_dma_latency_test branch from 18a0c68 to 7c5272b Compare July 15, 2025 14:33
@decsny decsny requested review from nashif and teburd July 15, 2025 14:33
@decsny
Copy link
Member Author

decsny commented Jul 15, 2025

@hakehuang i took a different approach by putting it as default so it isnt having to be changed per test case

Copy link

Copy link
Contributor

@hakehuang hakehuang left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

board testing on mimxrt1180_evk_cm33 pass

2025-07-16 09:27:48,370 - twister - DEBUG - DEVICE: �*** Booting Zephyr OS build v4.2.0-rc2-1-g7c5272b06a70 ***
2025-07-16 09:27:48,380 - twister - DEBUG - DEVICE: SPI test on buffers TX/RX 0x30004540/0x30004520, frame size = 8, DMA enabled (without CONFIG_NOCACHE_MEMORY)
2025-07-16 09:27:48,384 - twister - DEBUG - DEVICE: Polling...Running TESTSUITE spi_extra_api_features
2025-07-16 09:27:48,390 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,393 - twister - DEBUG - DEVICE: START - test_spi_hold_on_cs
2025-07-16 09:27:48,400 - twister - DEBUG - DEVICE: PASS - test_spi_hold_on_cs in 0.003 seconds
2025-07-16 09:27:48,406 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,409 - twister - DEBUG - DEVICE: START - test_spi_lock_release
2025-07-16 09:27:48,414 - twister - DEBUG - DEVICE: PASS - test_spi_lock_release in 0.002 seconds
2025-07-16 09:27:48,420 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,424 - twister - DEBUG - DEVICE: TESTSUITE spi_extra_api_features succeeded
2025-07-16 09:27:48,427 - twister - DEBUG - DEVICE: Running TESTSUITE spi_extra_api_features
2025-07-16 09:27:48,433 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,436 - twister - DEBUG - DEVICE: START - test_spi_hold_on_cs
2025-07-16 09:27:48,443 - twister - DEBUG - DEVICE: PASS - test_spi_hold_on_cs in 0.003 seconds
2025-07-16 09:27:48,449 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,451 - twister - DEBUG - DEVICE: START - test_spi_lock_release
2025-07-16 09:27:48,457 - twister - DEBUG - DEVICE: PASS - test_spi_lock_release in 0.002 seconds
2025-07-16 09:27:48,463 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,466 - twister - DEBUG - DEVICE: TESTSUITE spi_extra_api_features succeeded
2025-07-16 09:27:48,469 - twister - DEBUG - DEVICE: Running TESTSUITE spi_loopback
2025-07-16 09:27:48,475 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,478 - twister - DEBUG - DEVICE: Testing loopback spec: SLOW
2025-07-16 09:27:48,480 - twister - DEBUG - DEVICE: START - test_nop_nil_bufs
2025-07-16 09:27:48,484 - twister - DEBUG - DEVICE: PASS - test_nop_nil_bufs in 0.001 seconds
2025-07-16 09:27:48,490 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,493 - twister - DEBUG - DEVICE: START - test_spi_async_call
2025-07-16 09:27:48,655 - twister - DEBUG - DEVICE: PASS - test_spi_async_call in 0.159 seconds
2025-07-16 09:27:48,661 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,664 - twister - DEBUG - DEVICE: START - test_spi_complete_large_transfers
2025-07-16 09:27:48,826 - twister - DEBUG - DEVICE: PASS - test_spi_complete_large_transfers in 0.157 seconds
2025-07-16 09:27:48,832 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,835 - twister - DEBUG - DEVICE: START - test_spi_complete_loop_mode_0
2025-07-16 09:27:48,841 - twister - DEBUG - DEVICE: PASS - test_spi_complete_loop_mode_0 in 0.002 seconds
2025-07-16 09:27:48,847 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,850 - twister - DEBUG - DEVICE: START - test_spi_complete_loop_mode_1
2025-07-16 09:27:48,856 - twister - DEBUG - DEVICE: PASS - test_spi_complete_loop_mode_1 in 0.002 seconds
2025-07-16 09:27:48,862 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,866 - twister - DEBUG - DEVICE: START - test_spi_complete_loop_mode_2
2025-07-16 09:27:48,871 - twister - DEBUG - DEVICE: PASS - test_spi_complete_loop_mode_2 in 0.002 seconds
2025-07-16 09:27:48,877 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,881 - twister - DEBUG - DEVICE: START - test_spi_complete_loop_mode_3
2025-07-16 09:27:48,886 - twister - DEBUG - DEVICE: PASS - test_spi_complete_loop_mode_3 in 0.001 seconds
2025-07-16 09:27:48,892 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,896 - twister - DEBUG - DEVICE: START - test_spi_complete_multiple
2025-07-16 09:27:48,902 - twister - DEBUG - DEVICE: PASS - test_spi_complete_multiple in 0.003 seconds
2025-07-16 09:27:48,908 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,912 - twister - DEBUG - DEVICE: START - test_spi_complete_multiple_timed
2025-07-16 09:27:48,918 - twister - DEBUG - DEVICE: Transfer took 1407 us vs theoretical minimum 864 us
2025-07-16 09:27:48,920 - twister - DEBUG - DEVICE: Latency measurement: 543 us
2025-07-16 09:27:48,926 - twister - DEBUG - DEVICE: PASS - test_spi_complete_multiple_timed in 0.010 seconds
2025-07-16 09:27:48,932 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,936 - twister - DEBUG - DEVICE: START - test_spi_concurrent_transfer_different_spec
2025-07-16 09:27:48,945 - twister - DEBUG - DEVICE: PASS - test_spi_concurrent_transfer_different_spec in 0.004 seconds
2025-07-16 09:27:48,951 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,955 - twister - DEBUG - DEVICE: START - test_spi_concurrent_transfer_same_spec
2025-07-16 09:27:48,964 - twister - DEBUG - DEVICE: PASS - test_spi_concurrent_transfer_same_spec in 0.004 seconds
2025-07-16 09:27:48,970 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,972 - twister - DEBUG - DEVICE: START - test_spi_deinit
2025-07-16 09:27:48,977 - twister - DEBUG - DEVICE: zephyr,user miso-gpios or mosi-gpios are not defined
2025-07-16 09:27:48,981 - twister - DEBUG - DEVICE: SKIP - test_spi_deinit in 0.005 seconds
2025-07-16 09:27:48,986 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:48,989 - twister - DEBUG - DEVICE: START - test_spi_null_rx_buf_set
2025-07-16 09:27:48,995 - twister - DEBUG - DEVICE: PASS - test_spi_null_rx_buf_set in 0.001 seconds
2025-07-16 09:27:49,001 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,003 - twister - DEBUG - DEVICE: START - test_spi_null_tx_buf
2025-07-16 09:27:49,008 - twister - DEBUG - DEVICE: PASS - test_spi_null_tx_buf in 0.001 seconds
2025-07-16 09:27:49,014 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,017 - twister - DEBUG - DEVICE: START - test_spi_null_tx_buf_set
2025-07-16 09:27:49,023 - twister - DEBUG - DEVICE: PASS - test_spi_null_tx_buf_set in 0.002 seconds
2025-07-16 09:27:49,029 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,032 - twister - DEBUG - DEVICE: START - test_spi_null_tx_rx_buf_set
2025-07-16 09:27:49,037 - twister - DEBUG - DEVICE: PASS - test_spi_null_tx_rx_buf_set in 0.001 seconds
2025-07-16 09:27:49,043 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,046 - twister - DEBUG - DEVICE: START - test_spi_rx_bigger_than_tx
2025-07-16 09:27:49,052 - twister - DEBUG - DEVICE: PASS - test_spi_rx_bigger_than_tx in 0.002 seconds
2025-07-16 09:27:49,058 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,060 - twister - DEBUG - DEVICE: START - test_spi_rx_every_4
2025-07-16 09:27:49,066 - twister - DEBUG - DEVICE: PASS - test_spi_rx_every_4 in 0.002 seconds
2025-07-16 09:27:49,071 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,074 - twister - DEBUG - DEVICE: START - test_spi_rx_half_end
2025-07-16 09:27:49,079 - twister - DEBUG - DEVICE: PASS - test_spi_rx_half_end in 0.002 seconds
2025-07-16 09:27:49,085 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,088 - twister - DEBUG - DEVICE: START - test_spi_rx_half_start
2025-07-16 09:27:49,093 - twister - DEBUG - DEVICE: PASS - test_spi_rx_half_start in 0.002 seconds
2025-07-16 09:27:49,099 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,102 - twister - DEBUG - DEVICE: START - test_spi_same_buf_cmd
2025-07-16 09:27:49,107 - twister - DEBUG - DEVICE: PASS - test_spi_same_buf_cmd in 0.002 seconds
2025-07-16 09:27:49,113 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,116 - twister - DEBUG - DEVICE: START - test_spi_word_size_16
2025-07-16 09:27:49,122 - twister - DEBUG - DEVICE: PASS - test_spi_word_size_16 in 0.002 seconds
2025-07-16 09:27:49,128 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,130 - twister - DEBUG - DEVICE: START - test_spi_word_size_24
2025-07-16 09:27:49,138 - twister - DEBUG - DEVICE: PASS - test_spi_word_size_24 in 0.004 seconds
2025-07-16 09:27:49,144 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,146 - twister - DEBUG - DEVICE: START - test_spi_word_size_32
2025-07-16 09:27:49,154 - twister - DEBUG - DEVICE: PASS - test_spi_word_size_32 in 0.004 seconds
2025-07-16 09:27:49,160 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,163 - twister - DEBUG - DEVICE: START - test_spi_word_size_7
2025-07-16 09:27:49,168 - twister - DEBUG - DEVICE: PASS - test_spi_word_size_7 in 0.002 seconds
2025-07-16 09:27:49,174 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,177 - twister - DEBUG - DEVICE: START - test_spi_word_size_9
2025-07-16 09:27:49,182 - twister - DEBUG - DEVICE: PASS - test_spi_word_size_9 in 0.002 seconds
2025-07-16 09:27:49,188 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,190 - twister - DEBUG - DEVICE: START - test_spi_write_back
2025-07-16 09:27:49,195 - twister - DEBUG - DEVICE: PASS - test_spi_write_back in 0.002 seconds
2025-07-16 09:27:49,201 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,204 - twister - DEBUG - DEVICE: TESTSUITE spi_loopback succeeded
2025-07-16 09:27:49,207 - twister - DEBUG - DEVICE: Running TESTSUITE spi_loopback
2025-07-16 09:27:49,213 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,215 - twister - DEBUG - DEVICE: Testing loopback spec: FAST
2025-07-16 09:27:49,218 - twister - DEBUG - DEVICE: START - test_nop_nil_bufs
2025-07-16 09:27:49,222 - twister - DEBUG - DEVICE: PASS - test_nop_nil_bufs in 0.001 seconds
2025-07-16 09:27:49,228 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,230 - twister - DEBUG - DEVICE: START - test_spi_async_call
2025-07-16 09:27:49,257 - twister - DEBUG - DEVICE: PASS - test_spi_async_call in 0.023 seconds
2025-07-16 09:27:49,263 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,266 - twister - DEBUG - DEVICE: START - test_spi_complete_large_transfers
2025-07-16 09:27:49,293 - twister - DEBUG - DEVICE: PASS - test_spi_complete_large_transfers in 0.022 seconds
2025-07-16 09:27:49,299 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,302 - twister - DEBUG - DEVICE: START - test_spi_complete_loop_mode_0
2025-07-16 09:27:49,308 - twister - DEBUG - DEVICE: PASS - test_spi_complete_loop_mode_0 in 0.001 seconds
2025-07-16 09:27:49,314 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,317 - twister - DEBUG - DEVICE: START - test_spi_complete_loop_mode_1
2025-07-16 09:27:49,323 - twister - DEBUG - DEVICE: PASS - test_spi_complete_loop_mode_1 in 0.001 seconds
2025-07-16 09:27:49,329 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,332 - twister - DEBUG - DEVICE: START - test_spi_complete_loop_mode_2
2025-07-16 09:27:49,338 - twister - DEBUG - DEVICE: PASS - test_spi_complete_loop_mode_2 in 0.001 seconds
2025-07-16 09:27:49,344 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,347 - twister - DEBUG - DEVICE: START - test_spi_complete_loop_mode_3
2025-07-16 09:27:49,353 - twister - DEBUG - DEVICE: PASS - test_spi_complete_loop_mode_3 in 0.001 seconds
2025-07-16 09:27:49,359 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,362 - twister - DEBUG - DEVICE: START - test_spi_complete_multiple
2025-07-16 09:27:49,368 - twister - DEBUG - DEVICE: PASS - test_spi_complete_multiple in 0.002 seconds
2025-07-16 09:27:49,374 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,377 - twister - DEBUG - DEVICE: START - test_spi_complete_multiple_timed
2025-07-16 09:27:49,383 - twister - DEBUG - DEVICE: Transfer took 685 us vs theoretical minimum 27 us
2025-07-16 09:27:49,385 - twister - DEBUG - DEVICE: Latency measurement: 658 us
2025-07-16 09:27:49,390 - twister - DEBUG - DEVICE: PASS - test_spi_complete_multiple_timed in 0.009 seconds
2025-07-16 09:27:49,396 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,401 - twister - DEBUG - DEVICE: START - test_spi_concurrent_transfer_different_spec
2025-07-16 09:27:49,409 - twister - DEBUG - DEVICE: PASS - test_spi_concurrent_transfer_different_spec in 0.002 seconds
2025-07-16 09:27:49,415 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,419 - twister - DEBUG - DEVICE: START - test_spi_concurrent_transfer_same_spec
2025-07-16 09:27:49,426 - twister - DEBUG - DEVICE: PASS - test_spi_concurrent_transfer_same_spec in 0.002 seconds
2025-07-16 09:27:49,432 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,434 - twister - DEBUG - DEVICE: START - test_spi_deinit
2025-07-16 09:27:49,439 - twister - DEBUG - DEVICE: zephyr,user miso-gpios or mosi-gpios are not defined
2025-07-16 09:27:49,443 - twister - DEBUG - DEVICE: SKIP - test_spi_deinit in 0.005 seconds
2025-07-16 09:27:49,449 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,451 - twister - DEBUG - DEVICE: START - test_spi_null_rx_buf_set
2025-07-16 09:27:49,456 - twister - DEBUG - DEVICE: PASS - test_spi_null_rx_buf_set in 0.001 seconds
2025-07-16 09:27:49,462 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,465 - twister - DEBUG - DEVICE: START - test_spi_null_tx_buf
2025-07-16 09:27:49,470 - twister - DEBUG - DEVICE: PASS - test_spi_null_tx_buf in 0.001 seconds
2025-07-16 09:27:49,476 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,479 - twister - DEBUG - DEVICE: START - test_spi_null_tx_buf_set
2025-07-16 09:27:49,484 - twister - DEBUG - DEVICE: PASS - test_spi_null_tx_buf_set in 0.001 seconds
2025-07-16 09:27:49,490 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,493 - twister - DEBUG - DEVICE: START - test_spi_null_tx_rx_buf_set
2025-07-16 09:27:49,498 - twister - DEBUG - DEVICE: PASS - test_spi_null_tx_rx_buf_set in 0.001 seconds
2025-07-16 09:27:49,504 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,507 - twister - DEBUG - DEVICE: START - test_spi_rx_bigger_than_tx
2025-07-16 09:27:49,512 - twister - DEBUG - DEVICE: PASS - test_spi_rx_bigger_than_tx in 0.001 seconds
2025-07-16 09:27:49,518 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,521 - twister - DEBUG - DEVICE: START - test_spi_rx_every_4
2025-07-16 09:27:49,526 - twister - DEBUG - DEVICE: PASS - test_spi_rx_every_4 in 0.002 seconds
2025-07-16 09:27:49,532 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,535 - twister - DEBUG - DEVICE: START - test_spi_rx_half_end
2025-07-16 09:27:49,540 - twister - DEBUG - DEVICE: PASS - test_spi_rx_half_end in 0.002 seconds
2025-07-16 09:27:49,546 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,549 - twister - DEBUG - DEVICE: START - test_spi_rx_half_start
2025-07-16 09:27:49,554 - twister - DEBUG - DEVICE: PASS - test_spi_rx_half_start in 0.002 seconds
2025-07-16 09:27:49,555 - twister - DEBUG - -- west flash: using runner linkserver
RUNNER - gdb_port = 3333, semih port = 8888
-- runners.linkserver: LinkServer: /usr/local/LinkServer/LinkServer, version v24.9.75

2025-07-16 09:27:49,560 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,563 - twister - DEBUG - DEVICE: START - test_spi_same_buf_cmd
2025-07-16 09:27:49,568 - twister - DEBUG - DEVICE: PASS - test_spi_same_buf_cmd in 0.001 seconds
2025-07-16 09:27:49,574 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,576 - twister - DEBUG - DEVICE: START - test_spi_word_size_16
2025-07-16 09:27:49,581 - twister - DEBUG - DEVICE: PASS - test_spi_word_size_16 in 0.001 seconds
2025-07-16 09:27:49,587 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,590 - twister - DEBUG - DEVICE: START - test_spi_word_size_24
2025-07-16 09:27:49,595 - twister - DEBUG - DEVICE: PASS - test_spi_word_size_24 in 0.001 seconds
2025-07-16 09:27:49,601 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,603 - twister - DEBUG - DEVICE: START - test_spi_word_size_32
2025-07-16 09:27:49,608 - twister - DEBUG - DEVICE: PASS - test_spi_word_size_32 in 0.001 seconds
2025-07-16 09:27:49,614 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,617 - twister - DEBUG - DEVICE: START - test_spi_word_size_7
2025-07-16 09:27:49,622 - twister - DEBUG - DEVICE: PASS - test_spi_word_size_7 in 0.001 seconds
2025-07-16 09:27:49,628 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,630 - twister - DEBUG - DEVICE: START - test_spi_word_size_9
2025-07-16 09:27:49,635 - twister - DEBUG - DEVICE: PASS - test_spi_word_size_9 in 0.001 seconds
2025-07-16 09:27:49,641 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,644 - twister - DEBUG - DEVICE: START - test_spi_write_back
2025-07-16 09:27:49,649 - twister - DEBUG - DEVICE: PASS - test_spi_write_back in 0.001 seconds
2025-07-16 09:27:49,655 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,657 - twister - DEBUG - DEVICE: TESTSUITE spi_loopback succeeded
2025-07-16 09:27:49,661 - twister - DEBUG - DEVICE: ------ TESTSUITE SUMMARY START ------
2025-07-16 09:27:49,671 - twister - DEBUG - DEVICE: SUITE PASS - 100.00% [spi_extra_api_features]: pass = 2, fail = 0, skip = 0, total = 2 duration = 0.005 seconds
2025-07-16 09:27:49,678 - twister - DEBUG - DEVICE: - PASS - [spi_extra_api_features.test_spi_hold_on_cs] duration = 0.003 seconds
2025-07-16 09:27:49,685 - twister - DEBUG - DEVICE: - PASS - [spi_extra_api_features.test_spi_lock_release] duration = 0.002 seconds
2025-07-16 09:27:49,695 - twister - DEBUG - DEVICE: SUITE PASS - 100.00% [spi_loopback]: pass = 26, fail = 0, skip = 1, total = 27 duration = 0.381 seconds
2025-07-16 09:27:49,701 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_nop_nil_bufs] duration = 0.001 seconds
2025-07-16 09:27:49,707 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_async_call] duration = 0.159 seconds
2025-07-16 09:27:49,714 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_complete_large_transfers] duration = 0.157 seconds
2025-07-16 09:27:49,721 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_complete_loop_mode_0] duration = 0.002 seconds
2025-07-16 09:27:49,728 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_complete_loop_mode_1] duration = 0.002 seconds
2025-07-16 09:27:49,735 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_complete_loop_mode_2] duration = 0.002 seconds
2025-07-16 09:27:49,742 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_complete_loop_mode_3] duration = 0.001 seconds
2025-07-16 09:27:49,749 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_complete_multiple] duration = 0.003 seconds
2025-07-16 09:27:49,756 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_complete_multiple_timed] duration = 0.010 seconds
2025-07-16 09:27:49,764 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_concurrent_transfer_different_spec] duration = 0.004 seconds
2025-07-16 09:27:49,772 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_concurrent_transfer_same_spec] duration = 0.004 seconds
2025-07-16 09:27:49,778 - twister - DEBUG - DEVICE: - SKIP - [spi_loopback.test_spi_deinit] duration = 0.005 seconds
2025-07-16 09:27:49,785 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_null_rx_buf_set] duration = 0.001 seconds
2025-07-16 09:27:49,791 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_null_tx_buf] duration = 0.001 seconds
2025-07-16 09:27:49,797 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_null_tx_buf_set] duration = 0.002 seconds
2025-07-16 09:27:49,804 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_null_tx_rx_buf_set] duration = 0.001 seconds
2025-07-16 09:27:49,811 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_rx_bigger_than_tx] duration = 0.002 seconds
2025-07-16 09:27:49,817 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_rx_every_4] duration = 0.002 seconds
2025-07-16 09:27:49,823 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_rx_half_end] duration = 0.002 seconds
2025-07-16 09:27:49,830 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_rx_half_start] duration = 0.002 seconds
2025-07-16 09:27:49,836 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_same_buf_cmd] duration = 0.002 seconds
2025-07-16 09:27:49,842 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_word_size_16] duration = 0.002 seconds
2025-07-16 09:27:49,849 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_word_size_24] duration = 0.004 seconds
2025-07-16 09:27:49,855 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_word_size_32] duration = 0.004 seconds
2025-07-16 09:27:49,861 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_word_size_7] duration = 0.002 seconds
2025-07-16 09:27:49,868 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_word_size_9] duration = 0.002 seconds
2025-07-16 09:27:49,874 - twister - DEBUG - DEVICE: - PASS - [spi_loopback.test_spi_write_back] duration = 0.002 seconds
2025-07-16 09:27:49,877 - twister - DEBUG - DEVICE: ------ TESTSUITE SUMMARY END ------
2025-07-16 09:27:49,883 - twister - DEBUG - DEVICE: ===================================================================
2025-07-16 09:27:49,887 - twister - DEBUG - DEVICE: RunID: 81c55444db1b5a0377e842578563564c
2025-07-16 09:27:49,889 - twister - DEBUG - DEVICE: PROJECT EXECUTION SUCCESSFUL

@danieldegrasse danieldegrasse removed this from the v4.2.0 milestone Jul 21, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area: SPI SPI bus size: XS A PR changing only a single line of code Trivial Changes that can be reviewed by anyone, i.e. doc changes, minor build system tweaks, etc.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

tests: tests/drivers/spi/spi_loopback: mimxrt1180_evk/mimxrt1189/cm33: failed: Failed harness:'Testsuite failed'
6 participants