I2S driver on IMXRT1170_EVK causes DMA error after latest changes related to eDMA

[RadekPolyend]

After latest changes in eDMA and related to this I2S MCUX SAI driver eDMA error handler is invoked after first reload of buffer.

Use case:

• two audio buffers in a slab
• both of them allocated and written before the trigger start
• after first buffer is freed it is allocated and written again than edma error occurs

This problem did not happen before the changes.

Breakpoint 3, i2s_mcux_write (dev=0x3002ba0c <__device_dts_ord_458>, mem_block=0x2000a568 <malloc_arena+2664>, size=2048)
at /home/radekp/projects/zephyrproject/zephyr/drivers/i2s/i2s_mcux_sai.c:1019
1019 {
(gdb) c
Continuing.

Breakpoint 3, i2s_mcux_write (dev=0x3002ba0c <__device_dts_ord_458>, mem_block=0x2000ad68 <malloc_arena+4712>, size=2048)
at /home/radekp/projects/zephyrproject/zephyr/drivers/i2s/i2s_mcux_sai.c:1019
1019 {
(gdb) c
Continuing.

Breakpoint 1, i2s_dma_tx_callback (dma_dev=0x3002b8b8 <__device_dts_ord_455>, arg=0x3002ba0c <__device_dts_ord_458>, channel=31, status=0)
at /home/radekp/projects/zephyrproject/zephyr/drivers/i2s/i2s_mcux_sai.c:261
261 {
(gdb) c
Continuing.

Breakpoint 3, i2s_mcux_write (dev=0x3002ba0c <__device_dts_ord_458>, mem_block=0x2000a568 <malloc_arena+2664>, size=2048)
at /home/radekp/projects/zephyrproject/zephyr/drivers/i2s/i2s_mcux_sai.c:1019
1019 {
(gdb) c
Continuing.

Breakpoint 1, i2s_dma_tx_callback (dma_dev=0x3002b8b8 <__device_dts_ord_455>, arg=0x3002ba0c <__device_dts_ord_458>, channel=31, status=0)
at /home/radekp/projects/zephyrproject/zephyr/drivers/i2s/i2s_mcux_sai.c:261
261 {
(gdb) c
Continuing.

Breakpoint 2, dma_mcux_edma_error_irq_handler (dev=0x3002b8b8 <__device_dts_ord_455>) at /home/radekp/projects/zephyrproject/zephyr/drivers/dma/dma_mcux_edma.c:258

(gdb) (gdb) p/x ((struct dma_mcux_edma_data*)dev->data)->data_cb[31]
$6 = {transferConfig = {srcAddr = 0x2000a568, destAddr = 0x40404020, srcTransferSize = 0x2, destTransferSize = 0x2, srcOffset = 0x4, destOffset = 0x0, minorLoopBytes = 0x4,
majorLoopCounts = 0x200}, edma_handle = {callback = 0x30027439, userData = 0x20002fe4, base = 0x40070000, tcdPool = 0x0, channel = 0x1f, header = 0x0, tail = 0x0, tcdUsed = 0x0,
tcdSize = 0x0, flags = 0x0}, dev = 0x3002b8b8, user_data = 0x3002ba0c, dma_callback = 0x30012d31, transfer_settings = {source_data_size = 0x4, dest_data_size = 0x4,
source_burst_length = 0x4, dest_burst_length = 0x4, direction = 0x1, transfer_type = 0x2, valid = 0x1, cyclic = 0x1, write_idx = 0x3, empty_tcds = 0x3}, busy = 0x1}

The situation does not happen when I revert 7145295. but the sound is glitchy.

[dleach02]

@Raymond0225, can you please look into this as it was bisected back to you change. Thanks

[Raymond0225]

@Raymond0225, can you please look into this as it was bisected back to you change. Thanks

sure, I am looking into this issue. Will get back later.

[Raymond0225]

After latest changes in eDMA and related to this I2S MCUX SAI driver eDMA error handler is invoked after first reload of buffer.

Use case:

• two audio buffers in a slab
• both of them allocated and written before the trigger start
• after first buffer is freed it is allocated and written again than edma error occurs

This problem did not happen before the changes.

Breakpoint 3, i2s_mcux_write (dev=0x3002ba0c <__device_dts_ord_458>, mem_block=0x2000a568 <malloc_arena+2664>, size=2048) at /home/radekp/projects/zephyrproject/zephyr/drivers/i2s/i2s_mcux_sai.c:1019 1019 { (gdb) c Continuing.

Breakpoint 3, i2s_mcux_write (dev=0x3002ba0c <__device_dts_ord_458>, mem_block=0x2000ad68 <malloc_arena+4712>, size=2048) at /home/radekp/projects/zephyrproject/zephyr/drivers/i2s/i2s_mcux_sai.c:1019 1019 { (gdb) c Continuing.

Breakpoint 1, i2s_dma_tx_callback (dma_dev=0x3002b8b8 <__device_dts_ord_455>, arg=0x3002ba0c <__device_dts_ord_458>, channel=31, status=0) at /home/radekp/projects/zephyrproject/zephyr/drivers/i2s/i2s_mcux_sai.c:261 261 { (gdb) c Continuing.

Breakpoint 3, i2s_mcux_write (dev=0x3002ba0c <__device_dts_ord_458>, mem_block=0x2000a568 <malloc_arena+2664>, size=2048) at /home/radekp/projects/zephyrproject/zephyr/drivers/i2s/i2s_mcux_sai.c:1019 1019 { (gdb) c Continuing.

Breakpoint 1, i2s_dma_tx_callback (dma_dev=0x3002b8b8 <__device_dts_ord_455>, arg=0x3002ba0c <__device_dts_ord_458>, channel=31, status=0) at /home/radekp/projects/zephyrproject/zephyr/drivers/i2s/i2s_mcux_sai.c:261 261 { (gdb) c Continuing.

Breakpoint 2, dma_mcux_edma_error_irq_handler (dev=0x3002b8b8 <__device_dts_ord_455>) at /home/radekp/projects/zephyrproject/zephyr/drivers/dma/dma_mcux_edma.c:258

(gdb) (gdb) p/x ((struct dma_mcux_edma_data*)dev->data)->data_cb[31] $6 = {transferConfig = {srcAddr = 0x2000a568, destAddr = 0x40404020, srcTransferSize = 0x2, destTransferSize = 0x2, srcOffset = 0x4, destOffset = 0x0, minorLoopBytes = 0x4, majorLoopCounts = 0x200}, edma_handle = {callback = 0x30027439, userData = 0x20002fe4, base = 0x40070000, tcdPool = 0x0, channel = 0x1f, header = 0x0, tail = 0x0, tcdUsed = 0x0, tcdSize = 0x0, flags = 0x0}, dev = 0x3002b8b8, user_data = 0x3002ba0c, dma_callback = 0x30012d31, transfer_settings = {source_data_size = 0x4, dest_data_size = 0x4, source_burst_length = 0x4, dest_burst_length = 0x4, direction = 0x1, transfer_type = 0x2, valid = 0x1, cyclic = 0x1, write_idx = 0x3, empty_tcds = 0x3}, busy = 0x1}

The situation does not happen when I revert 7145295. but the sound is glitchy.

thanks for your information.
I set up a test case based on your description and try to reproduce this issue. What I found is that when TX buffer is set to 2, TX procedure will be stopped because of no more TX blocks in i2s_dma_tx_callback function.
so I prepared a patch to fixed it.
2 TX buffers works fine with this patch. I share the patch and my test file as attached.

The test file is based on test_i2s_speed.c; I added another test case in this file: in this test case, I started a RX thread for reading while in the test main doing TX. To run the test added, #define I2S_SPEED_TEST_RUN_SPECIAL 1
one thing you need to know that: because of only 2 TX buffers, DMA transfer is so fast so there will be some short period of time without real data on the I2S, RX side may receive some dummy bits.
Let me know if it helps or not.
i2s_patch.patch

[Raymond0225]

speed_test.txt
.c file can't be uploaded, I rename it as *.txt

[RadekPolyend]

This patch does not work for me. The procedure should not be stopped because after first buffer is sent over dma the dma callback is invoked and buffer is returned the the pool. In the meantime when second buffer is sent a thread is unlocked on pool, takes the buffer and write it again. For me the buffer is 128b for 44,1k sampling therefore I have more than enough 3ms to deliver the second buffer. You can see in my debug logs that after first dma callback a write is done so the next buffer is there but after second dma callback the edma error occurs.

[Raymond0225]

I paste reference code here, it works fine on my side. There is a standalone RX thread. If you can provide you code, we can help to have a review and try.
Other things you need pay attention is:
a) Enable deferred logging mode: CONFIG_LOG_MODE_DEFERRED=y
b) Check the DMA channel used for RX and TX and ensure they are not used by other peripherals like UART/SPI

#define MY_STACK_SIZE 1024
#define MY_PRIORITY 0

K_THREAD_STACK_DEFINE(my_stack_area, MY_STACK_SIZE);
struct k_thread my_thread_data;
void my_entry_point(void *dev, void * p1, void *p2);

uint32_t g_for_comparing[SAMPLE_NO];

static void fill_special(int16_t *tx_block, int att)
{

memset(tx_block,att,SAMPLE_NO<<2);

}

static int verify_special(int16_t *buf, int att)
{
memset(g_for_comparing,att,sizeof(g_for_comparing));
return memcmp(g_for_comparing,buf,sizeof(g_for_comparing));

}

void my_entry_point(void dev, void * p1, void p2)
{
void rx_data_p;
int rx_idx = (int*)p1;
uint32_t rx_size;
int att = 0;
int ret;
struct k_sem* sem = (struct k_sem*)p2;
int first_unmatch = -1;
int unmatch_count = 0;

/* Start reception */
ret = i2s_trigger(dev_i2s_rx, I2S_DIR_RX, I2S_TRIGGER_START);
zassert_equal(ret, 0, "RX START trigger failed");

/* RX is ready */
k_sem_give(sem);


while(1)
{
	/* Read and verify*/
	ret = i2s_read(dev, &rx_data_p, &rx_size);
	if (ret)
	{
		/* All but one data block read, stop reception */
		ret = i2s_trigger(dev_i2s_rx, I2S_DIR_RX, I2S_TRIGGER_STOP);
		zassert_equal(ret, 0, "RX STOP trigger failed");
		// TC_PRINT("Trigger RX stop");
		break;
	}
	zassert_equal(rx_size, BLOCK_SIZE);
	if (verify_special(rx_data_p,att++))
	{
		unmatch_count++;
		if (unmatch_count == 1)
		{
			first_unmatch = att - 1;
		}
	}
	k_mem_slab_free(&rx_0_mem_slab, rx_data_p);
	(*rx_idx)++;
}

TC_PRINT("RX thread terminiated, umatch(%d/%d)\r\n",first_unmatch,unmatch_count);

}

ZTEST(drivers_i2s_speed_plus, test_i2s_transfer_special)
{

if (IS_ENABLED(CONFIG_I2S_TEST_USE_I2S_DIR_BOTH)) {
	TC_PRINT("RX/TX transfer requires use of I2S_DIR_BOTH.\n");
	ztest_test_skip();
	return;
}

void *tx_p;
int tx_idx = 0;
int rx_idx = 0;
int ret;
struct k_sem sem_init;

k_sem_init(&sem_init,0,1);

k_tid_t my_tid = k_thread_create(&my_thread_data, my_stack_area,
			K_THREAD_STACK_SIZEOF(my_stack_area),
			my_entry_point,
			(void*)dev_i2s_rx, &rx_idx, &sem_init,
			MY_PRIORITY, 0, K_NO_WAIT);

/* Prepare TX data blocks */
for (tx_idx = 0; tx_idx < MIN(NUM_BLOCKS,4); tx_idx++) {
	ret = k_mem_slab_alloc(&tx_0_mem_slab, &tx_p,
			       K_FOREVER);
	zassert_equal(ret, 0);
	fill_special((uint16_t *)tx_p, tx_idx);

	ret = i2s_write(dev_i2s_tx, tx_p, BLOCK_SIZE);
	zassert_equal(ret, 0);
}

/* Wait for RX is ready*/
k_sem_take(&sem_init,K_FOREVER);

/* Start transmission */
ret = i2s_trigger(dev_i2s_tx, I2S_DIR_TX, I2S_TRIGGER_START);
zassert_equal(ret, 0, "TX START trigger failed");

for (; tx_idx < 100; tx_idx++) {
	/* Wait for buffer available */
	void* tx_data_p;

	/* prepare for writing*/
	ret = k_mem_slab_alloc(&tx_0_mem_slab, &tx_data_p,
				K_FOREVER);
	zassert_equal(ret, 0);
	fill_special((uint16_t *)tx_data_p, tx_idx);

	/* Add random delay between 0-10ms */
	// k_msleep(rand()%10);
	ret = i2s_write(dev_i2s_tx, tx_data_p, BLOCK_SIZE);
	zassert_equal(ret, 0);

}

/* All data written, flush TX queue and stop the transmission */
ret = i2s_trigger(dev_i2s_tx, I2S_DIR_TX, I2S_TRIGGER_DRAIN);
zassert_equal(ret, 0, "TX DRAIN trigger failed");

k_thread_join(my_tid,K_FOREVER);
TC_PRINT("%d TX blocks sent\n", tx_idx);
TC_PRINT("%d RX blocks received\n", rx_idx);

}

[RadekPolyend]

I have CONFIG_LOG_MODE_DEFERRED=y, DMA channels are used by I2S only. Regarding my code there is nothing special about it as I just wrote you and API does not really make it possible to use differently than it is supposed to be. I will try to run you test and let you know but to be honest if you use API the way it should be used and if it's working on older kernel than there must be some loophole which is visible in some circumstances when non isolated test is performed.

[DerekSnell]

Hi @RadekPolyend ,
There is a bug fix for the eDMA driver at #82890. Does that help with this issue?

Thanks