Repository navigation
[CML][Bug] IPC timed out for 0x60030000: GLB_STREAM_MSG: PCM_FREE in system reboot test #958
Description
Summary:
IPC timed out for 0x60030000: GLB_STREAM_MSG: PCM_FREE in system reboot test
To reproduce
Run ./test-reboot.sh 330 to do system reboot stress test, check dmesg once boot up during system reboot test.
Actual result
IPC timed out for 0x60030000: GLB_STREAM_MSG: PCM_FREE
Expect result
Boot up successfully without any ipc timed out issue.
Reproduce rate: 2/330
Environment
Kernel: linux-image-ipc_only.deb https://drive.google.com/drive/folders/16DI8IFPIGf-xjHw2n-5iVPwnkIyB-jpc?usp=sharing
Firmware repo: b73b9a6 https://github.com/thesofproject/sof/tree/debug-ipc-timeout
Topology: https://github.com/thesofproject/sof/tree/debug-ipc-timeout . Same as above SOF repo
file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg
Dmesg:
[47303.392229] IPv6: ADDRCONF(NETDEV_CHANGE): enx000ec6b72c8c: link becomes ready
[47303.395439] asix 1-1.1:1.0 enx000ec6b72c8c: link up, 100Mbps, full-duplex, lpa 0xCDE1
[47361.113405] sof-audio-pci 0000:00:1f.3: pcm: open stream 5 dir 0
[47361.113412] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[47361.113416] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[47361.113419] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[47361.113709] HDMI HDA Codec ehdaudio0D2: ASoC: can't set intel-hdmi-hifi3 hw params: -19
[47361.113719] iDisp3: ASoC: hw_params BE failed -19
[47361.113723] HDMI3: ASoC: hw_params BE failed -19
[47361.113729] sof-audio-pci 0000:00:1f.3: pcm: free stream 5 dir 0
[47361.113780] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[47361.416107] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[47361.416127] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[47361.416401] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[47361.416416] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[47361.416444] WARNING: CPU: 2 PID: 2271 at /usr/local/src/project/51/src/linux/kernel/workqueue.c:3030 __flush_work+0x150/0x180
[47361.416446] Modules linked in: asix usbnet snd_soc_skl_hda_dsp snd_soc_hdac_hdmi snd_soc_dmic snd_hda_codec_realtek snd_hda_codec_generic sof_pci_dev snd_sof_intel_hda_common iwlmvm snd_soc_hdac_hda snd_sof_intel_hda snd_sof_intel_byt snd_soc_acpi_intel_match snd_sof_intel_ipc snd_sof snd_sof_xtensa_dsp snd_soc_acpi snd_hda_ext_core snd_soc_core snd_hda_codec x86_pkg_temp_thermal snd_hwdep intel_powerclamp snd_hda_core snd_pcm iwlwifi processor_thermal_device intel_soc_dts_iosf mei_me intel_lpss_pci mei intel_lpss mfd_core intel_pch_thermal int3403_thermal int340x_thermal_zone int3400_thermal acpi_thermal_rel efivarfs xhci_pci sdhci_pci cqhci xhci_hcd sdhci
[47361.416495] CPU: 2 PID: 2271 Comm: pulseaudio Tainted: G W 5.1.0+ #32
[47361.416497] Hardware name: Dell Inc. Vostro 5391/, BIOS 0.1.4 05/02/2019
[47361.416505] RIP: 0010:__flush_work+0x150/0x180
error sof logger:
CORE LEVEL COMP_ID TIMESTAMP DELTA FILE_NAME CONTENT
0 1 COMP 209205371.927083 209205376.000000 rc/audio/component.c:140 comp_set_state() error: wrong state = 1, COMP_TRIGGER_START
0 1 IPC 209205378.125000 6.197917 src/audio/pipeline.c:606 pipeline_trigger() error: ret = -22, host->comp.id = 1, cmd = 1
0 1 IPC 209205385.000000 6.875000 src/ipc/handler.c:513 ipc: comp 1 trigger 0x40000 failed -22
0 1 COMP 209586980.937500 381595.937500 rc/audio/component.c:161 comp_set_state() error: wrong state = 1, COMP_TRIGGER_STOP
0 1 IPC 209586986.822917 5.885417 src/audio/pipeline.c:606 pipeline_trigger() error: ret = -22, host->comp.id = 1, cmd = 0
0 1 IPC 209586993.593750 6.770833 src/ipc/handler.c:513 ipc: comp 1 trigger 0x50000 failed -22
dmesg_failed_1.log
dmesg_failed_235.log
logger-t_failed_1.log
logger-t_failed_235.log
Activity
lyakh commentedon May 17, 2019
A full dmesg output is needed, attached logs are truncated
lyakh commentedon May 20, 2019
This looks like a duplicate of #932 to me
ranj063 commentedon May 20, 2019
@ClarexZhou where is this is test-reboot.sh test script?
ClarexZhou commentedon May 21, 2019
@ranj063 attach test script and need add this sh file to system startup application first.
Also you can find all stress test scripts from https://gitlab.devtools.intel.com/sof-ci/sofcitest/tree/master/sof-test-suites/stress-test
test-reboot.sh.txt
ranj063 commentedon May 21, 2019
Thanks @ClarexZhou
ranj063 commentedon May 22, 2019
@lyakh there's something very stange in the logs for this one. Why do have the call trace printed and besides the timeout seems to happen after hw_Params fails. So I am not sure which happens first. hw_params failure or the pcm_free ipc timeout.
ClarexZhou commentedon May 23, 2019
0x60030000: GLB_STREAM_MSG: PCM_FREE ipc timed out occurred during aplay stress test.
Env.
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
aplay_23_all_error_logger.log
aplay_23_all_logger.log
aplay_23_dmesg.log
ranj063 commentedon May 24, 2019
I have some more info now. The 80s long time interval between pcm close and the next open is caused by the hdac_codec runtime suspend and resume. The codec_display_power() calls in the 2 runtime PM callbacks take a really long time randomly. Removing this helps with reducing the gap.
ClarexZhou commentedon May 24, 2019
Error occurred on CFL laptop aplay -d 1 stress test in 16th. System response very slow first then ipc timed out
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
aplay_error_16_dmesg.log
aplay_error_16_logger_error.log
lyakh commentedon Jun 3, 2019
I was thinking whether such long delays could have been caused by deadlocks due to the wrong use of spin_lock() instead of spin_lock_irq(), but I don't think that could be the case: such a lockup would stay forever, it wouldn't just take a couple of seconds.
wenqingfu commentedon Jun 25, 2019
not reproducible after #1013 et al.