search

thesofproject / linux

Linux kernel source tree
Other
91 stars 131 forks source link

ipc timed out with closed-source firmware on WHL_UPEXT #3678

Closed XiaoyunWu6666 closed 2 years ago

XiaoyunWu6666 commented 2 years ago

Description Intel internal tests show failures for model=WHL_UPEXT_HDA_IPC4&testcase=multiple-pipeline-capture-50.sh in inner daily 13032 ipc timed out while processing the request of ipc4 unbind modules copier.host.9.1 -> copier.HDA.10.1

Haven't reproduced it so far ,will provide more info after managing to reproduce it

Test Recipe Kernel Branch: topic/sof-dev Kernel Commit: 2ce729e6af8e FW: cavs fw

Log During a series of sof_ipc4_route_free , unbind modules copier.host.5.1 -> copier.HDA.6.1 and unbind modules copier.host.7.1 -> copier.HDA.8.1,etc succeeded ,but when it comes to unbind modules copier.host.9.1 -> copier.HDA.10.1 , ipc time out happened [dmesg]

[ 3097.162741] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_route_free: unbind modules copier.host.9.1 -> copier.HDA.10.1
[ 3097.162747] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx      : 0x46060004|0x70004: MOD_UNBIND
[ 3097.162771] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.162774] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.162776] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.162811] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.162814] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.162816] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.162851] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.162854] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.162856] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.162886] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.162889] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.162891] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.162926] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.162929] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.162931] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.162965] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.162968] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.162970] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163004] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163007] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.163009] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163042] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163044] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.163047] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163080] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163082] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.163084] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163118] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163121] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.163123] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163158] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163161] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.163163] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163198] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163200] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.163203] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163236] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163238] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.163241] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163274] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163276] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.163279] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163346] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163349] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.163351] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163385] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163388] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.163390] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163423] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163426] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.163428] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163464] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163466] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.163468] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163502] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163504] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.163507] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163540] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.163542] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: sof_ipc4_rx_msg: Unhandled DSP message: 0x1b0a0000|0x4060
[ 3097.163545] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x4060: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 3097.669366] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc timed out for 0x46060004|0x70004
[ 3097.669516] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: failed to unbind modules copier.host.9.1 -> copier.HDA.10.1
[ 3097.669533] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx      : 0x12090000|0x0: GLB_DELETE_PIPELINE
[ 3098.174394] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc timed out for 0x12090000|0x0
[ 3098.174405] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: failed to free pipeline widget pipeline.9
[ 3098.174414] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx      : 0x120a0000|0x0: GLB_DELETE_PIPELINE
[ 3098.677431] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc timed out for 0x120a0000|0x0
[ 3098.677446] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: failed to free pipeline widget pipeline.10
[ 3098.677452] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: Failed to free connected widgets
[ 3098.677463] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_free on 0000:00:1f.3: -110
XiaoyunWu6666 commented 2 years ago

ipc error when trying to set pipeline state see inner result 13238 model WHL_UPEXT_HDA_IPC4 testcase check-pause-resume-playback-100)

[ 1732.074348] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc4 set pipeline 1 state 4
[ 1732.074352] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx      : 0x13010004|0x0: GLB_SET_PIPELINE_STATE
[ 1732.074667] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx reply: 0x33000000|0x0: GLB_SET_PIPELINE_STATE
[ 1732.075041] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx done : 0x13010004|0x0: GLB_SET_PIPELINE_STATE
[ 1732.075046] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc4 set pipeline 2 state 4
[ 1732.075050] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx      : 0x13020004|0x0: GLB_SET_PIPELINE_STATE
[ 1732.075262] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx reply: 0x33000000|0x0: GLB_SET_PIPELINE_STATE
[ 1732.075364] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx done : 0x13020004|0x0: GLB_SET_PIPELINE_STATE
[ 1732.075373] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc4_hda_dai_trigger: cmd=4 dai Analog CPU DAI direction 0
[ 1732.075383] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc4_hda_dai_trigger: cmd=0 dai Analog CPU DAI direction 0
[ 1732.075385] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc4 set pipeline 2 state 3
[ 1732.075387] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx      : 0x13020003|0x0: GLB_SET_PIPELINE_STATE
[ 1732.075825] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx reply: 0x33000000|0x0: GLB_SET_PIPELINE_STATE
[ 1732.076338] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx done : 0x13020003|0x0: GLB_SET_PIPELINE_STATE
[ 1732.076345] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc4 set pipeline 2 state 2
[ 1732.076348] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx      : 0x13020002|0x0: GLB_SET_PIPELINE_STATE
[ 1732.076479] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx reply: 0x33000006|0x2: GLB_SET_PIPELINE_STATE
[ 1732.076483] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: FW reported error: 6 - Unknown error while processing the request
[ 1732.077329] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc error for msg 0x13020002|0x0
[ 1732.077334] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ASoC: error at soc_dai_trigger on Analog CPU DAI: -22
[ 1732.077338] kernel:  HDA Analog: ASoC: dpcm_be_dai_trigger() failed at Analog Playback and Capture (-22)
[ 1732.077341] kernel:  HDA Analog: ASoC: trigger FE cmd: 0 failed: -22

But I haven't been able to reproduce it yet

keqiaozhang commented 2 years ago

We haven't seem this issue in CI for more than 2 months, @XiaoyunWu6666 can we close it?

XiaoyunWu6666 commented 2 years ago

ipc error when resetting pipeline (setting state 2) in inner testresult 14490 and 14386 14324 14301 14217 14196 ... [7 hits within past 30 days] on WHL_UPEXT_HDA_IPC4 when multiple-pause-resume-50 And this actually was identified as https://github.com/thesofproject/linux/issues/3626 which describe ipc error with FWeported error: 6 - Unknown error while processing the request when resetting pipeline

[dmesg]

[ 2313.984870] kernel: snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc4 set pipeline 23 state 3
[ 2313.984874] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx      : 0x13170003|0x0: GLB_SET_PIPELINE_STATE
[ 2313.985419] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx reply: 0x33000000|0x0: GLB_SET_PIPELINE_STATE
[ 2313.985435] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx done : 0x13170003|0x0: GLB_SET_PIPELINE_STATE
[ 2313.985440] kernel: snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc4 set pipeline 23 state 2
[ 2313.985443] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx      : 0x13170002|0x0: GLB_SET_PIPELINE_STATE
[ 2313.985685] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx reply: 0x33000006|0x17: GLB_SET_PIPELINE_STATE
[ 2313.985691] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: FW reported error: 6 - Unknown error while processing the request
[ 2313.985712] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc error for msg 0x13170002|0x0
[ 2313.985716] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ASoC: error at soc_dai_trigger on iDisp2 Pin: -22
[ 2313.985721] kernel:  HDMI2: ASoC: dpcm_be_dai_trigger() failed at iDisp2 (-22)
[ 2313.985724] kernel:  HDMI2: ASoC: trigger FE cmd: 0 failed: -22
[ 2313.985738] kernel: snd_sof:sof_pcm_hw_free: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: free stream 6 dir 0
[ 2313.985742] kernel: snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc4 set pipeline 22 state 3
[ 2313.985747] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx      : 0x13160003|0x0: GLB_SET_PIPELINE_STATE
[ 2313.985999] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx reply: 0x33000000|0x0: GLB_SET_PIPELINE_STATE
[ 2313.986016] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx done : 0x13160003|0x0: GLB_SET_PIPELINE_STATE
[ 2313.986020] kernel: snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc4 set pipeline 22 state 2
[ 2313.986024] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx      : 0x13160002|0x0: GLB_SET_PIPELINE_STATE
[ 2313.986519] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx reply: 0x33000000|0x0: GLB_SET_PIPELINE_STATE
[ 2313.986677] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx done : 0x13160002|0x0: GLB_SET_PIPELINE_STATE
[ 2313.986695] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-cnl 0000:00:1f.3: unbind modules copier.host.22.1 -> copier.HDA.23.1
XiaoyunWu6666 commented 2 years ago

And actually the ipc timed out described by this issue became rare. We haven't seem ipc time out issue in CI for more than 2 months, so we can close it. @keqiaozhang thanks for reminding.