[BUG IMX] Input/output error when mixing two streams

[iuliana-prodan]

Describe the bug
Input/output error when when mixing two streams.

To Reproduce
$aplay -Dhw:1,0 -f S16_LE -c 2 -r 48000 -t raw /dev/urandom & aplay -Dhw:1,1 -f S16_LE -c 2 -r 48000 -t raw /dev/urandom &

Reproduction Rate
100%

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: 5.10
   • SOF: master
2. Name of the topology file
   • Topology: sof-imx8-wm8960-mixer.tplg, sof-imx8-cs42888-mixer.tplg, sof-imx8mp-wm8960-mixer.tplg
3. Name of the platform(s) on which the bug is observed.
   • Platform: i.MX8QXP/i.MX8QM/i.MX8MP

Screenshots or console output

root@imx8qxpc0mek:~# aplay -Dhw:1,0 -f S16_LE -c 2 -r 48000 -t raw /dev/urandom & aplay -Dhw:1,1 -f S16_LE -c 2 -r 48000 -t raw /dev/urandom &
[1] 560
[2] 561
root@imx8qxpc0mek:~# Playing raw data '/dev/urandom' : Playing raw data '/dev/urandom' : Signed 16 bit Little Endian, Signed 16 bit Little Endian, Rate 48000 Hz, Rate 48000 Hz, StereoStereo


root@imx8qxpc0mek:~# aplay: pcm_write:2061: aplay: pcm_write:2061: write error: Input/output errorwrite error: Input/output error


[1]- Done(1) aplay -Dhw:1,0 -f S16_LE -c 2 -r 48000 -t raw /dev/urandom
[2]+ Done(1) aplay -Dhw:1,1 -f S16_LE -c 2 -r 48000 -t raw /dev/urandom
root@imx8qxpc0mek:~#
root@imx8qxpc0mek:~# ./sof-logger -t -l /lib/firmware/imx/sof/sof-imx8x.ldc 
 TIMESTAMP DELTA C# COMPONENT LOCATION CONTENT
[81523859753.437500] ( nan) c0 dai 1.2 src/audio/dai.c:847 WARN dai_copy(): Copy_bytes 0 + avail bytes 0 < period bytes 192, possible glitch
[81523860036.666672] ( 283.229156) c0 dai 1.2 src/audio/dai.c:855 WARN dai_copy(): nothing to copy
[81523892089.583344] ( 32052.916016) c0 buffer 3.15 src/audio/buffer.c:271 comp_update_buffer_consume(), no bytes to consume, source->comp.id = 13, source->comp.type = 5, sink->comp.id = 0, sink->comp.type = 6
[81523892409.270844] ( 319.687500) c0 buffer 1.4 src/audio/buffer.c:231 comp_update_buffer_produce(), no bytes to produce, source->comp.id = 0, source->comp.type = 6, sink->comp.id = 1, sink->comp.type = 5
[81523892734.635422] ( 325.364594) c0 pga 1.1 ../audio/volume/volume.c:729 volume_copy(), source_bytes = 0x0, sink_bytes = 0x0
[81523893066.562500] ( 331.927094) c0 dai 1.2 src/audio/dai.c:847 WARN dai_copy(): Copy_bytes 0 + avail bytes 0 < period bytes 192, possible glitch
[81523893349.479172] ( 282.916656) c0 dai 1.2 src/audio/dai.c:855 WARN dai_copy(): nothing to copy
[81523925364.114594] ( 32014.634766) c0 buffer 3.15 src/audio/buffer.c:271 comp_update_buffer_consume(), no bytes to consume, source->comp.id = 13, source->comp.type = 5, sink->comp.id = 0, sink->comp.type = 6
[81523925676.041672] ( 311.927094) c0 buffer 1.4 src/audio/buffer.c:231 comp_update_buffer_produce(), no bytes to produce, source->comp.id = 0, source->comp.type = 6, sink->comp.id = 1, sink->comp.type = 5
[81523926021.927094] ( 345.885406) c0 pga 1.1 ../audio/volume/volume.c:729 volume_copy(), source_bytes = 0x0, sink_bytes = 0x0
[81523926353.229172] ( 331.302094) c0 dai 1.2 src/audio/dai.c:847 WARN dai_copy(): Copy_bytes 0 + avail bytes 0 < period bytes 192, possible glitch
[81523926644.479172] ( 291.250000) c0 dai 1.2 src/audio/dai.c:855 WARN dai_copy(): nothing to copy
[81523958758.072922] ( 32113.593750) c0 buffer 3.15 src/audio/buffer.c:271 comp_update_buffer_consume(), no bytes to consume, source->comp.id = 13, source->comp.type = 5, sink->comp.id = 0, sink->comp.type = 6
[81523959075.312500] ( 317.239594) c0 buffer 1.4 src/audio/buffer.c:231 comp_update_buffer_produce(), no bytes to produce, source->comp.id = 0, source->comp.type = 6, sink->comp.id = 1, sink->comp.type = 5
[81523959400.260422] ( 324.947906) c0 pga 1.1 ../audio/volume/volume.c:729 volume_copy(), source_bytes = 0x0, sink_bytes = 0x0
[81523959731.562500] ( 331.302094) c0 dai 1.2 src/audio/dai.c:847 WARN dai_copy(): Copy_bytes 0 + avail bytes 0 < period bytes 192, possible glitch
[81523960014.166672] ( 282.604156) c0 dai 1.2 src/audio/dai.c:855 WARN dai_copy(): nothing to copy
[81523992138.333344] ( 32124.166016) c0 buffer 3.15 src/audio/buffer.c:271 comp_update_buffer_consume(), no bytes to consume, source->comp.id = 13, source->comp.type = 5, sink->comp.id = 0, sink->comp.type = 6
[81523992456.979172] ( 318.645844) c0 buffer 1.4 src/audio/buffer.c:231 comp_update_buffer_produce(), no bytes to produce, source->comp.id = 0, source->comp.type = 6, sink->comp.id = 1, sink->comp.type = 5
[81523992788.906250] ( 331.927094) c0 pga 1.1 ../audio/volume/volume.c:729 volume_copy(), source_bytes = 0x0, sink_bytes = 0x0
[81523993112.395844] ( 323.489594) c0 dai 1.2 src/audio/dai.c:847 WARN dai_copy(): Copy_bytes 0 + avail bytes 0 < period bytes 192, possible glitch
[81523993395.312500] ( 282.916656) c0 dai 1.2 src/audio/dai.c:855 WARN dai_copy(): nothing to copy
[81524025452.447922] ( 32057.134766) c0 buffer 3.15 src/audio/buffer.c:271 comp_update_buffer_consume(), no bytes to consume, source->comp.id = 13, source->comp.type = 5, sink->comp.id = 0, sink->comp.type = 6
[81524025764.062500] ( 311.614594) c0 buffer 1.4 src/audio/buffer.c:231 comp_update_buffer_produce(), no bytes to produce, source->comp.id = 0, source->comp.type = 6, sink->comp.id = 1, sink->comp.type = 5
[81524026087.135422] ( 323.072906) c0 pga 1.1 ../audio/volume/volume.c:729 volume_copy(), source_bytes = 0x0, sink_bytes = 0x0
[81524026410.312500] ( 323.177094) c0 dai 1.2 src/audio/dai.c:847 WARN dai_copy(): Copy_bytes 0 + avail bytes 0 < period bytes 192, possible glitch
[81524026693.854172] ( 283.541656) c0 dai 1.2 src/audio/dai.c:855 WARN dai_copy(): nothing to copy
[81524058770.000000] ( 32076.146484) c0 buffer 3.15 src/audio/buffer.c:271 comp_update_buffer_consume(), no bytes to consume, source->comp.id = 13, source->comp.type = 5, sink->comp.id = 0, sink->comp.type = 6
[81524059089.895844] ( 319.895844) c0 buffer 1.4 src/audio/buffer.c:231 comp_update_buffer_produce(), no bytes to produce, source->comp.id = 0, source->comp.type = 6, sink->comp.id = 1, sink->comp.type = 5
[81524059414.843750] ( 324.947906) c0 pga 1.1 ../audio/volume/volume.c:729 volume_copy(), source_bytes = 0x0, sink_bytes = 0x0
[81524059736.458344] ( 321.614594) c0 dai 1.2 src/audio/dai.c:847 WARN dai_copy(): Copy_bytes 0 + avail bytes 0 

[giuzan]

Hi @iuliana-prodan,

I experienced the issue on iMX8QM using sof-imx8-cs42888-mixer.tplg. The issue can be reproduced in both branches imx-stable-v1.5 and imx-stable-v1.6.

I applied the commits of this PR #3803 on the top of both branches and I performed some tests.

Test 1

It is basically the test you reported in bug description.

I run the following command:

aplay -D hw:1,0 test_1.wav & aplay -D hw:1,1 test_2.wav

The issue seems to be fixed (in both branches), I did not experience it anymore. Before the fix, I used to reproduce the issue simply playing on a single pipeline only. Through this test, I also tried to really mix the two streams.

Test 2

I tested a new scenario. I run the following command:

aplay -D hw:1,0 test_1.wav & aplay -D hw:1,1 test_2.wav & arecord -D hw:1,0 -c 2 -r 48000 -f S16_LE record.wav -d 10

In this way also the capture pipeline is involved.
I saw input/output errors (in both branches), could be the problem related to #3690?
Moreover, rarely happens that a "strange noise" is heard and no input/errors happen.

I hope that these information helps you.

I attach the script I'm using to perform the tests:

#!/bin/bash

p1=1
p2=1
r1=1

logs_recorder()
{
 sof-logger -l /lib/firmware/imx/sof/sof-imx8.ldc -t >> report.txt
}

test_aplay_1()
{
 while true
 do
 echo "start | ${p1} | aplay -D hw:1,0 test_1.wav" >> report.txt
 echo "start | ${p1} | aplay -D hw:1,0 test_1.wav"
 aplay -D hw:1,0 test_1.wav
 echo "end | ${p1} | aplay -D hw:1,0 test_1.wav" >> report.txt
 echo "end | ${p1} | aplay -D hw:1,0 test_1.wav"
 p1=$((p1+1))
 done
}

test_aplay_2()
{
 while true
 do
 echo "start | ${p2} | aplay -D hw:1,1 test_2.wav" >> report.txt
 echo "start | ${p2} | aplay -D hw:1,1 test_2.wav"
 aplay -D hw:1,1 test_2.wav
 echo "end | ${p2} | aplay -D hw:1,1 test_2.wav" >> report.txt
 echo "end | ${p2} | aplay -D hw:1,1 test_2.wav"
 p2=$((p2+1))
 done
}

test_arecord()
{
 while true
 do
 echo "start | ${r1} | arecord -D hw:1,0 -c 2 -r 48000 -f S16_LE record.wav -d 10" >> report.txt
 echo "start | ${r1} | arecord -D hw:1,0 -c 2 -r 48000 -f S16_LE record.wav -d 10"
 arecord -D hw:1,0 -c 2 -r 48000 -f S16_LE record.wav -d 10
 echo "end | ${r1} | arecord -D hw:1,0 -c 2 -r 48000 -f S16_LE record.wav -d 10" >> report.txt
 echo "end | ${r1} | arecord -D hw:1,0 -c 2 -r 48000 -f S16_LE record.wav -d 10"
 r1=$((r1+1))
 done
}

echo '* * *' > report.txt

logs_recorder &
test_aplay_1 &
test_aplay_2 &
test_arecord

[iuliana-prodan]

@giuzan Thanks for testing this!
Your Test 2 scenario it's a problem we've also discovered and, since you mentioned it, I've created another bug: #3809.
This is not quite related with the mixer issue: the playback and record are started/stopped multiple times and, at some point, it fails with Input/output error.

I'm looking into this, now.

[iuliana-prodan]

@giuzan For Test 2 scenario, if you don't start/stop the playback and record it works ok:

root@imx8qxpc0mek:~# date
Tue Feb 2 16:58:03 UTC 2021
root@imx8qxpc0mek:~# aplay -Dhw:1,0 -f S16_LE -c 2 -r 48000 -t raw /dev/urandom & aplay -Dhw:1,1 -f S16_LE -c 2 -r 48000 -t raw /dev/urandom & arecord -Dhw:1,0 -f S16_LE -c 2 -r 48000 -t raw /dev/null &
[1] 626
[2] 627
[3] 628
root@imx8qxpc0mek:~# Recording raw data '/dev/null' : Playing raw data '/dev/urandom' : Playing raw data '/dev/urandom' : Signed 16 bit Little Endian, Signed 16 bit Little Endian, Signed 16 bit Little Endian, Rate 48000 Hz, Rate 48000 Hz, Rate 48000 Hz, StereoStereoStereo

root@imx8qxpc0mek:~# jobs
[1] Running aplay -Dhw:1,0 -f S16_LE -c 2 -r 48000 -t raw /dev/urandom &
[2]- Running aplay -Dhw:1,1 -f S16_LE -c 2 -r 48000 -t raw /dev/urandom &
[3]+ Running arecord -Dhw:1,0 -f S16_LE -c 2 -r 48000 -t raw /dev/null &
root@imx8qxpc0mek:~# 
root@imx8qxpc0mek:~# date
Tue Feb 2 17:26:31 UTC 2021
root@imx8qxpc0mek:~# 

The start/stop playback & record will be handled in #3809.