Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
fredoh9 opened this issue Apr 20, 2023 · 23 comments
Closed

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

fredoh9 opened this issue Apr 20, 2023 · 23 comments
Assignees
Labels
bug Something isn't working as expected IPC4 Issues observed with IPC4 (same IPC as Windows) MTL Applies to Meteor Lake platform P2 Critical bugs or normal features suspend-resume Issues observed when doing system suspend and resume TGL Applies to Tiger Lake
Milestone

Comments

@fredoh9
Copy link
Contributor

fredoh9 commented Apr 20, 2023

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

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

@fredoh9 fredoh9 added bug Something isn't working as expected TGL Applies to Tiger Lake suspend-resume Issues observed when doing system suspend and resume IPC4 Issues observed with IPC4 (same IPC as Windows) labels Apr 20, 2023
@fredoh9
Copy link
Contributor Author

fredoh9 commented Apr 20, 2023

same issue was reported in #6679 which is closed now

@kv2019i
Copy link
Collaborator

kv2019i commented Apr 21, 2023

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

@abonislawski abonislawski added the P2 Critical bugs or normal features label Apr 25, 2023
@lgirdwood lgirdwood added this to the v2.6 milestone Apr 25, 2023
@ranj063
Copy link
Collaborator

ranj063 commented Apr 25, 2023

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

@juimonen
Copy link

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
Copy link
Collaborator

ranj063 commented Apr 27, 2023

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

@juimonen
Copy link

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

@ranj063
Copy link
Collaborator

ranj063 commented May 2, 2023

@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
Copy link
Contributor Author

fredoh9 commented May 2, 2023

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

@fredoh9 fredoh9 changed the title [BUG] ipc timed out MOD_SET_DX in suspend-resume with audio playback in TGLU_UP_HDA [BUG] ipc timed out MOD_SET_DX in suspend-resume in TGLU_UP_HDA May 2, 2023
@mengdonglin mengdonglin modified the milestones: v2.6, v2.7 May 12, 2023
@mengdonglin mengdonglin modified the milestones: v2.6, v2.7 May 26, 2023
@plbossart
Copy link
Member

This issue is seen on MTL as well

result/planresultdetail/26737?model=MTLP_RVP_NOCODEC&testcase=check-suspend-resume-with-capture-5

[ 3407.390760] kernel: PM: suspend entry (s2idle)
[ 3407.393168] kernel: Filesystems sync: 0.002 seconds
[ 3407.395799] kernel: Freezing user space processes
[ 3407.399117] kernel: Freezing user space processes completed (elapsed 0.003 seconds)
[ 3407.399127] kernel: OOM killer disabled.
[ 3407.399129] kernel: Freezing remaining freezable tasks
[ 3407.400808] kernel: Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[ 3407.400812] kernel: printk: Suspending console(s) (use no_console_suspend to debug)
[ 3407.425256] kernel: soundwire_intel:intel_pm_prepare: soundwire_intel soundwire_intel.link.0: SoundWire master 0 is disabled or not-started, ignoring
[ 3407.426358] kernel: snd_sof:sof_pcm_trigger: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: trigger stream 0 dir 1 cmd 5
[ 3407.426365] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-mtl 0000:00:1f.3: trigger cmd: 5 state: 3
[ 3407.426377] 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]
[ 3407.427432] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x33000000|0x1: GLB_SET_PIPELINE_STATE
[ 3407.427495] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x13000003|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
[ 3407.427736] kernel: soundwire_intel:intel_suspend: soundwire_intel soundwire_intel.link.0: SoundWire master 0 is disabled or not-started, ignoring
[ 3407.428502] kernel: asix 3-6.1:1.0 enx000ec6707217: Link is Down
[ 3407.431866] kernel: e1000e: EEE TX LPI TIMER: 00000011
[ 3407.432039] kernel: snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x80]=0x20140000 successful
[ 3407.432056] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-mtl 0000:00:1f.3: trigger cmd: 0 state: 2
[ 3407.432072] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13000002|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
[ 3407.432822] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x33000000|0x1: GLB_SET_PIPELINE_STATE
[ 3407.432862] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x13000002|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
[ 3407.432917] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-mtl 0000:00:1f.3: unbind modules dai-copier.SSP.NoCodec-0.capture:0 -> gain.8.1:0
[ 3407.432934] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget dai-copier.SSP.NoCodec-0.capture freed
[ 3407.432946] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-mtl 0000:00:1f.3: unbind modules gain.8.1:0 -> module-copier.8.2:0
[ 3407.432960] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget gain.8.1 freed
[ 3407.432970] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-mtl 0000:00:1f.3: unbind modules module-copier.8.2:0 -> module-copier.7.2:0
[ 3407.433005] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x46010004|0x20004: MOD_UNBIND
[ 3407.433453] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x66000000|0x20004: MOD_UNBIND
[ 3407.433506] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x46010004|0x20004: MOD_UNBIND
[ 3407.433541] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x12000000|0x0: GLB_DELETE_PIPELINE
[ 3407.434320] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x32000000|0x0: GLB_DELETE_PIPELINE
[ 3407.434596] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x12000000|0x0: GLB_DELETE_PIPELINE
[ 3407.434621] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget pipeline.8 freed
[ 3407.434634] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget module-copier.8.2 freed
[ 3407.434649] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-mtl 0000:00:1f.3: unbind modules module-copier.7.2:0 -> gain.7.1:0
[ 3407.434670] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget module-copier.7.2 freed
[ 3407.434683] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-mtl 0000:00:1f.3: unbind modules gain.7.1:0 -> host-copier.7.capture:0
[ 3407.434698] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget gain.7.1 freed
[ 3407.434718] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x12010000|0x0: GLB_DELETE_PIPELINE
[ 3407.435442] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x32000000|0x0: GLB_DELETE_PIPELINE
[ 3407.435659] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x12010000|0x0: GLB_DELETE_PIPELINE
[ 3407.435677] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget pipeline.7 freed
[ 3407.435686] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget host-copier.7.capture freed
[ 3407.435708] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x44000000|0x3060004c: MOD_LARGE_CONFIG_SET [data size: 76]
[ 3407.436047] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x64000000|0x3060004c: MOD_LARGE_CONFIG_SET
[ 3407.436300] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x44000000|0x3060004c: MOD_LARGE_CONFIG_SET [data size: 76]
[ 3407.436319] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x47000000|0x0: MOD_SET_DX [data size: 8]
[ 3407.943484] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
[ 3407.943499] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 3407.943508] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 3407.943526] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0xc7000000|0x0|0x0, target: 0x67000000|0x0|0x0, ctl: 0x3
[ 3407.943538] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 3407.943544] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 3407.943551] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
[ 3407.943557] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 3407.943572] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0xffffffff, ROM error: 0xffffffff
[ 3407.943580] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
[ 3407.943592] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit enabled
[ 3407.943598] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 3407.943608] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ctx_save IPC error: -110, proceeding with suspend
[ 3407.943635] kernel: snd_sof_intel_hda_common:mtl_enable_sdw_irq: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x114c]=0x0 successful
[ 3407.943667] kernel: snd_sof_intel_hda_common:mtl_enable_interrupts: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1800]=0x0 successful
[ 3407.943682] kernel: snd_sof_intel_hda_common:mtl_enable_interrupts: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1140]=0x0 successful
[ 3407.944815] kernel: snd_sof_intel_hda_common:mtl_dsp_core_power_down: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x178d04]=0x2000000 successful
[ 3407.945882] kernel: snd_sof_intel_hda_common:mtl_power_down_dsp: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1000]=0x0 successful
[ 3407.945946] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
[ 3407.945954] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: Debug PCIW: 00000010 at  00000044
[ 3407.946771] kernel: snd_sof_intel_hda_common:hda_dsp_state_log: sof-audio-pci-intel-mtl 0000:00:1f.3: Current DSP power state: D3
[ 3407.946776] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state change: 7 -> 0

@plbossart plbossart added the MTL Applies to Meteor Lake platform label May 31, 2023
@plbossart
Copy link
Member

@kv2019i @alex-cri not sure why an IPC timeout should only be fixed by 2.7 with a priority P2 ? That's a blocking issue in my book.

@keqiaozhang
Copy link
Collaborator

This issue also happened on TGL-H-0A70 IPC4 platform. Test ID:27185

   64.245377] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x44000000|0x3060004c: MOD_LARGE_CONFIG_SET [data size: 76]
[   64.245391] 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]
[   64.750154] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
[   64.750162] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[   64.750165] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[   64.750211] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[   64.750214] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[   64.750258] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0xc7000000|0x0|0x0, target: 0x0|0x0|0x0, ctl: 0x3
[   64.750261] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[   64.750263] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[   64.750266] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[   64.750268] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[   64.750304] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0xffffffff: unknown ROM status value
[   64.750323] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: extended rom status:  0xffffffff 0xffffffff 0xffffffff 0xffffffff 0xffffffff 0xffffffff 0xffffffff 0xffffffff
[   64.750325] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[   64.750330] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ctx_save IPC error: -110, proceeding with suspend

@fredoh9 fredoh9 changed the title [BUG] ipc timed out MOD_SET_DX in suspend-resume in TGLU_UP_HDA [BUG] ipc timed out MOD_SET_DX in suspend-resume in TGL HDA Jun 12, 2023
@fredoh9
Copy link
Contributor Author

fredoh9 commented Jun 12, 2023

This is pretty severe on TGLH_SKU0A70_HDA_IPC4ZPH.
Intel internal daily test: planresultdetail/27417

@kv2019i
Copy link
Collaborator

kv2019i commented Jun 14, 2023

@juimonen Worth checking if this is related to zephyrproject-rtos/zephyr#59060

@kv2019i
Copy link
Collaborator

kv2019i commented Jun 14, 2023

@plbossart wrote:

@kv2019i @alex-cri not sure why an IPC timeout should only be fixed by 2.7 with a priority P2 ? That's a blocking issue in my book.

Due to kernel dependencies, IPC4/cavs2.5 is still opt-in configuration for 2.6 and this issue is recoverable (DSP boots fine next time).

@juimonen
Copy link

should be fixed by: zephyrproject-rtos/zephyr#59272

@keqiaozhang
Copy link
Collaborator

@juimonen I have confirmed that zephyrproject-rtos/zephyr#59272 can fix this issue. Please help to merge the fix to main branch.

@juimonen
Copy link

@keqiaozhang 59272 merged to zephyr main and sof/stable2.6

@fredoh9
Copy link
Contributor Author

fredoh9 commented Jun 27, 2023

Found the issue today in MTLP_RVP_NOCODEC_MULTICORE with daily test.

[ 1547.350519] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x47000000|0x0: MOD_SET_DX [data size: 8]
[ 1547.856176] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
[ 1547.856190] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 1547.856195] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 1547.856224] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0xc7000000|0x0|0x0, target: 0x67000000|0x0|0x0, ctl: 0x3
[ 1547.856230] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 1547.856234] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 1547.856236] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
[ 1547.856239] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 1547.856251] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0xffffffff, ROM error: 0xffffffff
[ 1547.856255] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
[ 1547.856262] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit enabled
[ 1547.856265] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------

intel internal daily test: planresultdetail/28254?model=MTLP_RVP_NOCODEC_MULTICORE&testcase=check-suspend-resume-with-playback-5

@fredoh9 fredoh9 changed the title [BUG] ipc timed out MOD_SET_DX in suspend-resume in TGL HDA [BUG] ipc timed out MOD_SET_DX in suspend-resume in TGL/MTL Jun 27, 2023
@RDharageswari
Copy link

RDharageswari commented Jun 27, 2023

This issue is seen in MTL as well with the mtl-005 firmware branch
The behavior is random

[ 352.971033] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
[ 352.979537] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 352.988991] sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0xc7000000|0x0|0x0, target: 0x67000000|0x0|0x0, ctl: 0x3
[ 353.001735] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 353.010979] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 353.020423] sof-audio-pci-intel-mtl 0000:00:1f.3: IPC timeout
[ 353.026868] sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 353.035552] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM status: 0xffffffff, ROM error: 0xffffffff
[ 353.045287] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM debug status: 0x50000005, ROM debug error: 0x0
[ 353.055497] sof-audio-pci-intel-mtl 0000:00:1f.3: ROM feature bit not enabled
[ 353.063477] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 353.072721] sof-audio-pci-intel-mtl 0000:00:1f.3: ctx_save IPC error: -110, proceeding with suspend
[ 689.764439] sof-audio-pci-intel-mtl 0000:00:1f.3: GAIN (UUID: 61BCA9A8-18D0-4A18-8E7B-2639219804B7): No CPC match in the firmware file's manifest (ibs/obs: 768/768)
[ 692.922594] sof-audio-pci-intel-mtl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
[ 692.931113] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 692.940571] sof-audio-pci-intel-mtl 0000:00:1f.3: Host IPC initiator: 0xc7000000|0x0|0x0, target: 0x67000000|0x0|0x0, ctl: 0x3
[ 692.953325] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 692.962576] sof-audio-pci-intel-mtl 0000:00:1f.3: ------------[ DSP dump start ]---------

@marc-hb
Copy link
Collaborator

marc-hb commented Jul 12, 2023

Seen again in Intel today's daily result/planresultdetail/28947

@keqiaozhang
Copy link
Collaborator

keqiaozhang commented Jul 17, 2023

The kernel log is a little bit different today(29111):

[ 8141.656442] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget dai-copier.SSP.NoCodec-0.playback freed
[ 8141.656463] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x44000000|0x3060004c: MOD_LARGE_CONFIG_SET [data size: 76]
[ 8141.656659] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x64000000|0x3060004c: MOD_LARGE_CONFIG_SET
[ 8141.656685] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x44000000|0x3060004c: MOD_LARGE_CONFIG_SET [data size: 76]
[ 8141.656705] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x47000000|0x0: MOD_SET_DX [data size: 8]
[ 8141.657238] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x6700000d|0x0: MOD_SET_DX
[ 8141.657249] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: FW reported error: 13 - Requested power transition failed to complete
[ 8141.657274] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc error for msg 0x47000000|0x0
[ 8141.657286] kernel: sof-audio-pci-intel-mtl 0000:00:1f.3: ctx_save IPC error: -22, proceeding with suspend
[ 8141.657314] kernel: snd_sof_intel_hda_common:mtl_enable_sdw_irq: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x114c]=0x0 successful
[ 8141.657338] kernel: snd_sof_intel_hda_common:mtl_enable_interrupts: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1800]=0x0 successful
[ 8141.657346] kernel: snd_sof_intel_hda_common:mtl_enable_interrupts: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1140]=0x0 successful
[ 8141.658482] kernel: snd_sof_intel_hda_common:mtl_dsp_core_power_down: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x178d04]=0x2000000 successful
[ 8141.659552] kernel: snd_sof_intel_hda_common:mtl_power_down_dsp: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1000]=0x0 successful
[ 8141.659620] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
[ 8141.659626] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: Debug PCIW: 00000010 at  00000044
[ 8141.660657] kernel: snd_sof_intel_hda_common:hda_dsp_state_log: sof-audio-pci-intel-mtl 0000:00:1f.3: Current DSP power state: D3
[ 8141.660667] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state change: 7 -> 0

@keqiaozhang
Copy link
Collaborator

Let's track the IPC error issue ipc error for msg 0x47000000|0x0 |MOD_SET_DX in (#7969).

@keqiaozhang
Copy link
Collaborator

This issue can be closed, no reproductions in CI for weeks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working as expected IPC4 Issues observed with IPC4 (same IPC as Windows) MTL Applies to Meteor Lake platform P2 Critical bugs or normal features suspend-resume Issues observed when doing system suspend and resume TGL Applies to Tiger Lake
Projects
None yet
Development

No branches or pull requests