[BUG] ipc timed out for 0x11030007|GLB_CREATE_PIPELINE when testing multiple-pipeline playback

[keqiaozhang]

Describe the bug
Observed this issue in daily test. There's an IPC times out error on MTL-nocodec platform when testing with multiple pipeline.
The reproduce rate is low. This issue cannot be reproduced manually.

dmesg

[ 4849.201436] kernel: snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-tgl 0000:00:1f.3: Create widget pipeline.6 instance 4 - pipe 6 - core 0
[ 4849.201439] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x11040006|0x0: GLB_CREATE_PIPELINE
[ 4849.202438] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x31000000|0x0: GLB_CREATE_PIPELINE
[ 4849.202446] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x11040006|0x0: GLB_CREATE_PIPELINE
[ 4849.202449] kernel: snd_sof:sof_widget_setup_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: widget pipeline.6 setup complete
[ 4849.202452] kernel: snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-tgl 0000:00:1f.3: Create widget mixout.6.1 instance 2 - pipe 6 - core 0
[ 4849.202454] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x40020003|0x4000a: MOD_INIT_INSTANCE [data size: 40]
[ 4849.703559] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x40020003|0x4000a
[ 4849.703580] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 4849.703588] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 4849.703615] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000080 rirb 00
[ 4849.703627] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 4849.703671] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0x91040006|0x0|0x0, target: 0x0|0x0|0x0, ctl: 0x3
[ 4849.703683] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 4849.703692] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 4849.703700] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 4849.703708] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 4849.703736] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x00000005: module: ROM, state: FW_ENTERED, running
[ 4849.703808] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: extended rom status:  0x5 0x0 0x0 0x0 0x0 0x0 0x0 0x1
[ 4849.703817] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 4849.703873] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to create module mixout.6.1
[ 4849.703896] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x12040000|0x0: GLB_DELETE_PIPELINE
[ 4850.206631] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x12040000|0x0
[ 4850.206647] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context

mtrace

[  104.401413] <inf> pipe: pipeline new pipe_id 3 priority 0
[  104.401978] <inf> ipc: rx	: 0x40020004|0x30015
[  104.402040] <inf> dma: dma_get() ID 0 sref = 2 busy channels 0
[  104.402443] <inf> ipc: rx	: 0x40020006|0x30010
[  104.404001] <inf> ipc: rx	: 0x44020006|0x30000018
[  104.404348] <inf> ipc: rx	: 0x40020002|0x3000a
[  104.404883] <inf> ipc: rx	: 0x11040006|0x0
[  104.404896] <inf> pipe: pipeline new pipe_id 4 priority 0
[  105.422670] <inf> ll_schedule: ll timer avg 4444, max 9407, overruns 0
[  106.446670] <inf> ll_schedule: ll timer avg 4401, max 6064, overruns 0
[  107.470670] <inf> ll_schedule: ll timer avg 4402, max 6054, overruns 0
[  108.494670] <inf> ll_schedule: ll timer avg 4401, max 6058, overruns 0
[  109.518670] <inf> ll_schedule: ll timer avg 4401, max 6057, overruns 0
[  110.490643] <inf> host_comp: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192
[  110.491643] <inf> host_comp: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192
[  110.492643] <inf> host_comp: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192
[  110.493643] <inf> host_comp: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192
[  110.494643] <inf> host_comp: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192
[  110.495643] <inf> host_comp: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192
[  110.496645] <inf> host_comp: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192
......

To Reproduce
~/sof-test/test-case/multiple-pipeline.sh -f p -l 50

Reproduction Rate
TBD, unable to reproduce it manually.

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • Kernel: {17b5d3eee2c6}
   • SOF: {1dd1939f05ef}
2. Name of the topology file
   • Topology: {sof-tgl-nocodec.tplg}
3. Name of the platform(s) on which the bug is observed.
   • Platform: {mtl-nocodec}

dmesg.txt
mtrace.txt

[keqiaozhang]

This issue no longer exists in CI for a month, closing this bug.