Repository navigation
[BUG][CML]ipc timed out for 0x80010000: GLB_DAI_MSG: CONFIG after system boot up.(intermittent) #1422
Description
Describe the bug
sudo reboot to do system reboot, ipc timed out for 0x80010000: GLB_DAI_MSG: CONFIG after system boot up.
To Reproduce
sudo reboot to do system reboot
Expected behavior
Bootup without any issues.
Impact
IPC timed out.
Environment
platform: CML laptop with ALC3204 codec
Rander UCM https://github.com/RanderWang/intel-UCM
Kernel repo：9494607 https://github.com/thesofproject/linux/tree/release/sof-v5.0
Firmware repo: b73b9a6 https://github.com/thesofproject/sof/commits/master +PR1354
Topology: https://github.com/thesofproject/sof/commits/master . Same as above SOF repo
file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg
Error sof-logger:
CORE LEVEL COMP_ID TIMESTAMP DELTA FILE_NAME CONTENT
0 1 DMA 4499110.468750 4499110.500000 intel/cavs/hda-dma.c:616 hda-dmac: 5 invalid channel -1
Dmesg:
[ 3.370305] usb 1-4: Manufacturer: VIA Technologies Inc.
[ 3.370306] usb 1-4: SerialNumber: 0000000000000001
[ 3.411256] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 3.411279] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 3.662275] usb 1-6: new high-speed USB device number 5 using xhci_hcd
[ 3.747224] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 5:0
[ 3.761690] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 6:0
[ 3.812804] usb 1-6: New USB device found, idVendor=0bda, idProduct=5538, bcdDevice=88.07
[ 3.812810] usb 1-6: New USB device strings: Mfr=3, Product=1, SerialNumber=2
[ 3.812814] usb 1-6: Product: Integrated_Webcam_HD
[ 3.812818] usb 1-6: Manufacturer: CKFHH66O4634000251A0
[ 3.812820] usb 1-6: SerialNumber: 200901010001
[ 3.929218] usb 1-10: new full-speed USB device number 6 using xhci_hcd
[ 4.057287] usb 1-10: New USB device found, idVendor=8087, idProduct=0aaa, bcdDevice= 0.02
[ 4.057295] usb 1-10: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 4.445659] ax88179_178a 1-3:1.0 eth0: register 'ax88179_178a' at usb-0000:00:14.0-3, ASIX AX88179 USB 3.0 Gigabit Ethernet, 00:0e:c6:a1:e5:69
[ 4.445755] usbcore: registered new interface driver ax88179_178a
[ 4.453208] ax88179_178a 1-3:1.0 enx000ec6a1e569: renamed from eth0
[ 4.798306] systemd-udevd (1694) used greatest stack depth: 11912 bytes left
[ 5.602555] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[ 5.602561] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 5.602564] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 5.602566] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 5.602840] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 5.903485] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
[ 5.903508] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 5.903737] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 5.903747] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x00000000 mask 0x00000003
[ 5.903751] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 5.903757] sof-audio-pci 0000:00:1f.3: error: failed to set dai config for Analog Playback and Capture
[ 5.903762] sof-audio-pci 0000:00:1f.3: ASoC: can't set Analog CPU DAI hw params: -110
[ 5.903777] Analog Playback and Capture: ASoC: hw_params BE failed -110
[ 5.903781] HDA Analog: ASoC: hw_params BE failed -110
[ 5.903794] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[ 5.903800] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6.207484] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[ 6.207510] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 6.207806] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 6.207819] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x00000000 mask 0x00000003
[ 6.207823] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 6.208005] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 6.511317] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
[ 6.511343] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 6.511639] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 6.511652] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x90020000 mask 0x00000003
[ 6.511656] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 6.511661] sof-audio-pci 0000:00:1f.3: error: failed to set dai config for Analog Playback and Capture
[ 6.511667] sof-audio-pci 0000:00:1f.3: ASoC: can't set Analog CPU DAI hw params: -110
[ 6.511679] Analog Playback and Capture: ASoC: hw_params BE failed -110
[ 6.511683] HDA Analog: ASoC: hw_params BE failed -110
[ 6.511695] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[ 6.511702] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6.815515] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[ 6.815541] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 6.815837] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 6.815850] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x90020000 mask 0x00000003
[ 6.815854] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 6.816020] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 7.119267] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
[ 7.119293] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 7.119589] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 7.119602] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x90020000 mask 0x00000003
[ 7.119608] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 7.119619] sof-audio-pci 0000:00:1f.3: error: failed to set dai config for Analog Playback and Capture
[ 7.119624] sof-audio-pci 0000:00:1f.3: ASoC: can't set Analog CPU DAI hw params: -110
[ 7.119637] Analog Playback and Capture: ASoC: hw_params BE failed -110
[ 7.119640] HDA Analog: ASoC: hw_params BE failed -110
[ 7.119653] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[ 7.119659] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 7.423366] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[ 7.423392] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 7.423687] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 7.423700] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x90020000 mask 0x00000003
[ 7.423704] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 7.423859] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 7.727527] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
[ 7.727552] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 7.727848] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 7.727862] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x90020000 mask 0x00000003
[ 7.727865] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 7.727871] sof-audio-pci 0000:00:1f.3: error: failed to set dai config for Analog Playback and Capture
[ 7.727877] sof-audio-pci 0000:00:1f.3: ASoC: can't set Analog CPU DAI hw params: -110
[ 7.727899] Analog Playback and Capture: ASoC: hw_params BE failed -110
[ 7.727902] HDA Analog: ASoC: hw_params BE failed -110
[ 7.727915] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[ 7.727921] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 7.806992] ax88179_178a 1-3:1.0 enx000ec6a1e569: ax88179 - Link status is: 1
[ 7.813584] IPv6: ADDRCONF(NETDEV_CHANGE): enx000ec6a1e569: link becomes ready
[ 8.031476] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[ 8.031502] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 8.031798] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 8.031811] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x90020000 mask 0x00000003
[ 8.031815] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 8.031984] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 8.335541] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
[ 8.335565] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 8.335861] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 8.335875] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x90020000 mask 0x00000003
[ 8.335878] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 8.335883] sof-audio-pci 0000:00:1f.3: error: failed to set dai config for Analog Playback and Capture
[ 8.335888] sof-audio-pci 0000:00:1f.3: ASoC: can't set Analog CPU DAI hw params: -110
[ 8.335899] Analog Playback and Capture: ASoC: hw_params BE failed -110
[ 8.335903] HDA Analog: ASoC: hw_params BE failed -110
[ 8.335914] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[ 8.335919] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 8.639551] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[ 8.639576] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 8.639871] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 8.639883] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x90020000 mask 0x00000003
[ 8.639886] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 8.640070] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[ 8.640481] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[ 8.640486] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 8.640488] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 8.640490] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 8.640687] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 8.943323] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
[ 8.943348] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 8.943643] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace
Activity
[-][BUG][CML]ipc timed out for 0x80010000: GLB_DAI_MSG: CONFIG after system boot up.[/-][+][BUG][CML]ipc timed out for 0x80010000: GLB_DAI_MSG: CONFIG after system boot up.(intermittent)[/+]ClarexZhou commentedon May 14, 2019
Error occurred twice (2nd time reload and the 34th reload)during modules reload test on cml laptop.
Error logger
logger_all.log
boot_fail.log
tlauda commentedon May 14, 2019
@ClarexZhou Please retest without #1354 applied.
YvonneYang2 commentedon May 15, 2019
Error occurred once when do reboot stress test 53 times on CFL.
ENV
Rander UCM https://github.com/RanderWang/intel-UCM
Kernel repo：9494607 https://github.com/thesofproject/linux/tree/release/sof-v5.0
Firmware repo: b73b9a6 https://github.com/thesofproject/sof/commits/master +PR1354
Topology: https://github.com/thesofproject/sof/commits/master . Same as above SOF repo
file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg
platform: CFL laptop with ALC3254 codec
Error logger
dmesg_failed_52.log
logger-t_failed_52.log
ranj063 commentedon May 22, 2019
@ClarexZhou @YvonneYang2 the recipe used for this issue is incorrect. You cannot use FW PR 1354 without taking kernel PR 895. Please repeat this test by either taking both or removing both.
lgirdwood commentedon May 22, 2019
@mengdonglin can we also retest with trace disabled here too.
ClarexZhou commentedon May 23, 2019
0x80010000: GLB_DAI_MSG: CONFIG ipc timed out occurred during aplay -d 1 stress test. System response very slow then ipc timed out.
Environment
disable CONFIG_SND_SOC_SOF_DEBUG_ENABLE_DEBUGFS_CACHE in kernel config.
Kernel:
https://github.com/lyakh/linux/tree/ipc-timeout
commit 5969756 ASoC: SOF: hda: couple host and link DMA during FE hw_free , PR 895
FW:
https://github.com/lyakh/sof/tree/ipc-timeout
commit: b527fd7 dai: assign/free link DMA channel during dai_config() , PR1354
wasp_aplay_dmesg_18.log
wasp_aplay_errorlogger_18.log
wasp_aplay_soflogger_18.log
wasp_aplay_dmesg_18.log
wasp_aplay_errorlogger_18.log
wasp_aplay_soflogger_18.log
ranj063 commentedon May 24, 2019
@lyakh I think we have another race here. The pattern I see in my tests with aplay stress test is that the with successive DAI_CONFIG IPC's sent, one of them at some point times out. I also think this ipc timeout might be related to the the one seen in thesofproject/linux#958.
ranj063 commentedon May 24, 2019
this is the patter I'm noticing with the aplay -d 1 stress test.
For all the iterations that pass, pcm open happens right after the previous aplay closes. But when the failure occurs, there's a long delay between when the previous stream closes and the next one begins. Here's an example taken from the above logs:
[ 977.918441] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[ 978.825222] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 978.825249] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
----> a delay of almost 80s. looks like the system hung here.
[ 1058.761508] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[ 1058.761516] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 1058.761521] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 1058.761525] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 1058.762286] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 1059.067585] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
keyonjie commentedon May 24, 2019
@ranj063 can you paste the sof-logger log and dmesg log for the previous(the one at 978.xx second) iteration? It might already has something failed there.
ranj063 commentedon May 24, 2019
Finally, I have a glimmer of hope here, disabling runtime PM for the HDA codec device ehdaudio0D0 allows me to run the test successfully for 1K iterations
ClarexZhou commentedon May 24, 2019
Error occurred at 6th S3 with playback stress test. Also add previous log
Environment
Kernel: 9453da1 https://github.com/lyakh/linux/tree/ipc-timeout (with PR895)
FW:b527fd7 https://github.com/lyakh/sof/tree/ipc-timeout (with PR1354)
Topology:Same as above FW repo, file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg
kconfig:
unset CONFIG_SND_SOC_SOF_DEBUG_ENABLE_FIRMWARE_TRACE
unset CONFIG_SND_SOC_SOF_DEBUG_ENABLE_DEBUGFS_CACHE
6th error logger
6th dmesg
5th dmesg and no error logger
s3_test_5_dmesg.log
s3_test_6_dmesg.log
s3_test_6_logger_error.log
ClarexZhou commentedon May 24, 2019
Error still occurred after merge thesofproject/linux#977
Environment
Kernel: 9453da1 https://github.com/lyakh/linux/tree/ipc-timeout (with PR895) +PR977
FW:b527fd7 https://github.com/lyakh/sof/tree/ipc-timeout (with PR1354)
Topology:Same as above FW repo, file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg
kconfig:
unset CONFIG_SND_SOC_SOF_DEBUG_ENABLE_FIRMWARE_TRACE
unset CONFIG_SND_SOC_SOF_DEBUG_ENABLE_DEBUGFS_CACHE
wasp_s3_test_9_dmesg.log
wasp_s3_test_9_logger_error.log
ClarexZhou commentedon May 24, 2019
occurred again during S3 with playback stress test in 8th.
s3_test_8_logger_error.log
test_7.log
test_8.log
lgirdwood commentedon May 24, 2019
@ranj063 @kv2019i @lyakh I see this in every test from @ClarexZhou
[ 116.160468] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x00000000 mask 0x00000003Even when TRACE is OFF.
But the it looks like IPC dump is invalid for CAVS 1.8
Since the registers are different between APL and CML. The dump code above is for APL.
xiulipan commentedon May 27, 2019
@lgirdwood
We have different for cavs1.8 in cnl.c
https://github.com/thesofproject/linux/blob/924347de73e488fa21772af90566821694dcce55/sound/soc/sof/intel/cnl.c#L165-L181
keyonjie commentedon May 27, 2019
@ranj063's Kernel PR thesofproject/linux#977 fixed this issue for me.
lgirdwood commentedon May 28, 2019
@xiulipan ok great, thanks for checking. It is probably worth a comment in the generically named version to state it's for 1.5 only.
xiulipan commentedon May 28, 2019
@lgirdwood
Yes, the hda.c is actually a very misleading file name. We need some comments inline to identify what these files actually for.
lgirdwood commentedon May 28, 2019
@xiulipan agreed, we do have differences in IP between version 1.5, 1.8 and 2.x so having some comments to describe which version that file/function is for would avoid any confusion going onwards. Can you create a feature request for this ?
xiulipan commentedon May 29, 2019
@lgirdwood @plbossart
Done with thesofproject/linux#987
We need some explanation about what is the mapping.
wenqingfu commentedon Jun 19, 2019
not reproducible after the thesofproject/linux#1013 et al.