[BUG] HDA audio output garbled on MTL & cAVS2.5 with native Zephyr DMA+DAI

[kv2019i]

Describe the bug
Test audio playback to HDA headset codec.

To Reproduce
aplay file.wav

Reproduction Rate
100%

Expected behavior
Clean audio output

Impact
Showstopper

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: c693d0caf6fa
   • SOF: f6f9b62
2. Name of the topology file
   • Topology: sof-hda-generic-2ch.tplg
3. Name of the platform(s) on which the bug is observed.
   • Platform: TGL

Screenshots or console output

Notes
Originally reported by @singalsu on UP i11.

[kv2019i]

FYI @mengdonglin @lgirdwood , this potentially affects sof-2.4 stable branch as well. Confirmed to happen also with sof-2.4.

[marc-hb]

@kv2019i , @singalsu is this too small for https://github.com/thesofproject/sof-test/blob/main/test-case/check-alsabat.sh to notice?

[kv2019i]

@marc-hb alsabat should definitely pick this up.

[keqiaozhang]

@kv2019i I checked the alsabat on TGL-UP board with IPC4 fw/driver. it can pass the test and the audio wav looks perfect.

ubuntu@sh-tglu-up-hda-04:/tmp$ ~/sof-test/test-case/check-alsabat.sh -p hw:sofhdadsp,0 -c hw:Device,0
2022-12-05 09:31:06 UTC [INFO] ktime=84160 sof-test PID=6883: starting
2022-12-05 09:31:06 UTC [WARNING] NO MODEL is defined. Please define MODEL to run alsa_settings/MODEL.sh
2022-12-05 09:31:06 UTC [INFO] Starting /home/ubuntu/.local/bin/mtrace-reader.py
2022-12-05 09:31:06 UTC [INFO] check the PCMs before alsabat test
2022-12-05 09:31:08 UTC [COMMAND] alsabat -Phw:sofhdadsp,0 --standalone -n 240000 -r 48000 -c 2 -F 997
alsa-utils version 1.2.2

Entering playback thread (ALSA).
Get period size: 2048  buffer size: 16384
Playing generated audio sine wave
2022-12-05 09:31:09 UTC [COMMAND] alsabat -Chw:Device,0 -c 1 -r 48000 -F 997
alsa-utils version 1.2.2

Entering capture thread (ALSA).
Get period size: 3000  buffer size: 24000
Recording ...
Capture completed.

BAT analysis: signal has 65536 frames at 48000 Hz, 1 channels, 2 bytes per sample.

Channel 1 - Checking for target frequency 997.00 Hz
Amplitude: 23524.8; Percentage: [71]
Detected peak at 996.83 Hz of 35.86 dB
 Total 42.0 dB from 983.64 to 1010.01 Hz
 PASS: Peak detected at target frequency
Detected at least 1 signal(s) in total

Return value is 0
Playback completed.

Return value is 0
2022-12-05 09:31:14 UTC [INFO] pkill -TERM -f mtrace-reader.py
2022-12-05 09:31:14 UTC [INFO] ktime=84168 sof-test PID=6883: ending
2022-12-05 09:31:14 UTC [INFO] Test Result: PASS!

[kv2019i]

Hmm, something is off here. @singalsu , @ujfalusi both got the audio problem. I just retried building kernel (sof-dev of today 41f9d4fe31be334ece6ec0a1829b730342f9c900), rebuild tplg (main of today 7029fb7) and rebuild FW (main of today 7029fb7) and I still get the garbled audio.

Dmic seems to be ok, so at least some of the DMAs are running as expected. The FW log also seems ok, performance is at expected level and no xruns are reported.

[mengdonglin]

@kv2019i @singalsu @ujfalusi @keqiaozhang Do you have PulseAudio or Pipewire enabled during your test?

[kv2019i]

@mengdonglin Not enabled, this happens with plain aplay to native PCM, so audio servers should not interfere.

Also tested today:

• forcing DMI-L1 off (-> no impact)
• older test branch for native drivers: SOF c04b406fd0a1085ba5b1dee888c2bbcf0c601ba0 , Zephyr bd60b9289a635aedf80fc997e6b2a2de56fe5786 (-> issue still seen)

[lgirdwood]

Do FW logs show any issues re underruns ?
Is audio garbled with less gain i.e. overall gain at -3dB or -6dB
Is there a wav capture to append ?

[ujfalusi]

@lgirdwood, this is what I have in firmware log when playing audio to HDMI. The audio is garbled and it is playing in slow motion (1.5 times slower):

[    0.000000] <inf> dma_intel_adsp_gpdma: intel_adsp_gpdma_init: dma dma@7d000 initialized
[    0.000000] <inf> dma_intel_adsp_gpdma: intel_adsp_gpdma_init: dma dma@7c000 initialized
*** Booting Zephyr OS build ffed8388e7cb ***
[    0.000000] <inf> main: SOF on intel_adsp_cavs25
[    0.015530] <inf> init: FW ABI 0x301a000 DBG ABI 0x5003000 tags SOF:v2.0-rc1-1798-g8c16ce371dbf zephyr:ffed8388e7cb src hash 0xdeb39d20 (ref hash 0xdeb39d20)
[    0.015550] <inf> power: pm_runtime_enable_dsp dsp_d0_sref 1
[    0.015648] <inf> ll_schedule: dma_single_chan_domain_init(): num_dma 2, clk 4
[    0.015668] <inf> ipc: ipc_init()
[    0.015686] <inf> idc: idc_init()
[    0.015701] <inf> dma_trace: dma_trace_init_complete()
[    0.015713] <inf> dma: dma_get() ID 4 sref = 1 busy channels 0
[    0.015845] <inf> main: SOF initialized
[    0.015921] <inf> idc: idc_init()
[    0.016133] <inf> ipc: rx    : 0x44000000|0x31400008
[    0.016295] <inf> ipc: rx    : 0x44000000|0x3060004c
[    0.046951] <inf> ipc: rx    : 0xe070000|0x180
[    0.046963] <inf> pipe: pipeline new pipe_id 8388608 priority 0
[    0.047005] <inf> dma: dma_get() ID 5 sref = 1 busy channels 0
[    0.047063] <inf> dma: dma_get() ID 7 sref = 1 busy channels 0
[    0.047066] <inf> ipc: comp:8388608 0x800002 dai_config() dai type = 3 index = 15 dd 0x9e080bc0
[    0.047081] <inf> ipc: buffer new size 0x180 id 8388608.8388611 flags 0x0
[    0.047105] <inf> pipe: comp:8388608 0x800001 connect buffer 8388611 as sink
[    0.047110] <inf> pipe: comp:8388608 0x800002 connect buffer 8388611 as source
[    0.047118] <inf> pipe: pipe:8388608 0x0 pipeline complete, clock freq 400000000Hz
[    0.047151] <inf> ipc: comp:8388608 0x800002 dai_data_config() dai type = 3 index = 15 dd 0x9e080bc0
[    0.047170] <inf> dai_comp: comp:8388608 0x800002 dai_playback_params() dest_dev = 0 stream_id = 0 src_width = 2 dest_width = 2
[    0.047175] <inf> dai_comp: comp:8388608 0x800002 dai_playback_params() fifo 0x0
[    0.047193] <inf> pipe: pipe:8388608 0x0 pipe prepare
[    0.047211] <inf> dai_comp: comp:8388608 0x800002 dai_prepare()
[    0.047215] <inf> dai_comp: comp:8388608 0x800002 dai_config_prepare(), channel = 0
[    0.047220] <inf> dai_comp: comp:8388608 0x800002 dai_config_prepare(): new configured dma channel index 0
[    0.047235] <inf> pipe: pipe:8388608 0x0 pipe trigger cmd 7
[    0.047241] <inf> ll_schedule: task add 0xbe081a40 0x20180U priority 0 flags 0x0
[    0.047261] <inf> ll_schedule: zephyr_domain_register domain->type 1 domain->clk 4 domain->ticks_per_ms 38400 period 1000
[    0.047400] <inf> host_comp: comp:8388608 0x800001 no bytes to copy, 384 free in buffer, 0 available in DMA
[    0.047406] <wrn> dai_comp: comp:8388608 0x800002 dai_copy(): Copy_bytes 0 + avail bytes 16 < period bytes 192, possible glitch
[    0.047411] <wrn> dai_comp: comp:8388608 0x800002 dai_copy(): nothing to copy
[    0.048380] <wrn> dai_comp: comp:8388608 0x800002 dai_copy(): Copy_bytes 128 + avail bytes 0 < period bytes 192, possible glitch
[    0.049353] <wrn> dai_comp: comp:8388608 0x800002 dai_copy(): Copy_bytes 128 + avail bytes 0 < period bytes 192, possible glitch
[    0.050350] <wrn> dai_comp: comp:8388608 0x800002 dai_copy(): Copy_bytes 128 + avail bytes 0 < period bytes 192, possible glitch
[    0.051350] <wrn> dai_comp: comp:8388608 0x800002 dai_copy(): Copy_bytes 128 + avail bytes 0 < period bytes 192, possible glitch
[    0.052350] <wrn> dai_comp: comp:8388608 0x800002 dai_copy(): Copy_bytes 128 + avail bytes 0 < period bytes 192, possible glitch
[    0.053350] <wrn> dai_comp: comp:8388608 0x800002 dai_copy(): Copy_bytes 128 + avail bytes 0 < period bytes 192, possible glitch

The <wrn> lines are flooding the log ^

Analog playback (garbled, distorted, but correct speed):

[    0.000000] <inf> dma_intel_adsp_gpdma: intel_adsp_gpdma_init: dma dma@7d000 initialized
[    0.000000] <inf> dma_intel_adsp_gpdma: intel_adsp_gpdma_init: dma dma@7c000 initialized
*** Booting Zephyr OS build ffed8388e7cb ***
[    0.000000] <inf> main: SOF on intel_adsp_cavs25
[    0.015351] <inf> init: FW ABI 0x301a000 DBG ABI 0x5003000 tags SOF:v2.0-rc1-1798-g8c16ce371dbf zephyr:ffed8388e7cb src hash 0xdeb39d20 (ref hash 0xdeb39d20)
[    0.015371] <inf> power: pm_runtime_enable_dsp dsp_d0_sref 1
[    0.015471] <inf> ll_schedule: dma_single_chan_domain_init(): num_dma 2, clk 4
[    0.015491] <inf> ipc: ipc_init()
[    0.015508] <inf> idc: idc_init()
[    0.015523] <inf> dma_trace: dma_trace_init_complete()
[    0.015536] <inf> dma: dma_get() ID 4 sref = 1 busy channels 0
[    0.015668] <inf> main: SOF initialized
[    0.015743] <inf> idc: idc_init()
[    0.015803] <inf> ipc: rx    : 0x44000000|0x31400008
[    0.015905] <inf> ipc: rx    : 0x44000000|0x3060004c
[    0.184833] <inf> ipc: rx    : 0x11000005|0x0
[    0.184843] <inf> pipe: pipeline new pipe_id 0 priority 0
[    0.185081] <inf> ipc: rx    : 0x40000004|0x15
[    0.185115] <inf> ipc: buffer new size 0x180 id 0.0 flags 0x0
[    0.185148] <inf> dma: dma_get() ID 5 sref = 1 busy channels 0
[    0.185161] <inf> pipe: comp:0 0x40000 connect buffer 0 as sink
[    0.185341] <inf> ipc: rx    : 0x40000006|0x10
[    0.185370] <inf> module_adapter: comp:0 0x60000 module_init() start
[    0.185385] <inf> module_adapter: comp:0 0x60000 module_init() done
[    0.185616] <inf> ipc: rx    : 0x44000006|0x30000018
[    0.186163] <inf> ipc: rx    : 0x40000002|0xa
[    0.186371] <inf> ipc: rx    : 0x11010006|0x0
[    0.186378] <inf> pipe: pipeline new pipe_id 1 priority 0
[    0.186555] <inf> ipc: rx    : 0x40000003|0x1000a
[    0.186788] <inf> ipc: rx    : 0x40010006|0x10010
[    0.186811] <inf> module_adapter: comp:1 0x60001 module_init() start
[    0.186833] <inf> module_adapter: comp:1 0x60001 module_init() done
[    0.187238] <inf> ipc: rx    : 0x44010006|0x30000018
[    0.187456] <inf> ipc: rx    : 0x40010004|0x10015
[    0.187485] <inf> ipc: buffer new size 0x300 id 1.0 flags 0x0
[    0.187530] <inf> dma: dma_get() ID 7 sref = 1 busy channels 0
[    0.187533] <inf> ipc: comp:1 0x40001 dai_config() dai type = 3 index = 0 dd 0x9e082580
[    0.187543] <inf> pipe: comp:1 0x40001 connect buffer 0 as source
[    0.187801] <inf> ipc: rx    : 0x45000004|0x6
[    0.187816] <inf> ipc: buffer new size 0x300 id 0.0 flags 0x0
[    0.187850] <inf> pipe: comp:0 0x40000 connect buffer 0 as sink
[    0.187853] <inf> pipe: comp:0 0x60000 connect buffer 0 as source
[    0.188558] <inf> ipc: rx    : 0x45000006|0x2
[    0.188570] <inf> ipc: buffer new size 0x300 id 0.0 flags 0x0
[    0.188585] <inf> pipe: comp:0 0x60000 connect buffer 0 as sink
[    0.188590] <inf> pipe: comp:0 0x20000 connect buffer 0 as source
[    0.188708] <inf> ipc: rx    : 0x45000002|0x3
[    0.188716] <inf> ipc: buffer new size 0x300 id 0.0 flags 0x0
[    0.188738] <inf> pipe: comp:0 0x20000 connect buffer 0 as sink
[    0.188743] <inf> pipe: comp:1 0x30000 connect buffer 0 as source
[    0.188886] <inf> ipc: rx    : 0x45000003|0x10006
[    0.188895] <inf> ipc: buffer new size 0x300 id 1.0 flags 0x0
[    0.188910] <inf> pipe: comp:1 0x30000 connect buffer 0 as sink
[    0.188915] <inf> pipe: comp:1 0x60001 connect buffer 0 as source
[    0.189421] <inf> ipc: rx    : 0x45010006|0x10004
[    0.189431] <inf> ipc: buffer new size 0x300 id 1.0 flags 0x0
[    0.189446] <inf> pipe: comp:1 0x60001 connect buffer 0 as sink
[    0.189450] <inf> pipe: comp:1 0x40001 connect buffer 0 as source
[    0.191803] <inf> ipc: rx    : 0x13010003|0x0
[    0.191823] <inf> pipe: pipe:1 0x0 pipeline complete, clock freq 400000000Hz
[    0.191918] <inf> ipc: rx    : 0x13010004|0x0
[    0.191941] <inf> ipc: comp:1 0x40001 dai_data_config() dai type = 3 index = 0 dd 0x9e082580
[    0.191961] <inf> dai_comp: comp:1 0x40001 dai_playback_params() dest_dev = 0 stream_id = 0 src_width = 4 dest_width = 4
[    0.191966] <inf> dai_comp: comp:1 0x40001 dai_playback_params() fifo 0x0
[    0.191993] <inf> pipe: pipe:1 0x0 pipe prepare
[    0.192033] <inf> dai_comp: comp:1 0x40001 dai_prepare()
[    0.192038] <inf> dai_comp: comp:1 0x40001 dai_config_prepare(), channel = 0
[    0.192043] <inf> dai_comp: comp:1 0x40001 dai_config_prepare(): new configured dma channel index 0
[    0.192056] <inf> pipe: pipe:1 0x0 pipe trigger cmd 7
[    0.192066] <inf> ll_schedule: task add 0xbe084480 0x20180U priority 0 flags 0x0
[    0.192086] <inf> ll_schedule: zephyr_domain_register domain->type 1 domain->clk 4 domain->ticks_per_ms 38400 period 1000
[    0.192971] <inf> ipc: rx    : 0x13000003|0x0
[    0.192986] <wrn> ipc: ipc_pipeline_complete(): no scheduling component specified, use comp 131072
[    0.192991] <inf> pipe: pipe:0 0x0 pipeline complete, clock freq 400000000Hz
[    0.193068] <inf> ipc: rx    : 0x13000004|0x0
[    0.193118] <inf> pipe: pipe:0 0x0 pipe prepare
[    0.193221] <inf> pipe: pipe:0 0x0 pipe trigger cmd 7
[    0.193231] <inf> ll_schedule: task add 0xbe084b00 0x20180U priority 0 flags 0x0
[    0.194213] <err> copier: comp:0 0x40000 failed to find dai comp or sink pipeline not running.
[    0.194235] <err> copier: comp:0 0x40000 failed to find dai comp or sink pipeline not running.
[    0.194250] <inf> host_comp: comp:0 0x40000 no bytes to copy, 384 free in buffer, 0 available in DMA
[    1.215231] <inf> ll_schedule: ll timer avg 2666, max 3992, overruns 0
[    2.239231] <inf> ll_schedule: ll timer avg 2666, max 3088, overruns 0
[    3.263231] <inf> ll_schedule: ll timer avg 2666, max 3069, overruns 0
[    4.287231] <inf> ll_schedule: ll timer avg 2664, max 3081, overruns 0

Nothing special to my eyes in the log.

[bardliao]

I can reproduce the issue on my Up Xtreme board (TGL) with the specific recipe
Kernel: c693d0caf6fa
SOF: f6f9b62