CI:adc_dma:frdm_k64f: adc_read return EBUSY in repeat_sample test

[hakehuang]

This issue list is only for bugs in the main Zephyr code base
(https://github.com/zephyrproject-rtos/zephyr/). If the bug is for a project
fork (such as NCS) specific feature, please open an issue in the fork project
instead.

Describe the bug
frdm_k64f: adc_read return EBUSY in repeat_sample test

Please also mention any information which could help others to understand
the problem you're facing:

• What target platform are you using?
  FRDM_K64F
• What have you tried to diagnose or workaround this issue?
  change the HW_TRIGGER_INTERVAL to 4.
  do not use PICO lib
• Is this a regression? If yes, have you been able to "git bisect" it to a
  specific commit?
  there is low rate to such issue before 3.4.0, but it is high in 3.4.0, git bisect can not find a related code change
• ...

To Reproduce
Steps to reproduce the behavior:

1. west build -b frdm_k64f
2. west flash
3. See error

Expected behavior
test PASS

Impact
adc repeat sampling

Logs and console output

*** Booting Zephyr OS build v3.4.0-rc1-24-g5f5b34793dc8 ***
Running TESTSUITE adc_dma
===================================================================
START - test_adc_asynchronous_call
Samples read: 0x0371 0x0371 0x01fc 0x022e 0x0371 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 
 PASS - test_adc_asynchronous_call in 0.024 seconds
===================================================================
START - test_adc_invalid_request
E: Invalid resolution
E: Invalid resolution
Samples read: 0x0034 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 
 PASS - test_adc_invalid_request in 0.029 seconds
===================================================================
START - test_adc_repeated_samplings
repeated_samplings_callback: done 1
Samples read: 0x0373 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 
repeated_samplings_callback: done 2
Samples read: 0x0373 0x0080 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 
repeated_samplings_callback: done 3
Samples read: 0x0373 0x02d8 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 
repeated_samplings_callback: done 4
Samples read: 0x0373 0x036f 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 
repeated_samplings_callback: done 5
Samples read: 0x0373 0x0371 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 
repeated_samplings_callback: done 6
Samples read: 0x0373 0x027d 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 
repeated_samplings_callback: done 7
Samples read: 0x0373 0x0373 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 
repeated_samplings_callback: done 8
Samples read: 0x0373 0x01dd 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 
repeated_samplings_callback: done 9
Samples read: 0x0373 0x036f 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 
repeated_samplings_callback: done 10
Samples read: 0x0373 0x036f 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 

    Assertion failed at WEST_TOPDIR/zephyr/tests/drivers/adc/adc_dma/src/test_adc.c:469: test_task_repeated_samplings: (ret not equal to 0)
adc_read() failed with code -16
 FAIL - test_adc_repeated_samplings in 0.017 seconds
===================================================================
START - test_adc_sample_one_channel

Samples read: 0x036f 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 
 PASS - test_adc_sample_one_channel in 0.025 seconds
===================================================================
START - test_adc_sample_two_channels
 SKIP - test_adc_sample_two_channels in 0.001 seconds
===================================================================
START - test_adc_sample_with_interval
Samples read: 0x0371 0x036f 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 0xffff8000 
0xffff8000 0xffff8000 0xffff8000 
 PASS - test_adc_sample_with_interval in 0.225 seconds
===================================================================
TESTSUITE adc_dma failed.

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

SUITE FAIL -  80.00% [adc_dma]: pass = 4, fail = 1, skip = 1, total = 6 duration = 0.321 seconds
 - PASS - [adc_dma.test_adc_asynchronous_call] duration = 0.024 seconds
 - PASS - [adc_dma.test_adc_invalid_request] duration = 0.029 seconds
 - FAIL - [adc_dma.test_adc_repeated_samplings] duration = 0.017 seconds
 - PASS - [adc_dma.test_adc_sample_one_channel] duration = 0.025 seconds
 - SKIP - [adc_dma.test_adc_sample_two_channels] duration = 0.001 seconds
 - PASS - [adc_dma.test_adc_sample_with_interval] duration = 0.225 seconds

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

===================================================================
PROJECT EXECUTION FAILED

Environment (please complete the following information):

• OS: (e.g. Linux)
• Toolchain (e.g Zephyr SDK, ...)
• Commit SHA or Version used: v3.4.0-rc1-24-g5f5b34793dc8

[hakehuang]

@dleach02 , @yvanderv
I find below code change for test can resolve this issue

--- a/tests/drivers/adc/adc_dma/src/test_adc.c
+++ b/tests/drivers/adc/adc_dma/src/test_adc.c
@@ -23,7 +23,7 @@
 #define ADC_ACQUISITION_TIME ADC_ACQ_TIME_DEFAULT
 #define ADC_1ST_CHANNEL_ID 26
 #define COUNTER_NODE_NAME pit0
-#define HW_TRIGGER_INTERVAL (2U)
+#define HW_TRIGGER_INTERVAL (4U)
 #define SAMPLE_INTERVAL_US HW_TRIGGER_INTERVAL

 #elif defined(CONFIG_BOARD_FRDM_K82F)

and this only happens on frdm_k64f

[danieldegrasse]

@hakehuang I do not believe we should be setting SAMPLE_INTERVAL_US to such a low value: The MK64 SOC has a worst case rating of 37ksps in 16 bit mode:

A sample interval of 2us will result in a necessary conversion rate of 500ksps, which is not possible in 16 bit mode. Futhermore, with the default SYSTICK timer source and CONFIG_SYS_CLOCK_TICKS_PER_SEC=10000, theoretical best case kernel timer interval that the ADC context subsystem can achieve is ~100us.

Prior to PR #56104, the sampling interval for the K64 would have been 10000us. This is easily achievable with the ADC. On my board, the ADC can sample within a 12us period:

I believe the intermittent nature of the failure is because the kernel timer will not usually fire within a 2us boundary, but in some cases it can fire close to that boundary, which allows the ADC context subsystem to detect that the ADC is failing to sample within an 2us period. You can see a case here where the kernel timer fires multiple times in quick succession (each toggle of the KERN_TIMER signal is the timer expiry, and BUSY_ERR indicates the context subsystem set the -EBUSY status):

Edit: after investigating this a bit further, I see no reason not to set the sampling interval to 0us. This will result in the ADC subsystem sampling as fast as possible without using a kernel timer. This avoids the pitfalls of using a short kernel timer, which may expire while the user's ADC callback is still running, and does not result in the next ADC sample starting until the prior one has completed.

[hakehuang]

Edit: after investigating this a bit further, I see no reason not to set the sampling interval to 0us. This will result in the ADC subsystem sampling as fast as possible without using a kernel timer. This avoids the pitfalls of using a short kernel timer, which may expire while the user's ADC callback is still running, and does not result in the next ADC sample starting until the prior one has completed.

@danieldegrasse , the concern here is that, for a real user case, they always expect to have fix sampled value so that the following FFT algorithm can works well, and I set it to 2US is because 500K sample rates is a typical one when we do auido noise reducing, the adc will record the micophone output and use the recorded data compare with the earphone inputs, such as user own voice will be removed from earphone. so l suggest to keep the interval, and maybe we can change to a small one.

[danieldegrasse]

@hakehuang I understand for an use case like an FFT where the user might want to sample at a fixed interval the 2US timeout would make sense, but achieving this timeout with the current driver and test has a few issues:

In the below diagrams, each signal has the following meaning:

DMA	High when DMA transfer starts, low when completed
ADC_CALLBACK	High when `repeat_samplings_callback` is entered, low when exit
KER_TIMER	toggles each time the ADC context kernel timer callback is called

1. The test itself will not allow for such a short kernel timeout. I've used a signal analyzer to track some key timings in the repeated_samplings test, and the callback takes roughly 27 ms to execute. This means the sample is only actually triggered every 27 ms.

2. In the best case, the DMA takes ~14us to execute (this can be improved to about 4us by increasing the relative priority of the EDMA interrupt). This maps to a sampling rate of ~71ksps, which fits well into the range of ADC sample rates possible on this SOC. Note- the datasheet suggests that a sample rate of 500ksps is not possible in 16 bit mode, so a 2us sample timeout does not seem achievable
   

3. Even if the test's callback is reworked to eliminate the 27ms delay, the samples still do not complete within a 2us boundary:
   

Here we see that the kernel timer is expiring within 28us, which is still not the requested 2us (it does not seem this interval is not possible given the rate the system timer runs at). We do see that the kernel timer expires while a DMA sample is executing, and this run of the test failed as expected.

If we increase the kernel timer interval to 30us (and reconfigure CONFIG_SYS_CLOCK_TICKS_PER_SEC to support this reduced timeout interval) the ADC can sample within this interval and the test passes In this case I have reconfigured interrupt priorities to give the EDMA increased priority, resulting in a sample interval of around 4us.

If we want to take full advantage of the ADC here, I think we need to implement the adc_context_enable_timer, and utilize a hardware timer for our trigger interval. The kernel timer is simply not fast enough to support a consistent interval under 100us, without some significant reconfiguration. Beyond this, we would need to rework the callback in the test to avoid the 27ms delay, as with this the ADC is not really being sampled quickly at all.

[hakehuang]

@danieldegrasse fully agree with your judgement, for now I would suggest we can just enlarge the HW_TRIGGER_INTERVAL to a reasonable value, and create a PR to improve, what do you think?
also to clarify the adc trigger source, it is the pit0 as the trigger source, the trigger interval is controlled by HW_TRIGGER_INTERVAL. the problem here is both the kernel_timer and hw trigger interval is too margin(but it is OK in zephyr-v3.3.0-4123-gd01780fc9403). the hw trigger interval will sample adc, and update its buffer, and the kernel_timer will trigger a dma read to the adc buffer.

[danieldegrasse]

the hw trigger interval will sample adc, and update its buffer, and the kernel_timer will trigger a dma read to the adc buffer.

Thanks for the clarification here about when the ADC will actually sample- I was under the impression a sample would not occur until the DMA engine was started. I will update the linked PR to increase HW_TRIGGER_INTERVAL, so that the PIT0 timer only fires every 30ms. This way the PIT0 trigger will only occur as often as the kernel timer can trigger, so the test will still be validating support for triggered sampling.