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

Firmware recovery #1675

Open
plbossart opened this issue Jan 9, 2020 · 11 comments
Open

Firmware recovery #1675

plbossart opened this issue Jan 9, 2020 · 11 comments
Assignees
Labels
enhancement New feature or request

Comments

@plbossart
Copy link
Member

We really need to have a watchdog-like mechanism where the host driver can detect the DSP is no longer responding and recover by reinitializing the hardware and notify apps.

@plbossart plbossart added the enhancement New feature or request label Jan 9, 2020
@lgirdwood
Copy link
Member

ACK. This can be first tied into the IPC timeout handler code. We already have a developer Kconfig option that prevents D3 upon FW crash (via IPC timeout) so would likely need the default action to be recover if this Kconfig option is not enabled.

@plbossart
Copy link
Member Author

Right, this can work as a kernel-side detection only.

But I was thinking here of an explicit watchdog or something that shows a sign of activity on the firmware side.

@kv2019i
Copy link
Collaborator

kv2019i commented Jan 18, 2020

@plbossart This is a duplicate of #452
Still valid. Some work was done for #452 but delayed due to other work.

@plbossart
Copy link
Member Author

@ujfalusi the Skylake driver implemented a recovery mechanism that was used on ApolloLake, but I am not sure if that part was ever upstreamed. @mwasko would you happen to recall?
IIRC there's a need to let applications know the card was restarted, I just don't recall what mechanism (uevent?) was used.

@ujfalusi
Copy link
Collaborator

@plbossart, what have worked for me in the past is to call snd_pcm_stop_xrun(struct snd_pcm_substream *substream) to escalate the event up to the application.

I need to take a look at the options, but instant detection of firmware crash can only be done if the crashed firmware would give us an interrupt/event that it crashed, which I don't think it is going to do.
The only option is to set up a timer matching the period_elapsed (well 1.2x of it to be safe) and restart it when we have got the elapsed. If the timer fires then the firmware might have been crashed.

@mwasko
Copy link

mwasko commented May 25, 2021

@ujfalusi the Skylake driver implemented a recovery mechanism that was used on ApolloLake, but I am not sure if that part was ever upstreamed. @mwasko would you happen to recall?

In Skylake driver we had implemented the FW recovery for specific releases for ApolloLake but I don't think it was upstream to Linux kernel. However the recovery itself was not done based on watchdog-like mechanism but on critical errors like IPC timeout or FW errors like memory issues during FW boot.

@ujfalusi
Copy link
Collaborator

@mwasko, thanks for the details. IPC timeout is a good indication of firmware error with the additional watchdog (when it applies) we can also catch crashes which happen without much IPC traffic, like audio operation when we just receive the periodic elapsed events.

I'll keep these in mind.

@kv2019i
Copy link
Collaborator

kv2019i commented May 25, 2021

@ujfalusi And to further complicate, SOF supports SNDRV_PCM_HW_PARAMS_NO_PERIOD_WAKEUP, so you might not get any regular IPCs nor period-elapsed IRQs. If a DSP stops in this configuration, you can detect this at XRUN, but it's not very straighforward -- some hw_ptr liveliness check could work, but needs to differentiate from application side errors. I believe starting with distinct FW failure events (a DSP panic or error to IPC), is a good starting point.

@ujfalusi
Copy link
Collaborator

@kv2019i, IPC timout can be used to check NO_PERIOD_WAKEUP from a periodic timer (read position, status, hearthbeat, something small and trivial) but it would just defeat the whole purpose of NO_PERIOD_WAKEUP. I would leave this for now.
The other possibility would be to handle the underflow/overflow interrupts from the DAI HW directly in Linux. That would indicate FW issue (unless the firmware is crashed but the DMA is still happily servicing the peripheral in cyclic mode).
In that case we would notice it when user space asks for a position.

@marc-hb
Copy link
Collaborator

marc-hb commented Jan 11, 2024

This suspend/resume failure below did not just TIMEOUT, for a change the system stayed alive enough to send logs. What I found interesting and relevant is:

  • The DSP panics during suspend/resume. Should be easy enough to simulate.
  • The DSP seems to reboot just fine
  • Then all IPCs time out.

So I suspect the kernel successfully rebooted the DSP but didn't properly clean-up something in its internal state.
https://sof-ci.01.org/sofpr/PR8571/build1764/devicetest/index.html?model=TGLU_RVP_NOCODEC-ipc4&testcase=check-suspend-resume-with-playback
Internal TEST run #36728.
CI build start time: 2024-01-10T15:53:36-08:00
Linux Branch: topic/sof-dev
Commit: 623c00b5e977
Kconfig Branch: master
Kconfig Commit: 40725018b505
PR ID: 8571
Commit: Merge 6978c7c7e421 into 1cc7a4c5b1b173327103315f
Zephyr Commit: d7af6f371034

Kernel logs
[ 5550.716069] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x33000000|0x1: GLB_SET_PIPELINE_STATE
[ 5550.716152] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x13000003|0x1: GLB_SET_PIPELINE_STATE [data size: 16]
[ 5550.717254] kernel: asix 3-4.1:1.0 enx000ec667532b: Link is Down
[ 5550.734422] kernel: e1000e: EEE TX LPI TIMER: 00000011
[ 5550.734456] kernel: snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x180]=0x20240000 successful
[ 5550.734470] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-tgl 0000:00:1f.3: trigger cmd: 0 state: 2
[ 5550.734481] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x13000002|0x1: GLB_SET_PIPELINE_STATE [data size: 16]
[ 5550.738470] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx      : 0x1b0a0000|0x0: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 5550.738477] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 5550.738480] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: DSP panic!
[ 5550.738482] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 5550.738502] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x00000005: module: ROM, state: FW_ENTERED, running
[ 5550.738711] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW is built with XCC toolchain
[ 5550.738714] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: DSP Firmware Oops
[ 5550.738716] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: EXCCAUSE 0x0000003f EXCVADDR 0x00000000 PS       0x00060e20 SAR     0x0000001b
[ 5550.738719] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: EPC1     0xbe059a27 EPC2     0x00000000 EPC3     0x00000000 EPC4    0x00000000
[ 5550.738723] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: EPC5     0x00000000 EPC6     0x00000000 EPC7     0x00000000 DEPC    0x00000000
[ 5550.738725] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: EPS2     0x00000000 EPS3     0x00000000 EPS4     0x00000000 EPS5    0x00000000
[ 5550.738727] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: EPS6     0x00000000 EPS7     0x00000000 INTENABL 0x00000000 INTERRU 0x00000000
[ 5550.738730] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: stack dump from 0x00000000
[ 5550.738732] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: AR registers:
[ 5550.738735] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x0: be014fb8 be0b0040 00000004 be0b0050
[ 5550.738739] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x10: be0b0030 00000004 9e0c30a4 ffffff7c
[ 5550.738741] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x20: be014179 be0affb0 be07bb30 be0b0050
[ 5550.738744] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x30: be014179 be0affb0 be07bb30 be0b0050
[ 5550.738746] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 5550.738749] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state change: 7 -> 8
[ 5550.738808] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done : 0x1b0a0000|0x0: GLB_NOTIFICATION|EXCEPTION_CAUGHT
[ 5551.238460] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x13000002|0x1
[ 5551.238465] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 5551.238466] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 5551.238509] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[ 5551.238511] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 5551.238557] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0x93000002|0x1|0x0, target: 0x0|0x0|0x80000000, ctl: 0x3
[ 5551.238559] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 5551.238560] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 5551.238561] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 5551.238562] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_CRASHED (8)
[ 5551.238584] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x00000005: module: ROM, state: FW_ENTERED, running
[ 5551.238774] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW is built with XCC toolchain
[ 5551.238776] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: DSP Firmware Oops
[ 5551.238777] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: EXCCAUSE 0x0000003f EXCVADDR 0x00000000 PS       0x00060e20 SAR     0x0000001b
[ 5551.238779] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: EPC1     0xbe059a27 EPC2     0x00000000 EPC3     0x00000000 EPC4    0x00000000
[ 5551.238780] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: EPC5     0x00000000 EPC6     0x00000000 EPC7     0x00000000 DEPC    0x00000000
[ 5551.238781] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: EPS2     0x00000000 EPS3     0x00000000 EPS4     0x00000000 EPS5    0x00000000
[ 5551.238782] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: EPS6     0x00000000 EPS7     0x00000000 INTENABL 0x00000000 INTERRU 0x00000000
[ 5551.238782] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: stack dump from 0x00000000
[ 5551.238783] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: AR registers:
[ 5551.238785] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x0: be014fb8 be0b0040 00000004 be0b0050
[ 5551.238786] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x10: be0b0030 00000004 9e0c30a4 ffffff7c
[ 5551.238787] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x20: be014179 be0affb0 be07bb30 be0b0050
[ 5551.238787] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0x30: be014179 be0affb0 be07bb30 be0b0050
[ 5551.238789] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 5551.238823] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to set final state 2 for all pipelines
[ 5551.238919] kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x1010f0f successful
[ 5551.238931] kernel: snd_sof_intel_hda_common:hda_dsp_core_power_down: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f successful
[ 5551.238934] kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-tgl 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
[ 5551.239021] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000010 at  00000044
[ 5551.239035] kernel: snd_sof_intel_hda_common:hda_dsp_state_log: sof-audio-pci-intel-tgl 0000:00:1f.3: Current DSP power state: D3
[ 5551.239036] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state change: 8 -> 0
[ 5551.283872] kernel: ACPI: EC: interrupt blocked
[ 5556.160683] kernel: ACPI: EC: interrupt unblocked
[ 5556.639384] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
[ 5556.639401] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000040 at  00000048
[ 5556.639420] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIW: 00000000 at  00000048
[ 5556.642673] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000000 at  00000048
[ 5556.642677] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIW: 00000040 at  00000048
[ 5556.642685] kernel: snd_sof_intel_hda_common:hda_dsp_state_log: sof-audio-pci-intel-tgl 0000:00:1f.3: Current DSP power state: D0I0
[ 5556.642687] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state change: 0 -> 2
[ 5556.642689] kernel: snd_sof:snd_sof_load_firmware: sof-audio-pci-intel-tgl 0000:00:1f.3: loading firmware
[ 5556.642691] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state change: 2 -> 3
[ 5556.642698] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000002 at  00000048
[ 5556.642703] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIW: 00000000 at  00000048
[ 5556.642709] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
[ 5556.642714] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIW: 00000004 at  00000044
[ 5556.642716] kernel: snd_sof:snd_sof_run_firmware: sof-audio-pci-intel-tgl 0000:00:1f.3: booting DSP firmware
[ 5556.642727] kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-tgl 0000:00:1f.3: period_bytes:0x0
[ 5556.642729] kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-tgl 0000:00:1f.3: periods:1
[ 5556.642818] kernel: snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x40000 successful
[ 5556.642838] kernel: snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x40000 successful
[ 5556.642841] kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-tgl 0000:00:1f.3: period_bytes:0x0
[ 5556.642842] kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-tgl 0000:00:1f.3: periods:1
[ 5556.642917] kernel: snd_sof_intel_hda_common:hda_dsp_cl_boot_firmware: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting iteration 0 of Core En/ROM load...
[ 5556.642922] kernel: snd_sof_intel_hda_common:hda_dsp_core_power_up: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf010f0f successful
[ 5556.642930] kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_leave: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf010f0e successful
[ 5556.642933] kernel: snd_sof_intel_hda_common:hda_dsp_core_run: sof-audio-pci-intel-tgl 0000:00:1f.3: unstall/run core: core_mask = 1
[ 5556.642937] kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-tgl 0000:00:1f.3: DSP core(s) enabled? 1 : core_mask 1
[ 5556.643444] kernel: snd_sof_intel_hda_common:cl_dsp_init: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0xd4]=0x80000000 successful
[ 5556.647945] kernel: serial 00:03: activated
[ 5556.705372] kernel: snd_sof_intel_hda_common:cl_dsp_init: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x80000]=0x5000001 successful
[ 5556.705376] kernel: snd_sof_intel_hda_common:hda_cl_copy_fw: sof-audio-pci-intel-tgl 0000:00:1f.3: Code loader DMA starting
[ 5556.708041] kernel: nvme nvme0: 8/0/0 default/read/poll queues
[ 5556.714257] kernel: snd_sof_intel_hda_common:hda_cl_copy_fw: sof-audio-pci-intel-tgl 0000:00:1f.3: Code loader DMA done, waiting for FW_ENTERED status
[ 5556.727852] kernel: snd_sof_intel_hda_common:hda_cl_copy_fw: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x80000]=0x5 successful
[ 5556.727855] kernel: snd_sof_intel_hda_common:hda_cl_copy_fw: sof-audio-pci-intel-tgl 0000:00:1f.3: Code loader FW_ENTERED status
[ 5556.728383] kernel: snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x140000 successful
[ 5556.728388] kernel: snd_sof_intel_hda_common:hda_cl_copy_fw: sof-audio-pci-intel-tgl 0000:00:1f.3: Code loader DMA stopped
[ 5556.728389] kernel: snd_sof_intel_hda_common:hda_dsp_cl_boot_firmware: sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware download successful, booting...
[ 5556.760929] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx      : 0x1b080000|0x0: GLB_NOTIFICATION|FW_READY
[ 5556.760933] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state change: 3 -> 6
[ 5556.760935] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done : 0x1b080000|0x0: GLB_NOTIFICATION|FW_READY
[ 5556.760982] kernel: snd_sof:snd_sof_run_firmware: sof-audio-pci-intel-tgl 0000:00:1f.3: firmware boot complete
[ 5556.760984] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state change: 6 -> 7
[ 5556.761000] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000000 at  00000048
[ 5556.761006] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIW: 00000002 at  00000048
[ 5556.761017] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000004 at  00000044
[ 5556.761024] kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIW: 00000000 at  00000044
[ 5556.873820] kernel: atkbd serio0: Failed to deactivate keyboard on isa0060/serio0
[ 5557.132981] kernel: asix 3-4.1:1.0 enx000ec667532b: configuring for phy/internal link mode
[ 5557.249922] kernel: atkbd serio0: Failed to enable keyboard on isa0060/serio0
[ 5557.375587] kernel: OOM killer enabled.
[ 5557.375592] kernel: Restarting tasks ... 
[ 5557.378683] kernel: snd_sof:sof_pcm_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 41 dir 0 cmd 1
[ 5557.378695] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-tgl 0000:00:1f.3: trigger cmd: 1 state: 4
[ 5557.378708] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x13000003|0x1: GLB_SET_PIPELINE_STATE [data size: 16]
[ 5557.379126] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x33000009|0x1: GLB_SET_PIPELINE_STATE
[ 5557.379137] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW reported error: 9 - Specified resource not found
[ 5557.379296] kernel: done.
[ 5557.379372] kernel: random: crng reseeded on system resumption
[ 5557.380455] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc error for msg 0x13000003|0x1
[ 5557.380466] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to pause all pipelines
[ 5557.380472] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -22
[ 5557.380478] kernel:  Port0 Aux Playback: ASoC: trigger FE cmd: 1 failed: -22
[ 5557.380486] kernel: snd_sof:sof_pcm_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 41 dir 0 cmd 0
[ 5557.380491] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-tgl 0000:00:1f.3: trigger cmd: 0 state: 3
[ 5557.381268] kernel: PM: suspend exit
[ 5557.986111] kernel: snd_sof:sof_pcm_hw_free: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: free stream 41 dir 0
[ 5557.986149] kernel: snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x180]=0x40000 successful
[ 5557.986177] kernel: snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-tgl 0000:00:1f.3: trigger cmd: 0 state: 2
[ 5557.986189] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x13000002|0x1: GLB_SET_PIPELINE_STATE [data size: 16]
[ 5557.986655] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x33000009|0x1: GLB_SET_PIPELINE_STATE
[ 5557.986660] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW reported error: 9 - Specified resource not found
[ 5557.986721] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc error for msg 0x13000002|0x1
[ 5557.986728] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to set final state 2 for all pipelines
[ 5557.986795] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-tgl 0000:00:1f.3: unbind modules host-copier.41.playback:0 -> gain.21.1:0
[ 5557.986809] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: widget host-copier.41.playback freed
[ 5557.986815] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-tgl 0000:00:1f.3: unbind modules gain.21.1:0 -> mixin.21.1:0
[ 5557.986821] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: widget gain.21.1 freed
[ 5557.986826] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-tgl 0000:00:1f.3: unbind modules mixin.21.1:0 -> mixout.16.1:0
[ 5557.986832] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x46000002|0x3: MOD_UNBIND
[ 5557.987312] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x66000009|0x3: MOD_UNBIND
[ 5557.987316] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW reported error: 9 - Specified resource not found
[ 5557.987372] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc error for msg 0x46000002|0x3
[ 5557.987377] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to unbind modules mixin.21.1:0 -> mixout.16.1:0
[ 5557.987388] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x12000000|0x0: GLB_DELETE_PIPELINE
[ 5557.987946] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x32000009|0x0: GLB_DELETE_PIPELINE
[ 5557.987956] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: FW reported error: 9 - Specified resource not found
[ 5557.988026] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc error for msg 0x12000000|0x0
[ 5557.988034] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to free pipeline widget pipeline.21
[ 5557.988044] 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]
[ 5557.988388] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx reply: 0x67000000|0x0: MOD_SET_DX
[ 5557.988452] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx done : 0x47000000|0x0: MOD_SET_DX [data size: 8]
[ 5557.988517] kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x1010f0f successful
[ 5557.988547] kernel: snd_sof_intel_hda_common:hda_dsp_core_power_down: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f successful
[ 5557.988573] kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-tgl 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
[ 5557.988579] kernel: snd_sof:snd_sof_dsp_core_put: sof-audio-pci-intel-tgl 0000:00:1f.3: Core 0 powered down
[ 5557.988603] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-tgl 0000:00:1f.3: unbind modules mixout.16.1:0 -> mixin.16.1:0
[ 5557.988611] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: widget mixout.16.1 freed
[ 5557.988617] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-tgl 0000:00:1f.3: unbind modules mixin.16.1:0 -> mixout.2.1:1
[ 5557.988624] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x46020002|0x1010003: MOD_UNBIND
[ 5558.489616] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x46020002|0x1010003
[ 5558.489633] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 5558.489638] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 5558.489681] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[ 5558.489689] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 5558.489736] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0x0|0x0|0x0, target: 0x0|0x0|0x0, ctl: 0x0
[ 5558.489744] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 5558.489749] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 5558.489754] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 5558.489759] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 5558.489787] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0xffffffff: unknown ROM status value
[ 5558.489867] kernel: snd_sof:sof_ipc4_find_debug_slot_offset_by_type: sof-audio-pci-intel-tgl 0000:00:1f.3: Slot type 0x4c455400 is not available in debug window
[ 5558.489872] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 5558.489917] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to unbind modules mixin.16.1:0 -> mixout.2.1:1
[ 5558.489937] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x12010000|0x0: GLB_DELETE_PIPELINE
[ 5558.993517] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x12010000|0x0
[ 5558.993535] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 5558.993541] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 5558.993581] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[ 5558.993588] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 5558.993638] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0x0|0x0|0x0, target: 0x0|0x0|0x0, ctl: 0x0
[ 5558.993646] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 5558.993651] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 5558.993656] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 5558.993661] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 5558.993689] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0xffffffff: unknown ROM status value
[ 5558.993768] kernel: snd_sof:sof_ipc4_find_debug_slot_offset_by_type: sof-audio-pci-intel-tgl 0000:00:1f.3: Slot type 0x4c455400 is not available in debug window
[ 5558.993773] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 5558.993818] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to free pipeline widget pipeline.16
[ 5558.993830] 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]
[ 5559.497407] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
[ 5559.497425] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 5559.497430] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 5559.497470] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[ 5559.497477] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 5559.497527] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0x0|0x0|0x0, target: 0x0|0x0|0x0, ctl: 0x0
[ 5559.497534] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 5559.497540] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 5559.497544] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 5559.497549] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 5559.497577] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0xffffffff: unknown ROM status value
[ 5559.497653] kernel: snd_sof:sof_ipc4_find_debug_slot_offset_by_type: sof-audio-pci-intel-tgl 0000:00:1f.3: Slot type 0x4c455400 is not available in debug window
[ 5559.497657] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 5559.497701] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to disable target core: 0 for pipeline pipeline.16
[ 5559.497714] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-tgl 0000:00:1f.3: unbind modules mixout.2.1:0 -> gain.2.1:0
[ 5559.497725] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: widget mixout.2.1 freed
[ 5559.497731] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-tgl 0000:00:1f.3: unbind modules gain.2.1:0 -> smart_amp.2.1:0
[ 5559.497737] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: widget gain.2.1 freed
[ 5559.497742] kernel: snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-tgl 0000:00:1f.3: unbind modules smart_amp.2.1:0 -> dai-copier.SSP.NoCodec-0.playback:0
[ 5559.497748] kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: widget smart_amp.2.1 freed
[ 5559.497757] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx      : 0x12030000|0x0: GLB_DELETE_PIPELINE
[ 5560.001303] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x12030000|0x0
[ 5560.001321] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 5560.001326] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 5560.001369] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[ 5560.001377] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 5560.001423] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0x0|0x0|0x0, target: 0x0|0x0|0x0, ctl: 0x0
[ 5560.001430] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 5560.001436] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 5560.001440] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 5560.001446] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 5560.001474] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0xffffffff: unknown ROM status value
[ 5560.001556] kernel: snd_sof:sof_ipc4_find_debug_slot_offset_by_type: sof-audio-pci-intel-tgl 0000:00:1f.3: Slot type 0x4c455400 is not available in debug window
[ 5560.001561] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 5560.001604] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to free pipeline widget pipeline.2
[ 5560.001617] 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]
[ 5560.505209] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc timed out for 0x47000000|0x0
[ 5560.505227] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Attempting to prevent DSP from entering D3 state to preserve context
[ 5560.505233] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 5560.505277] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[ 5560.505285] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 5560.505336] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Host IPC initiator: 0x0|0x0|0x0, target: 0x0|0x0|0x0, ctl: 0x0
[ 5560.505344] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 5560.505349] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 5560.505355] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 5560.505360] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (7)
[ 5560.505389] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: 0xffffffff: unknown ROM status value
[ 5560.505465] kernel: snd_sof:sof_ipc4_find_debug_slot_offset_by_type: sof-audio-pci-intel-tgl 0000:00:1f.3: Slot type 0x4c455400 is not available in debug window
[ 5560.505471] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 5560.505514] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to disable target core: 0 for pipeline pipeline.2
[ 5560.505524] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to free connected widgets
[ 5560.505541] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_free on 0000:00:1f.3: -110
[ 5560.505667] kernel: snd_sof:sof_pcm_close: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: close stream 41 dir 0
[ 5562.310270] kernel: asix 3-4.1:1.0 enx000ec667532b: Link is Up - 100Mbps/Full - flow control rx/tx

EDIT: same again in https://sof-ci.01.org/sofpr/PR8743/build1905/devicetest/index.html?model=TGLU_RVP_NOCODEC-ipc4&testcase=check-suspend-resume-with-playback / thesofproject/sof#8743

@ujfalusi
Copy link
Collaborator

@marc-hb, #4780 should in theory will fix the kernel state in case of this dsp panic. I cannot reproduce the issue locally.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement New feature or request
Projects
None yet
Development

No branches or pull requests

6 participants