[BUG] ipc timed out MOD_SET_DX in suspend-resume in TGL/MTL

[fredoh9]

Describe the bug

Found in Intel internal daily test, test case was check-suspend-resume-with-playback
planresultdetail/23903?model=TGLU_UP_HDA_IPC4ZPH&testcase=check-suspend-resume-with-playback-5

[ 6168.932762] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x47000000|0x0: MOD_SET_DX [data size: 8]
[ 6168.971415] kernel: e1000e: EEE TX LPI TIMER: 00000011
[ 6169.437427] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
[ 6169.437432] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 6169.437435] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 6169.437453] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[ 6169.437457] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 6169.437479] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0xc7000000|0x0|0x0, target: 0x0|0x0|0x0, ctl: 0x3
[ 6169.437483] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 6169.437486] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 6169.437488] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 6169.437490] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 6169.437498] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x00000005: module: ROM, state: FW_ENTERED, running
[ 6169.437533] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: extended rom status:  0x5 0x0 0x0 0x0 0x0 0x0 0x0 0x1
[ 6169.437535] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 6169.437540] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ctx_save IPC error: -110, proceeding with suspend

To Reproduce
TPLG=/lib/firmware/intel/avs-tplg/sof-hda-generic.tplg MODEL=TGLU_UP_HDA_IPC4ZPH ~/sof-test/test-case/check-suspend-resume-with-audio.sh -l 5 -m playback

Reproduction Rate
Checking the Reproduction Rate but not so often

Environment

• Kernel Branch: topic/sof-dev
• Kernel Commit: cea8235d1887
• SOF Branch: main
• SOF Commit: 6aa71dd6f249
• Zephyr Commit: zephyr-v3.3.0-1778-g1851950977d5

Screenshots or console output
mtrace-tglu-hda.txt
dmesg-tglu-hda.txt

[fredoh9]

same issue was reported in #6679 which is closed now

[kv2019i]

@juimonen Can you take a look? Potentially related to the recent PM change for cAVS2.5.

[ranj063]

This seems to also show up on TGL nocodec but reproduction rate is quite low

[juimonen]

yeah tried to get with sof/zephyr/kernel heads with nocodec in upx.... just could not reproduce. Actually got errors from mtrace bailing out... but not this

[ranj063]

looks like this one is also seen without audio playback in a recent test

[juimonen]

@ranj063 can you point me to some of those failing... tried to search but quite tedious...

[ranj063]

@juimonen I disabled support for D0i3 ( by making the deep buffer PCM not D0i3 compatible) in TGL/ADL in our topologies. I think with that change, this issue has not been seen lately.

[fredoh9]

Without audio has same error,

[ 2451.567272] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x47000000|0x0: MOD_SET_DX [data size: 8]
[ 2452.073254] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
[ 2452.073259] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 2452.073263] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 2452.073275] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[ 2452.073280] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 2452.073293] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0xc7000000|0x0|0x0, target: 0x0|0x0|0x0, ctl: 0x3
[ 2452.073298] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 2452.073300] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 2452.073303] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 2452.073306] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 2452.073314] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x00000005: module: ROM, state: FW_ENTERED, running
[ 2452.073334] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: extended rom status:  0x5 0x0 0x0 0x0 0x0 0x0 0x0 0x1
[ 2452.073337] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 2452.073341] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ctx_save IPC error: -110, proceeding with suspend

Intel intenal daily test:
planresultdetail/24699?model=TGLU_UP_HDA_IPC4ZPH&testcase=check-suspend-resume-50