-
Notifications
You must be signed in to change notification settings - Fork 7.7k
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
base: main
Are you sure you want to change the base?
tests: spi_loopback: nxp_lpspi: Increase latency acceptance for DMA #92862
Conversation
There was a problem hiding this 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!
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. |
@decsny on my board testing for mximrt1180 and frdm_ke17z, I see the same issue
other cases are OK.
|
@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:
could this be |
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>
18a0c68
to
7c5272b
Compare
@hakehuang i took a different approach by putting it as default so it isnt having to be changed per test case |
|
There was a problem hiding this 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
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