I2S SAI DMA stops when system gets under load

[Sagre]

Hello together,

we are streaming Audio on a MIMXRT1061 with SAI2 and DMA (using i2s_mcux_sai and therefore dma_mcux_edma), using Zephyr 4.1.0.

However, during a stream when the system gets under load due to additional activites, unrelated to audio, the stream suddenly stops. I could trace that down to dma_mcux_edma_reload checking for the TCD ids and having a matching TCD id for the last and current active TCD. However, I am at loss how this could be caused. Using debugger and logging I verified that no call to stop or suspend the DMA was made, so it somehow stopped "itself"?

Any help is appreciated in order to track that down. These are the last logs, that are produced by i2s_mcux_sai and dma_mcux_edma.
What I see is:

• A DMA interrupt performing no reload at 00:23:597:869. Afterwards the first "Transfer Stop" log is happening. Dont know if that is relevant.
• Multiple Occurences of "Transfer Stop" or "Last Transfer" logs. In multiple runs this is not consistent in what order or how many of these loggs appear.
• It seems to be timing related, the action that increases the load on the system only causes a stream stop in 80% of the cases.

Any help is appreciated to track that down

[00:00:23.512,512] <dbg> dma_mcux_edma: dma_mcux_edma_irq_handler: IRQ OCCURRED
[00:00:23.512,603] <dbg> dma_mcux_edma: nxp_edma_callback: transfer 0
[00:00:23.512,664] <dbg> dev_i2s_mcux: i2s_dma_tx_callback: tx cb
[00:00:23.512,817] <dbg> dma_mcux_edma: dma_mcux_edma_reload: Manu stop
[00:00:23.512,847] <dbg> dma_mcux_edma: dma_mcux_edma_reload: w_idx:3 no:1(ch:3)
[00:00:23.512,939] <dbg> dma_mcux_edma: dma_mcux_edma_irq_handler: IRQ DONE
[00:00:23.518,218] <dbg> dev_i2s_mcux: i2s_mcux_write: i2s_mcux_write
[00:00:23.533,782] <dbg> dma_mcux_edma: dma_mcux_edma_irq_handler: IRQ OCCURRED
[00:00:23.533,813] <dbg> dma_mcux_edma: nxp_edma_callback: transfer 0
[00:00:23.533,874] <dbg> dev_i2s_mcux: i2s_dma_tx_callback: tx cb
[00:00:23.534,027] <dbg> dma_mcux_edma: dma_mcux_edma_reload: Manu stop
[00:00:23.534,057] <dbg> dma_mcux_edma: dma_mcux_edma_reload: w_idx:0 no:1(ch:3)
[00:00:23.534,118] <dbg> dma_mcux_edma: dma_mcux_edma_irq_handler: IRQ DONE
[00:00:23.539,581] <dbg> dev_i2s_mcux: i2s_mcux_write: i2s_mcux_write
[00:00:23.593,231] <dbg> dma_mcux_edma: dma_mcux_edma_irq_handler: IRQ OCCURRED
[00:00:23.593,261] <dbg> dma_mcux_edma: nxp_edma_callback: transfer 0
[00:00:23.593,322] <dbg> dev_i2s_mcux: i2s_dma_tx_callback: tx cb
[00:00:23.593,444] <dbg> dma_mcux_edma: dma_mcux_edma_reload: Last transfer.
[00:00:23.593,475] <dbg> dma_mcux_edma: dma_mcux_edma_reload: Manu stop
[00:00:23.593,475] <dbg> dma_mcux_edma: dma_mcux_edma_reload: w_idx:1 no:1(ch:3)
[00:00:23.593,566] <dbg> dma_mcux_edma: dma_mcux_edma_irq_handler: IRQ DONE
[00:00:23.597,869] <dbg> dma_mcux_edma: dma_mcux_edma_irq_handler: IRQ OCCURRED
[00:00:23.597,900] <dbg> dma_mcux_edma: nxp_edma_callback: transfer 0
[00:00:23.597,930] <dbg> dev_i2s_mcux: i2s_dma_tx_callback: tx cb
[00:00:23.598,022] <dbg> dma_mcux_edma: dma_mcux_edma_irq_handler: IRQ DONE
[00:00:23.604,583] <dbg> dev_i2s_mcux: i2s_mcux_write: i2s_mcux_write
[00:00:23.609,039] <dbg> dev_i2s_mcux: i2s_mcux_write: i2s_mcux_write
[00:00:23.619,232] <dbg> dma_mcux_edma: dma_mcux_edma_irq_handler: IRQ OCCURRED
[00:00:23.619,323] <dbg> dma_mcux_edma: nxp_edma_callback: transfer 0
[00:00:23.619,354] <dbg> dev_i2s_mcux: i2s_dma_tx_callback: tx cb
[00:00:23.619,476] <dbg> dma_mcux_edma: dma_mcux_edma_reload: Transfer done,auto stop
[00:00:23.619,537] <dbg> dma_mcux_edma: dma_mcux_edma_reload: w_idx:2 no:2(ch:3)
[00:00:23.619,598] <dbg> dma_mcux_edma: dma_mcux_edma_reload: Last transfer.
[00:00:23.619,628] <dbg> dma_mcux_edma: dma_mcux_edma_reload: Manu stop
[00:00:23.619,659] <dbg> dma_mcux_edma: dma_mcux_edma_reload: w_idx:3 no:1(ch:3)
[00:00:23.619,720] <dbg> dma_mcux_edma: dma_mcux_edma_irq_handler: IRQ DONE
[00:00:23.625,213] <dbg> dev_i2s_mcux: i2s_mcux_write: i2s_mcux_write
[00:00:23.640,563] <dbg> dma_mcux_edma: dma_mcux_edma_irq_handler: IRQ OCCURRED
[00:00:23.640,686] <dbg> dma_mcux_edma: nxp_edma_callback: transfer 0
[00:00:23.640,747] <dbg> dev_i2s_mcux: i2s_dma_tx_callback: tx cb
[00:00:23.640,899] <dbg> dma_mcux_edma: dma_mcux_edma_reload: Last transfer.
[00:00:23.640,930] <dbg> dma_mcux_edma: dma_mcux_edma_reload: Manu stop
[00:00:23.640,960] <dbg> dma_mcux_edma: dma_mcux_edma_reload: w_idx:0 no:1(ch:3)
[00:00:23.641,052] <dbg> dma_mcux_edma: dma_mcux_edma_irq_handler: IRQ DONE
[00:00:23.646,301] <dbg> dev_i2s_mcux: i2s_mcux_write: i2s_mcux_write
[00:00:23.662,048] <dbg> dma_mcux_edma: dma_mcux_edma_irq_handler: IRQ OCCURRED
[00:00:23.662,109] <dbg> dma_mcux_edma: nxp_edma_callback: transfer 0
[00:00:23.662,139] <dbg> dev_i2s_mcux: i2s_dma_tx_callback: tx cb
[00:00:23.662,261] <dbg> dma_mcux_edma: dma_mcux_edma_reload: Last transfer.
[00:00:23.662,292] <dbg> dma_mcux_edma: dma_mcux_edma_reload: Manu stop
[00:00:23.662,292] <dbg> dma_mcux_edma: dma_mcux_edma_reload: w_idx:1 no:1(ch:3)
[00:00:23.662,384] <dbg> dma_mcux_edma: dma_mcux_edma_irq_handler: IRQ DONE
[00:00:23.719,238] <dbg> dma_mcux_edma: dma_mcux_edma_irq_handler: IRQ OCCURRED
[00:00:23.719,268] <dbg> dma_mcux_edma: nxp_edma_callback: transfer 0
[00:00:23.719,299] <dbg> dev_i2s_mcux: i2s_dma_tx_callback: tx cb
[00:00:23.719,360] <dbg> dma_mcux_edma: dma_mcux_edma_irq_handler: IRQ DONE
[00:00:23.729,064] <dbg> dev_i2s_mcux: i2s_mcux_write: i2s_mcux_write
[00:00:23.734,130] <dbg> dev_i2s_mcux: i2s_mcux_write: i2s_mcux_write

[DerekSnell]

Hi @Sagre ,
Thank you for reporting this. NXP uses the i2s_speed test for testing this driver. If you are able to modify that test on the MIMXRT1060-EVK so others can replicate the issue, that may help others to investigate this.

Thanks

[Raymond0225]

@Sagre Could you give more information on "the action increase the load on the system"? what kind of actions? More CPU consuming tasks or interrupts? so we can try replicate this issue on test app.