[EHL][BUG]Dmesg shows "ASoC: error at snd_soc_dai_startup on intel-hdmi-hifi1: -16" when do multi-pipleline stress test.

Describe the bug
Dmesg warning show "ASoC: error at snd_soc_dai_startup on intel-hdmi-hifi1: -16" when aplay headset, DP and HMDI at the same time. "ctrl+c "the playback terminal can be freezed after issue occured and all pipelines can't work.
Note: Unplug/plug in power cable can recover.

Need some workaround on EHL when runtime PM keeps active after system reboot. Steps as below:
Add "i915.force_probe=4571" after kernel in "/boot/grub/grub.cfg" .(refer to issue #2061)
Eg. linux /boot/vmlinuz-5.7.0-rc3-default-validation-20200507-ehl-0-ad2331e root=UUID=77b6e30a-340a-4342-87b9-62028fb440b8 ro quiet nosplash i915.force_probe=4571

To Reproduce
1.Boot up system.
2.cd sof-test/test-case
3.export TPLG=/lib/firmware/intel/sof-tplg/ sof-ehl-rt5660.tplg
2. Run "./multiple-pipeline-playback.sh -c 8 -r -l 5". (https://github.com/thesofproject/sof-test/blob/master/test-case/multiple-pipeline-playback.sh)

[  138.926918] snd_hda_codec_hdmi ehdaudio0D2: HDMI: ASP channel 0 => slot 0
[  138.926986] snd_hda_codec_hdmi ehdaudio0D2: HDMI: ASP channel 1 => slot 1
[  138.927049] snd_hda_codec_hdmi ehdaudio0D2: HDMI: ASP channel 15 => slot 2
[  138.927102] snd_hda_codec_hdmi ehdaudio0D2: HDMI: ASP channel 15 => slot 3
[  138.927153] snd_hda_codec_hdmi ehdaudio0D2: HDMI: ASP channel 15 => slot 4
[  138.927207] snd_hda_codec_hdmi ehdaudio0D2: HDMI: ASP channel 15 => slot 5
[  138.927256] snd_hda_codec_hdmi ehdaudio0D2: HDMI: ASP channel 15 => slot 6
[  138.927311] snd_hda_codec_hdmi ehdaudio0D2: HDMI: ASP channel 15 => slot 7
[  138.928510] snd_hda_codec_hdmi ehdaudio0D2: hdmi_pin_hbr_setup: NID=0x6, pinctl=0x40
[  138.928612] snd_hda_codec_hdmi ehdaudio0D2: hda_codec_setup_stream: NID=0x3, stream=0x2, channel=0, format=0x31
[  138.932429] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=1
[  138.932442] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 4 dir 0 cmd 1
[  138.932849] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x24001e successful
[  138.932857] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[  138.933023] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[  139.628620] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  139.628653] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  140.128594] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  140.128627] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  141.528500] snd_hda_codec_hdmi ehdaudio0D2: ASoC: error at snd_soc_dai_startup on intel-hdmi-hifi1: -16
[  141.528505] snd_hda_codec_hdmi ehdaudio0D2: ASoC: can't open DAI intel-hdmi-hifi1: -16

Reproduce rate
5/5

Expected result
Aplay headset, DP and HMDI at the same time should no error.

Actual result
Dmesg warning show "ASoC: error at snd_soc_dai_startup on intel-hdmi-hifi1: -16" when aplay headset, DP and HMDI at the same time.

Test recipe

Kernel:https://github.com/thesofproject/linux/commits/topic/sof-dev commit:c05a3f86 and add below 2 patches for add codec acpi
0001-ASoC-rt5660-Add-the-codec-ID-of-EHL-CRB.patch.txt
0002-ehl-use-intc-codec-id.patch.txt
FW: https://github.com/thesofproject/sof/commits/v1.5 commit: 7e6cd4b0
Tplg: sof-ehl-rt5660.tplg
Platform:EHL RVP with RT5660 in I2S mode

dmesg_drm.log
sof_trace07.log

Issue also can be reproduced with master(commit:2c9bb63) and sof-dev(commit:c05a3f86) when do multi pipeline stress test.

Issue also can be reproduced on another EHL RVP with RT5660 in I2S mode when do multi pipeline stress test.

Issue also can be reproduced with sof-dev+master on TGL-U RVP with codec ALC711 and RT1308 in SDW mode. "ctrl+c "playback terminal can be freezed after issue occured and all pipelines can't work.
Test steps:
1.Boot up system.
2.cd sof-test/test-case
3.export TPLG=/lib/firmware/intel/sof-tplg/sof-tgl-rt711-rt1308.tplg
2. Run "./multiple-pipeline-playback.sh -c 9 -r -l 10". (https://github.com/thesofproject/sof-test/blob/master/test-case/multiple-pipeline-playback.sh)

[   60.576111] snd_hda_codec_hdmi ehdaudio0D2: HDMI: hinfo 00000000b2233cbd not registered
[   60.576363] snd_hda_codec_hdmi ehdaudio0D2: choose cvt 2 for pin nid 6
[   60.576806] sof-audio-pci 0000:00:1f.3: pcm: open stream 5 dir 0
[   60.576807] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[   60.576807] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[   60.576808] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[   60.576826] snd_hda_codec_hdmi ehdaudio0D2: ASoC: error at snd_soc_dai_startup on intel-hdmi-hifi2: -16
[   60.576829] snd_hda_codec_hdmi ehdaudio0D2: ASoC: can't open DAI intel-hdmi-hifi2: -16
[   61.063788] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[   61.063822] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[   61.563765] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[   61.563813] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG

sof_trace.log
dmesg.log

Issue also can be reproduced with sof-dev+master on JSL-RVP with ALC700 in HDA mode when do multi-pipeline stress test.

3.export TPLG=/lib/firmware/intel/sof-tplg/sof-tgl-rt711-rt1308.tplg

This is wrong. It should be sof-ehl-xxx.tplg

And it seems the bios is set wrongly.

3.export TPLG=/lib/firmware/intel/sof-tplg/sof-tgl-rt711-rt1308.tplg

This is wrong. It should be sof-ehl-xxx.tplg

Sorry for writing the wrong TPLG in the describe. But I reproduced it with sof-ehl-rt5660.tplg

Test with latest sof-dev +master, issue still can be reproduced.

Error can be seen with PR thesofproject/sof#2886 after pulseaudio disabled.

@sinahuang

This does not look right:
Apr 3 06:18:05 ubuntu-Tiger-Lake-Client-Platform kernel: [ 60.574153] snd_hda_codec_hdmi ehdaudio0D2: choose cvt 1 for pin nid 6
Apr 3 06:18:05 ubuntu-Tiger-Lake-Client-Platform kernel: [ 60.576111] snd_hda_codec_hdmi ehdaudio0D2: HDMI: hinfo 00000000b2233cbd not registered
Apr 3 06:18:05 ubuntu-Tiger-Lake-Client-Platform kernel: [ 60.576363] snd_hda_codec_hdmi ehdaudio0D2: choose cvt 2 for pin nid 6

Using same nid==6 would be ok if both monitors are connected via DP-MST, but this bug was with mix of HDMI and DP, so it can't be that, so something else has gone wrong.

@sinahuang I'd need a few more logs:

output of "alsa-info" when both monitors are connected
i915 log
- modprobe conf.d:
  options drm debug=0x1e
- or with kernel cmdline:
  drm.debug=0x1e

Attached drm log and alsa info on TGL-U RVP with two monitors connected.

drm.log
sof_trace.log
amixer.txt

Output of "alsa-info" on EHL RVP as below when two monitors are connected.

test@test-Elkhart-Lake-Embedded-Platform:~$ alsa-info
ALSA Information Script v 0.4.64
--------------------------------

This script visits the following commands/files to collect diagnostic
information about your ALSA installation and sound related hardware.

  dmesg
  lspci
  lsmod
  aplay
  amixer
  alsactl
  /proc/asound/
  /sys/class/sound/
  ~/.asoundrc (etc.)

See '/usr/sbin/alsa-info --help' for command line options.

cat: '/sys/module/snd_soc_ehl_rt5660/parameters/*': No such file or directory
Automatically upload ALSA information to www.alsa-project.org? [y/N] : y
Uploading information to www.alsa-project.org ...  Done!

Your ALSA information is located at http://alsa-project.org/db/?f=c4a6bc490955e250fdf744f5c94da3f40057358e

Please inform the person helping you.

Thanks for the logs. DRM logs seem good, nothing pops up. So looks like a SOF driver side issue, continuing to investigate.

Suspected rootcause is this -> #2159 (comment) -- no fix candidate yet.

@sinahuang

#2208 is a potential fix for this as well. @sinahuang Due to other issues, I could not verify this on a EHL device yet, so if you could check that would be great.

Verified with PR #2208, error info are different from original issue when do multi-pipeline stress test, dmesg shows as below:
First round, failed at 1st time
2nd round , failed at 4th time
And now after issue occurred aplay all pipelines again all pipelines can work well.

Apr  2 01:24:20 ubuntu-Elkhart-Lake-Embedded-Platform kernel: [   40.753894] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
Apr  2 01:24:20 ubuntu-Elkhart-Lake-Embedded-Platform kernel: [   40.754094] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
Apr  2 01:24:20 ubuntu-Elkhart-Lake-Embedded-Platform kernel: [   40.754097] sof-audio-pci 0000:00:1f.3: pcm: stream dir 0, posn mailbox offset is 790984
Apr  2 01:24:20 ubuntu-Elkhart-Lake-Embedded-Platform kernel: [   40.754165] snd_hda_codec_hdmi ehdaudio0D2: ASoC: error at snd_soc_dai_startup on intel-hdmi-hifi2: -16
Apr  2 01:24:20 ubuntu-Elkhart-Lake-Embedded-Platform kernel: [   40.754169] snd_hda_codec_hdmi ehdaudio0D2: ASoC: can't open DAI intel-hdmi-hifi2: -16
Apr  2 01:24:20 ubuntu-Elkhart-Lake-Embedded-Platform kernel: [   40.754173]  iDisp2: ASoC: BE open failed -16
Apr  2 01:24:20 ubuntu-Elkhart-Lake-Embedded-Platform kernel: [   40.754178]  HDMI2: ASoC: failed to start some BEs -16
Apr  2 01:24:20 ubuntu-Elkhart-Lake-Embedded-Platform kernel: [   40.754837] snd_hda_codec_hdmi ehdaudio0D2: HDMI: hinfo 00000000c44034f1 not registered
Apr  2 01:24:20 ubuntu-Elkhart-Lake-Embedded-Platform kernel: [   40.755129] snd_hda_codec_hdmi ehdaudio0D2: choose cvt 3 for pin nid 6
Apr  2 01:24:20 ubuntu-Elkhart-Lake-Embedded-Platform kernel: [   40.755291] sof-audio-pci 0000:00:1f.3: pcm: open stream 6 dir 0
Apr  2 01:24:20 ubuntu-Elkhart-Lake-Embedded-Platform kernel: [   40.755293] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
Apr  2 01:24:20 ubuntu-Elkhart-Lake-Embedded-Platform kernel: [   40.755294] sof-audio-pci 0000:00:1f.3: period count 2 max 16

drm.log

@sinahuang

@sinahuang Thank you for testing! Does the test itself also fail or do you just get the error messages in the dmesg output? When this error print is now emitted, the application has tried to open a PCM that has no connected PCM. I wonder if the test case does this? Then it would be as expected to get error for the one converter that is not connected. If test fails on the PCM nodes that are connected, then there is still more issues to debug.

HDMI Dhw:0,4 is connected, HDMI port DHW:0,3 is not connected. Run aplay Dhw:0,3 for 50 times, error not seen. run aplay Dhw:0,4 for 50 times error also not seen. Seems issue only can be reproduced via multi_pipline stress test which contains unconnected HDMI port .
Reproduced with command "./multiple-pipeline-playback.sh -c 8 -r -l 10"

aplay: main:830: audio open error: Device or resource busy
2020-04-01 18:20:06 UTC [INFO] Testing: HDMI1 [hw:0,3]
2020-04-01 18:20:06 UTC [COMMAND] aplay -D hw:0,3 -c 2 -r 48000 -f S16_LE /dev/zero -q
2020-04-01 18:20:06 UTC [INFO] ./multiple-pipeline-playback.sh will use topology /lib/firmware/intel/sof-tplg/sof-ehl-rt5660.tplg to run the test case
2020-04-01 18:20:06 UTC [INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital,Media Playback,DMIC16k' in test case
2020-04-01 18:20:06 UTC [INFO] Run command to get pipeline parameters
2020-04-01 18:20:06 UTC [COMMAND] sof-tplgreader.py /lib/firmware/intel/sof-tplg/sof-ehl-rt5660.tplg -f 'type:capture' -b ' pcm:HDA Digital,Media Playback,DMIC16k' -s 0 -e
2020-04-01 18:20:06 UTC [INFO] Testing: Headset [hw:0,0]
2020-04-01 18:20:06 UTC [COMMAND] arecord -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/null -q
2020-04-01 18:20:06 UTC [INFO] Testing: DMIC16kHz [hw:0,2]
2020-04-01 18:20:06 UTC [COMMAND] arecord -D hw:0,2 -c 2 -r 16000 -f S16_LE /dev/null -q
2020-04-01 18:20:06 UTC [INFO] Testing: DMIC [hw:0,1]
2020-04-01 18:20:06 UTC [COMMAND] arecord -D hw:0,1 -c 4 -r 48000 -f S16_LE /dev/null -q
2020-04-01 18:20:06 UTC [INFO] pipeline start sleep 0.5s for device wakeup
2020-04-01 18:20:11 UTC [ERROR] Target pipeline count: 8, current process count: 7
./multiple-pipeline-playback.sh: line 96: 11027 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
./multiple-pipeline-playback.sh: line 96: 11036 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
./multiple-pipeline-playback.sh: line 96: 11045 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
./multiple-pipeline-playback.sh: line 96: 11063 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
/home/ubuntu/sof-test/case-lib/hijack.sh: line 8: 11088 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
/home/ubuntu/sof-test/case-lib/hijack.sh: line 8: 11097 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
/home/ubuntu/sof-test/case-lib/hijack.sh: line 8: 11106 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
2020-04-01 18:20:14 UTC [INFO] Test Result: FAIL!

@sinahuang

@sinahuang This patch for addressing the warning might help with the multiple-pipeline test:
#2223

Split to track error warning issue by #2216.
Test on JSL and EHL with PR #2223, multiple-pipeline test still can be failed and dmesg as below:

[  637.950582] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[  637.950636] snd_hda_codec_hdmi ehdaudio0D2: ASoC: error at snd_soc_dai_startup on intel-hdmi-hifi1: -16
[  637.950644] snd_hda_codec_hdmi ehdaudio0D2: ASoC: can't open DAI intel-hdmi-hifi1: -16
[  637.950650]  iDisp1: ASoC: BE open failed -16
[  637.950653]  HDMI1: ASoC: failed to start some BEs -16
[  637.950711] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[  637.950845] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[  637.950866] sof-audio-pci 0000:00:1f.3: format_val=49, rate=48000, ch=2, format=10

2020-05-28 12:21:51 UTC [INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital,Media Playback,DMIC16k' in test case
2020-05-28 12:21:51 UTC [INFO] Run command to get pipeline parameters
2020-05-28 12:21:51 UTC [COMMAND] sof-tplgreader.py /lib/firmware/intel/sof-tplg/sof-hda-generic-4ch.tplg -f 'type:capture' -b ' pcm:HDA Digital,Media Playback,DMIC16k' -s 0 -e
2020-05-28 12:21:51 UTC [INFO] Testing: DMIC [hw:0,6]
2020-05-28 12:21:51 UTC [COMMAND] arecord -D hw:0,6 -c 4 -r 48000 -f S16_LE /dev/null -q
2020-05-28 12:21:51 UTC [INFO] Testing: DMIC16kHz [hw:0,7]
2020-05-28 12:21:51 UTC [COMMAND] arecord -D hw:0,7 -c 4 -r 16000 -f S16_LE /dev/null -q
2020-05-28 12:21:51 UTC [INFO] pipeline start sleep 0.5s for device wakeup
aplay: main:830: audio open error: Device or resource busy
2020-05-28 12:21:56 UTC [ERROR] Target pipeline count: 6, current process count: 5
./multiple-pipeline-playback.sh: line 96:  2194 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
./multiple-pipeline-playback.sh: line 96:  2212 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
./multiple-pipeline-playback.sh: line 96:  2221 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
/home/ubuntu/sof-test/case-lib/hijack.sh: line 8:  2241 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
/home/ubuntu/sof-test/case-lib/hijack.sh: line 8:  2250 Killed                  "${APP_LST[$1]}" -D $dev -c $channel -r $rate -f $fmt "${DEV_LST[$1]}" -q
2020-05-28 12:21:59 UTC [INFO] Test Result: FAIL!

dmesg_mul.log

Navigation Menu

Repository navigation

[EHL][BUG]Dmesg shows "ASoC: error at snd_soc_dai_startup on intel-hdmi-hifi1: -16" when do multi-pipleline stress test. #2084

1 remaining item

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[EHL][BUG]Dmesg shows "ASoC: error at snd_soc_dai_startup on intel-hdmi-hifi1: -16" when do multi-pipleline stress test. #2084

Description

Activity

sinahuang commented on May 8, 2020

sinahuang commented on May 12, 2020

sinahuang commented on May 29, 2020

sinahuang commented on Jun 2, 2020

libinyang commented on Jun 2, 2020

libinyang commented on Jun 2, 2020

sinahuang commented on Jun 2, 2020

1 remaining item

sinahuang commented on Jun 3, 2020

kv2019i commented on Jun 3, 2020

sinahuang commented on Jun 4, 2020

sinahuang commented on Jun 9, 2020

kv2019i commented on Jun 11, 2020

kv2019i commented on Jun 16, 2020

kv2019i commented on Jun 17, 2020

sinahuang commented on Jun 18, 2020

kv2019i commented on Jun 18, 2020

sinahuang commented on Jun 18, 2020

kv2019i commented on Jun 22, 2020

sinahuang commented on Jun 23, 2020

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions