Skip to content

[Bug][CML] ipc timed out for '0x40010000: GLB_PM_MSG: CTX_SAVE' #919

New issue
New issue
Closed
Closed
[Bug][CML] ipc timed out for '0x40010000: GLB_PM_MSG: CTX_SAVE'#919
Assignees
dabekjakub
Labels
CMLApplies to Comet Lake platformHDAApplies to HD-Audio bus for codec connectionIPC timeoutIPC timeout observedbugSomething isn't working

Description

@ClarexZhou
ClarexZhou
opened on May 9, 2019

Summary:
'ipc timed out for for '0x40010000: GLB_PM_MSG: CTX_SAVE' after stop aplay or system reboot.

To reproduce
Scenario A：Do system reboot stress test. Error occurred after system reboot.
Scenario B：Do aplay test several times. Error occurred after Stop aplay

Actual result
error: ipc timed out for 0x40010000: GLB_PM_MSG: CTX_SAVE

Reproduce rate: 1%

Test recipe
Rander UCM https://github.com/RanderWang/intel-UCM  
Kernel repo：c99938c https://github.com/thesofproject/linux/tree/release/sof-v5.0
Firmware repo: 05d4e19 https://github.com/thesofproject/sof/commits/master |  
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

Dmesg log

[   11.396879] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[   11.396881] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[   11.396975] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[   11.397001] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[   35.877875] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[   35.877930] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[   35.912770] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[   36.215604] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76
[   36.215633] sof-audio-pci 0000:00:1f.3: unknown ROM status value ffffffff
[   36.215906] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xffffffff trace 0xffffffff
[   36.215912] sof-audio-pci 0000:00:1f.3: error: ctx_save ipc error during suspend -110
[   36.215929] sof-audio-pci 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -110)

dmesg_failed_129.log
logger_failed_129.log
logger-t_failed_129.log

Activity

  1. ClarexZhou
    added
    bugSomething isn't working
    CMLApplies to Comet Lake platform
    HDAApplies to HD-Audio bus for codec connection
    on May 9, 2019

  2. jason77-wang commented on May 9, 2019

    @jason77-wang
    jason77-wang
    on May 9, 2019

    I met a similar/ same issue last night. the reproduce rate is about 1/10.
    please refer to: https://bugs.launchpad.net/somerville/+bug/1821270/comments/29

  3. mengdonglin
    added
    IPC timeoutIPC timeout observed
    on May 9, 2019
  4. mengdonglin
    assigned
    dabekjakub
    on May 14, 2019

  5. tlauda commented on May 14, 2019

    @tlauda
    tlauda
    on May 14, 2019

    @ClarexZhou FW log is empty.

  6. ClarexZhou commented on May 14, 2019

    @ClarexZhou
    ClarexZhou
    on May 14, 2019
    Author

    @tlauda my mistake. update FW log in original error.

  7. ClarexZhou commented on May 17, 2019

    @ClarexZhou
    ClarexZhou
    on May 17, 2019
    Author

    Error occurred twice during 330 times system reboot stress test on CML latptop.
    No error sof logger.

    [    2.792148] sof-audio-pci 0000:00:1f.3: pcm: close stream 5 dir 0
[    3.237223] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[    3.237249] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[    3.737456] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[    3.737482] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[    4.897436] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[    5.201373] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76
[    5.201391] sof-audio-pci 0000:00:1f.3: unknown ROM status value ffffffff
[    5.201661] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xffffffff trace 0xffffffff
[    5.201673] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x00000000 mask 0x00000003
[    5.201678] sof-audio-pci 0000:00:1f.3: error: ctx_save ipc error during suspend -110
[    5.201693] sof-audio-pci 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -110)
[   34.652614] rfkill: input handler disabled

    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_failed_205.log
    dmesg_failed_216.log
    logger-t_failed_205.log
    logger-t_failed_216.log

  8. YvonneYang2 commented on May 22, 2019

    @YvonneYang2
    YvonneYang2
    on May 22, 2019

    Error occurred once after one time reboot.

    Environment
    Firmware: 5fa2426 https://github.com/thesofproject/sof/tree/master
    Kernel: b58f448 https://github.com/thesofproject/linux/tree/release/sof-v5.0
    Topology: file: tools/topology/sof-hda-generic.tplg, sof-hda-generic-2ch.tplg same as firmware
    Kconfig: https://sof-ci-storage.sh.intel.com/daily/20190521/release/linux/topic/sof-dev/901cd2a5-2/config-daily-hda-20190521.txt
    platform ：CML laptop

    dmesg

    [   61.363397] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[   61.363563] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[   63.630663] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[   63.630711] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[   63.665639] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[   63.968467] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76
[   63.968495] sof-audio-pci 0000:00:1f.3: unknown ROM status value ffffffff
[   63.968819] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xffffffff trace 0xffffffff
[   63.968835] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x00000000 mask 0x00000003
[   63.968840] sof-audio-pci 0000:00:1f.3: error: ctx_save ipc error during suspend -110
[   63.968855] sof-audio-pci 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -110)
[   67.626195] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[   67.626200] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[   67.626203] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[   67.626205] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[   67.626430] sof-audio-pci 0000:00:1f.3: format_val=49, rate=48000, ch=2, format=10
[   67.626467] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 0
[   67.626473] sof-audio-pci 0000:00:1f.3: generating page table for 0000000076ede493 size 0xffc0 pages 16
[   67.626505] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[   67.626512] sof-audio-pci 0000:00:1f.3: periods:4
[   67.626534] sof-audio-pci 0000:00:1f.3: stream_tag 1
[   67.626548] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[   67.626620] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60010000 size 20
[   67.626630] sof-audio-pci 0000:00:1f.3: error: hw params ipc failed for stream 1
[   67.626639] sof-audio-pci 0000:00:1f.3: ASoC: 0000:00:1f.3 hw params failed: -1
[   67.626645]  HDA Analog: ASoC: hw_params FE failed -1
[   67.626664] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0

    reboot_failed.log
    reboot_failed_logger.log

  9. stevyan commented on May 22, 2019

    @stevyan
    stevyan
    on May 22, 2019

    Error occurred when try to paplay/parecord on the CFL RVP HDA.

    Precondition
    pulseaudio enabled.

    To reproduce

    1. paplay music.wav -vvv

    Actual Result

    Opening a playback stream with sample specification 's16le 2ch 48000Hz' and channel map 'front-left,front-right'.
Connection established.
Stream error: Timeout

    Test Recipe
    date: 2019-05-22
    sof (master): 3e423f4
    linux (topic/sof-dev): e3ec7cf
    topology: sof-hda-generic.tplg

    dmesg log

    [   34.084014] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[   34.084149] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[   34.084233] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[   57.379854] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[   57.379897] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[   57.409490] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[   57.714815] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76
[   57.714828] sof-audio-pci 0000:00:1f.3: unknown ROM status value ffffffff
[   57.715097] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xffffffff trace 0xffffffff
[   57.715104] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x00000000 mask 0x00000003
[   57.715107] sof-audio-pci 0000:00:1f.3: error: ctx_save ipc error during suspend -110
[   57.715112] sof-audio-pci 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -110)
[  142.885738] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[  142.885744] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[  142.885747] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[  142.885749] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[  142.885985] sof-audio-pci 0000:00:1f.3: format_val=49, rate=48000, ch=2, format=10
[  142.885997] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 0
[  142.886003] sof-audio-pci 0000:00:1f.3: generating page table for 0000000073ca4684 size 0xffc0 pages 16
[  142.886039] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[  142.886041] sof-audio-pci 0000:00:1f.3: periods:4
[  142.886072] sof-audio-pci 0000:00:1f.3: stream_tag 1
[  142.886084] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[  142.886275] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60010000 size 20
[  142.886283] sof-audio-pci 0000:00:1f.3: error: hw params ipc failed for stream 1
[  142.886290] sof-audio-pci 0000:00:1f.3: ASoC: 0000:00:1f.3 hw params failed: -1
[  142.886297]  HDA Analog: ASoC: hw_params FE failed -1
[  142.886321] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[  142.886326] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  143.194731] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[  143.194750] sof-audio-pci 0000:00:1f.3: unknown ROM status value ffffffff
[  143.195051] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xffffffff trace 0xffffffff
[  143.195074] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  143.195211] sof-audio-pci 0000:00:1f.3: format_val=49, rate=48000, ch=2, format=10
[  143.195226] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 0
[  143.195231] sof-audio-pci 0000:00:1f.3: generating page table for 0000000073ca4684 size 0xffc0 pages 16
[  143.195268] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[  143.195270] sof-audio-pci 0000:00:1f.3: periods:4
[  143.195293] sof-audio-pci 0000:00:1f.3: stream_tag 1

    paplay_failed-dmesg.log
    paplay_failed-slogger.log

  10. ClarexZhou commented on May 24, 2019

    @ClarexZhou
    ClarexZhou
    on May 24, 2019
    Author

    Error occurred on CML laptop after stop aplay during aplay -d 1 stress test in 107th

    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

    No error logger, dmesg as below:

    [  491.358758] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  491.358788] sof-audio-pci 0000:00:1f.3: pcm: close stream 5 dir 0
[  492.375953] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 0
[  492.375972] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  492.376148] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  492.376174] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=0
[  492.376312] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[  492.376323] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  492.376505] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  492.376549] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[  492.376680] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[  492.376830] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[  494.391071] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[  494.699458] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76
[  494.699480] sof-audio-pci 0000:00:1f.3: unknown ROM status value ffffffff
[  494.699805] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xffffffff trace 0xffffffff
[  494.699821] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x00000000 mask 0x00000003
[  494.699829] sof-audio-pci 0000:00:1f.3: error: ctx_save ipc error during suspend -110
[  494.699849] sof-audio-pci 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -110)
[  608.094503] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[  608.094511] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[  608.094516] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[  608.094520] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[  608.099988] sof-audio-pci 0000:00:1f.3: pcm: open stream 5 dir 0
[  608.100015] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[  608.100021] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[  608.100026] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[  608.100165] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[  608.403438] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
[  608.403459] sof-audio-pci 0000:00:1f.3: unknown ROM status value ffffffff
[  608.403783] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xffffffff trace 0xffffffff
[  608.403798] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  608.403805] sof-audio-pci 0000:00:1f.3: error: failed to set dai config for Analog Playback and Capture
[  608.403813] sof-audio-pci 0000:00:1f.3: ASoC: can't set Analog CPU DAI hw params: -110
[  608.403827]  Analog Playback and Capture: ASoC: hw_params BE failed -110
[  608.403833]  HDA Analog: ASoC: hw_params BE failed -110
[  608.403855] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[  608.403863] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  608.707463] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[  608.707484] sof-audio-pci 0000:00:1f.3: unknown ROM status value ffffffff
[  608.707807] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xffffffff trace 0xffffffff
[  608.707822] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  608.707935] HDMI HDA Codec ehdaudio0D2: ASoC: can't set intel-hdmi-hifi3 hw params: -19
[  608.707945]  iDisp3: ASoC: hw_params BE failed -19
[  608.707951]  HDMI3: ASoC: hw_params BE failed -19
[  608.707963] sof-audio-pci 0000:00:1f.3: pcm: free stream 5 dir 0
[  608.707973] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[  609.011465] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60030000 size 12
[  609.011485] sof-audio-pci 0

    aplay_107_dmesg.log

  11. keyonjie commented on May 27, 2019

    @keyonjie
    keyonjie
    on May 27, 2019

    Hi @ClarexZhou can this be reproduced with latest ipc-timeout recipe?

  12. ClarexZhou commented on May 28, 2019

    @ClarexZhou
    ClarexZhou
    on May 28, 2019
    Author

    Error occurred during multipipline stress test after about 13th times. aplay response very slow and can't be played successfully in stress test. Stop stress test then aplay manually, ipc timed out.

    Environment
    Kernel: https://github.com/lyakh/linux/tree/ipc-timeout commit 9453da1 (with PR895)
    FW:https://github.com/lyakh/sof/tree/ipc-timeout commit 47dc14d (with PR1354 and PR1470)
    Kconfig: disable CONFIG_SND_SOC_SOF_DEBUG_ENABLE_DEBUGFS_CACHE in kernel config.

    [  721.439018] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[  721.439023] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[  721.439027] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[  721.439239] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 1
[  721.439247] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[  721.439252] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[  721.439256] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[  721.440281] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[  721.440510] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[  721.440520] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[  721.440526] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[  721.440574] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[  721.440661] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 1
[  721.440789] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 1
[  721.440797] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[  721.440803] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[  721.440808] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[  721.441324] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[  721.441372] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 1
[  735.497689] usb 1-1: new high-speed USB device number 8 using xhci_hcd
[  735.626099] usb 1-1: New USB device found, idVendor=05e3, idProduct=0608, bcdDevice=85.36
[  735.626107] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[  735.626112] usb 1-1: Product: USB2.0 Hub
[  735.627446] hub 1-1:1.0: USB hub found
[  735.627711] hub 1-1:1.0: 4 ports detected
[  735.908684] usb 1-1.1: new high-speed USB device number 9 using xhci_hcd
[  736.000727] usb 1-1.1: New USB device found, idVendor=0b95, idProduct=7720, bcdDevice= 0.01
[  736.000734] usb 1-1.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  736.000739] usb 1-1.1: Product: AX88772A
[  736.000743] usb 1-1.1: Manufacturer: ASIX Elec. Corp.
[  736.000747] usb 1-1.1: SerialNumber: 00044E
[  736.420074] asix 1-1.1:1.0 eth0: register 'asix' at usb-0000:00:14.0-1.1, ASIX AX88772 USB 2.0 Ethernet, 00:0e:c6:b7:2c:16
[  736.484903] usb 1-1.3: new low-speed USB device number 10 using xhci_hcd
[  736.569412] usb 1-1.3: New USB device found, idVendor=046d, idProduct=c063, bcdDevice=57.00
[  736.569421] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  736.569427] usb 1-1.3: Product: DELL USB Laser Mouse
[  736.569431] usb 1-1.3: Manufacturer: DELL
[  736.578137] input: DELL DELL USB Laser Mouse as /devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1.3/1-1.3:1.0/0003:046D:C063.0002/input/input13
[  736.578465] hid-generic 0003:046D:C063.0002: input,hidraw0: USB HID v1.10 Mouse [DELL DELL USB Laser Mouse] on usb-0000:00:14.0-1.3/input0
[  736.597491] asix 1-1.1:1.0 enx000ec6b72c16: renamed from eth0
[  737.982472] IPv6: ADDRCONF(NETDEV_CHANGE): enx000ec6b72c16: link becomes ready
[  737.985981] asix 1-1.1:1.0 enx000ec6b72c16: link up, 100Mbps, full-duplex, lpa 0xCDE1
[  789.781781] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 1
[  789.781790] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[  789.781794] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[  789.781798] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[  789.781993] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[  789.782000] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[  789.782004] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[  789.782008] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[  789.782879] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 1
[  789.783235] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[  821.283144] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  821.283176] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  821.306963] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[  821.612004] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76
[  821.612014] sof-audio-pci 0000:00:1f.3: unknown ROM status value ffffffff
[  821.612349] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0xffffffff trace 0xffffffff
[  821.612357] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x00000000 mask 0x00000003
[  821.612358] sof-audio-pci 0000:00:1f.3: error: ctx_save ipc error during suspend -110
[  821.612363] sof-audio-pci 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -110)
[  901.919021] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[  901.919029] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[  901.919033] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[  901.919036] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[  901.919962] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0

    mulitpipline_13_dmesg.log
    mulitpipline_13_logger_all.log

  13. YvonneYang2 commented on May 29, 2019

    @YvonneYang2
    YvonneYang2
    on May 29, 2019

    Issue occurred after finishing the 300 times s3 without playback test.

    Test recipe
    date: 2019-05-29
    sof (master): b4d292d
    linux (topic/sof-dev): d1008d1
    topology: sof-apl-nocodec.tplg
    platform: cd-apl-up2-nocodec-03

    dmesg

    [ 6286.046204] PM: suspend entry (deep)
[ 6286.046486] Filesystems sync: 0.000 seconds
[ 6286.046824] Freezing user space processes ... (elapsed 0.002 seconds) done.
[ 6286.049091] OOM killer disabled.
[ 6286.049092] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 6286.050255] printk: Suspending console(s) (use no_console_suspend to debug)
[ 6286.050853] r8169 0000:02:00.0 enp2s0: Link is Down
[ 6286.051110] sof-audio-pci 0000:00:0e.0: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 6286.356173] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x40010000 size 76
[ 6286.356185] sof-audio-pci 0000:00:0e.0: unknown ROM status value 01006701
[ 6286.356227] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x001d003c trace 0x00000000
[ 6286.356234] sof-audio-pci 0000:00:0e.0: error: host status 0x00420000 dsp status 0x00000000 mask 0x00000000
[ 6286.356239] sof-audio-pci 0000:00:0e.0: error: ctx_save ipc error during suspend -110
[ 6286.356256] PM: pci_pm_suspend(): snd_sof_suspend+0x0/0x10 [snd_sof] returns -110
[ 6286.356266] PM: dpm_run_callback(): pci_pm_suspend+0x0/0x120 returns -110
[ 6286.356272] PM: Device 0000:00:0e.0 failed to suspend: error -110
[ 6286.356278] PM: Some devices failed to suspend, or early wake event detected
[ 6286.440212] r8169 0000:03:00.0 enp3s0: Link is Down
[ 6286.442633] OOM killer enabled.
[ 6286.442636] Restarting tasks ... done.
[ 6286.446773] video LNXVIDEO:00: Restoring backlight state
[ 6286.446824] PM: suspend exit
[ 6286.462569] rfkill: input handler enabled
[ 6286.476665] rfkill: input handler disabled
[ 6286.669045] ata2: SATA link down (SStatus 4 SControl 300)
[ 6286.669099] ata1: SATA link down (SStatus 4 SControl 300)
[ 6288.486285] sof-audio-pci 0000:00:0e.0: pcm: open stream 0 dir 0
[ 6288.486290] sof-audio-pci 0000:00:0e.0: period min 192 max 16384 bytes
[ 6288.486292] sof-audio-pci 0000:00:0e.0: period count 2 max 16
[ 6288.486294] sof-audio-pci 0000:00:0e.0: buffer max 65536 bytes
[ 6288.486628] sof-audio-pci 0000:00:0e.0: rate_min: 48000 rate_max: 48000
[ 6288.486631] sof-audio-pci 0000:00:0e.0: channels_min: 2 channels_max: 2
[ 6288.486634] sof-audio-pci 0000:00:0e.0: rate_min: 48000 rate_max: 48000
[ 6288.486636] sof-audio-pci 0000:00:0e.0: channels_min: 2 channels_max: 2
[ 6288.486639] sof-audio-pci 0000:00:0e.0: rate_min: 48000 rate_max: 48000
[ 6288.486641] sof-audio-pci 0000:00:0e.0: channels_min: 2 channels_max: 2
[ 6288.486645] sof-audio-pci 0000:00:0e.0: pcm: hw params stream 0 dir 0

    s3_without_playback_500_dmesg.log
    s3_without_playback_500_logger.log

  14. kv2019i commented on Jun 14, 2019

    @kv2019i
    kv2019i
    on Jun 14, 2019
    Collaborator

    @ClarexZhou Can this be closed?

    As per recent test result, no timeouts should be observed anymore in the original scenarios of this bug:

    ""Scenario A：Do system reboot stress test. Error occurred after system reboot.
    Scenario B：Do aplay test several times. Error occurred after Stop aplay""

  15. ClarexZhou commented on Jun 17, 2019

    @ClarexZhou
    ClarexZhou
    on Jun 17, 2019
    Author

    Close for not reproduced on sof-dev 96033e6

  16. ClarexZhou
    closed this as completedon Jun 17, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

CMLApplies to Comet Lake platformHDAApplies to HD-Audio bus for codec connectionIPC timeoutIPC timeout observedbugSomething isn't working

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions