Skip to content

[BUG] Various IPC timed out with multi-core run simultaneously #7774

Closed

Description

@keqiaozhang

Describe the bug
We enabled multi-core tplg in CI and observed that it doesn't support 3 cores run at the same time. It failed with IPC timed out 0x40030004|MOD_INIT_INSTANCE.

dmesg

[ 2398.696058] kernel: snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-mtl 0000:00:1f.3: Create widget dai-copier.SSP.NoCodec-2.playback instance 3 - pipe 6 - core 2
[ 2398.696064] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x40030004|0x203002f: MOD_INIT_INSTANCE [data size: 188]
[ 2399.201595] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x40030004|0x203002f
[ 2399.201612] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 2399.201618] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 2399.201643] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0xc0030004|0x203002f|0x0, target: 0x40030004|0x203002f|0x0, ctl: 0x3
[ 2399.201650] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 2399.201655] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 2399.201659] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
[ 2399.201663] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 2399.201677] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0x5, ROM error: 0x0
[ 2399.201682] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
[ 2399.201689] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit enabled
[ 2399.201693] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------

To Reproduce
TPLG=/lib/firmware/intel/sof-ace-tplg/sof-mtl-nocodec-multicore.tplg MODEL=MTLP_RVP_NOCODEC_MULTICORE ~/sof-test/test-case/multiple-pipeline.sh -f p -l 50

Reproduction Rate
30%

Environment

  1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
  2. Name of the topology file
    • Topology: {sof-ace-tplg/sof-mtl-nocodec-multicore.tplg}
  3. Name of the platform(s) on which the bug is observed.
    • Platform: {MTL-NOCODEC-MULTICORE}

dmesg.txt
mtrace.txt

Activity

  1. added
    bugSomething isn't working as expected
    multicoreIssues observed when not only core#0 is used.
    MTLApplies to Meteor Lake platform
    P2Critical bugs or normal features
    multicore-3coresIssues observed when 3 cores are used.
    and removed
    multicoreIssues observed when not only core#0 is used.
    on Jun 9, 2023
  2. keqiaozhang commented on Jun 21, 2023

    @keqiaozhang
    CollaboratorAuthor

    New errors in CI. Test ID:28022

    [ 2375.146587] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x45020003|0x50006: MOD_BIND
    [ 2375.146874] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x65000000|0x50006: MOD_BIND
    [ 2375.146904] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x45020003|0x50006: MOD_BIND
    [ 2375.146916] kernel: snd_sof:sof_ipc4_route_setup: sof-audio-pci-intel-mtl 0000:00:1f.3: bind gain.4.1:0 -> dai-copier.SSP.NoCodec-1.playback:0
    [ 2375.146921] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x45050006|0x50004: MOD_BIND
    [ 2375.651700] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x45050006|0x50004
    [ 2375.651719] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
    [ 2375.651724] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
    [ 2375.651745] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0x45050006|0x50004|0x0, target: 0x45050006|0x50004|0x0, ctl: 0x3
    [ 2375.651753] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
    [ 2375.651758] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
    [ 2375.651762] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
    [ 2375.651767] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
    [ 2375.651781] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0x5, ROM error: 0x0
    [ 2375.651786] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
    [ 2375.651793] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit enabled
    [ 2375.651797] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
    [ 2375.651816] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: failed to bind modules gain.4.1:0 -> dai-copier.SSP.NoCodec-1.playback:0
    
    [  471.356100] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x11060002|0x0: GLB_CREATE_PIPELINE
    [  471.523624] kernel: snd_sof:sof_pcm_trigger: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 0
    [  471.523642] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-mtl 0000:00:1f.3: trigger cmd: 0 state: 3
    [  471.859109] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x11060002|0x0
    [  471.859131] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
    [  471.859155] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: failed to create module pipeline.10
    [  471.859169] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Failed to set up connected widgets
    [  471.859181] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13000003|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
    [  471.859186] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: error: failed widget list set up for pcm 1 dir 1
    [  471.859197] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_params on 0000:00:1f.3: -110
    [  471.859236] kernel:  Port1: ASoC: error at __soc_pcm_hw_params on Port1: -110
    [  471.859256] kernel:  Port1: ASoC: error at dpcm_fe_dai_hw_params on Port1: -110
    [  471.859269] kernel: snd_sof:sof_pcm_hw_free: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: free stream 1 dir 1
    [  471.859431] kernel: snd_sof:sof_pcm_hw_free: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: free stream 1 dir 0
    [  471.859450] kernel: snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x200]=0x340000 successful
    [  471.859462] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-mtl 0000:00:1f.3: trigger cmd: 0 state: 2
    [  472.363516] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x13000003|0x1
    [  472.363566] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
    [  472.363612] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: failed to pause all pipelines
    [  472.363638] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
    [  472.363661] kernel:  Port0: ASoC: trigger FE cmd: 0 failed: -110
    
    [ 1792.547349] kernel: snd_sof:sof_widget_setup_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget pipeline.6 setup complete
    [ 1792.547360] kernel: snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-mtl 0000:00:1f.3: Create widget mixout.6.1 instance 1 - pipe 6 - core 1
    [ 1792.547372] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x40010003|0x103000a: MOD_INIT_INSTANCE [data size: 40]
    [ 1793.049074] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x40010003|0x103000a
    [ 1793.049100] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
    [ 1793.049105] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
    [ 1793.049138] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0xc0010003|0x103000a|0x0, target: 0x31000000|0x100000|0x0, ctl: 0x3
    [ 1793.049157] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
    [ 1793.049170] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
    [ 1793.049182] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
    [ 1793.049192] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
    [ 1793.049213] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0x5, ROM error: 0x0
    [ 1793.049225] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
    [ 1793.049241] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit enabled
    [ 1793.049251] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
    
  3. added this to the v2.7 milestone on Jul 5, 2023
  4. fredoh9 commented on Jul 26, 2023

    @fredoh9
    Contributor

    Instead of MOD_INIT_INSTANCE, now IPC timeout with MOD_BIND.

    [ 2495.308510] kernel: snd_sof:sof_ipc4_route_setup: sof-audio-pci-intel-mtl 0000:00:1f.3: bind gain.4.1:0 -> dai-copier.SSP.NoCodec-1.playback:0
    [ 2495.308538] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x45050006|0x50004: MOD_BIND
    [ 2495.813887] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x45050006|0x50004
    [ 2495.813911] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
    [ 2495.813922] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
    [ 2495.813939] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0x45050006|0x50004|0x0, target: 0x45050006|0x50004|0x0, ctl: 0x3
    [ 2495.813947] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
    [ 2495.813951] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
    [ 2495.813955] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
    [ 2495.813960] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
    [ 2495.813970] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0x0, ROM error: 0x0
    [ 2495.813975] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
    [ 2495.813982] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit enabled
    [ 2495.813986] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
    [ 2495.814011] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: failed to bind modules gain.4.1:0 -> dai-copier.SSP.NoCodec-1.playback:0
    
  5. changed the title [-][BUG] Multi-core feature doesn't support 3 cores run at the same time[/-] [+][BUG] Various IPC timed out with multi-core run simultaneously[/+] on Jul 31, 2023
  6. keqiaozhang commented on Jul 31, 2023

    @keqiaozhang
    CollaboratorAuthor

    The highest probability of IPC timed out is "MOD_BIND" when testing multiple pipelines, The reproduction rate is about 90%.
    The second one is "GLB_SET_PIPELINE_STATE", the reproduction rate is about 10%.

  7. lgirdwood commented on Jul 31, 2023

    @lgirdwood
    Member

    @keqiaozhang can you retry Tuesday, a multicore fix PR has been merged today (after you ran this test). Thanks !!

  8. 18 remaining items

  9. RanderWang commented on Aug 28, 2023

    @RanderWang
    Collaborator

    I did many tests and find that if IPC4 logging is disabled, multi-core test can pass. I found one infinite loop in fw on one device but it can't be reproduced on another one. I will update the status when I get any hint

  10. RanderWang commented on Aug 28, 2023

    @RanderWang
    Collaborator

    BTW, this issue is very easy to reproduce when mtrace is DISABLED, even with PR #8000. Here is the test results:https://sof-ci.ostc.intel.com/#/result/planresultdetail/29740

    It's hard to reproduce this issue locally in python tests without IPC payloads.

    Could you please rerun this PR run with IPC payload enabled? For me, it will be easier to reproduce if I get passed tests results :)

    For the HW hang with multicore feature, it can't be reproduced by python test and only found with Linux audio test. Finally found the root reason by HW team

  11. lgirdwood commented on Aug 28, 2023

    @lgirdwood
    Member

    I did many tests and find that if IPC4 logging is disabled, multi-core test can pass. I found one infinite loop in fw on one device but it can't be reproduced on another one. I will update the status when I get any hint

    @RanderWang can you fix infinite loop with a timout check and log error. We think some were introduced when drivers were added to Zephyr. @kv2019i @abonislawski fyi.

  12. kv2019i commented on Aug 28, 2023

    @kv2019i
    Collaborator

    @RanderWang Which infinite loop did you see? Let's add a timeout to these, so we can exclude them out. I pushed first such fix now -> zephyrproject-rtos/zephyr#61967

    Another break-from-inifinite-loop fix at zephyrproject-rtos/zephyr#61978

  13. RanderWang commented on Aug 29, 2023

    @RanderWang
    Collaborator

    Maybe it is cause by #8115

  14. lyakh commented on Aug 30, 2023

    @lyakh
    Collaborator

    Can we test the same on TGL?

  15. keqiaozhang commented on Sep 6, 2023

    @keqiaozhang
    CollaboratorAuthor

    This issue has been improved a lot after #8143 merged. Only multiple-pause-resume test failed in today's CI testing.

  16. mengdonglin commented on Sep 8, 2023

    @mengdonglin
    Collaborator

    After PR #8149 got merged, this issue cannot be reproduced on ww36.4

  17. wszypelt commented on Sep 8, 2023

    @wszypelt

    @keqiaozhang request for confirmation and closing the bug

  18. fredoh9 commented on Sep 8, 2023

    @fredoh9
    Contributor

    this issue cannot be reproduced on ww36.5 either. Let me do some manually test before closing the issue.

  19. fredoh9 commented on Sep 8, 2023

    @fredoh9
    Contributor

    re-run multicore test with daily build(planresultdetail/31515) and manually ran multiple-pipeline.sh. Looks very stable.
    I think we can close this.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Labels

Fix confirmedFix for the issue has been found and verifiedIPC timeoutIPC timeout observedIntel Linux Daily testsThis issue can be found in internal Linux daily testsMTLApplies to Meteor Lake platformP1Blocker bugs or important featuresbugSomething isn't working as expectedmulticoreIssues observed when not only core#0 is used.

Type

No type

Projects

No projects

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions