linux
linux copied to clipboard
thesofproject
[BUG] DSP initialization times out on ICL
Describe the bug CI detected this issue on ICL when testing check-kmod-load-unload-after-playback-5. DSP initialization timed out after 3 iterations and caused the firmware failed to boot from IMR.
[ 6420.591416] kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f0e0e successful
[ 6420.591424] kernel: snd_sof_intel_hda_common:hda_dsp_core_power_down: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x1010e0e successful
[ 6420.591430] kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-icl 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask e
[ 6420.891828] kernel: snd_sof_intel_hda_common:cl_dsp_init: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x80000]=0x6000010 timedout
[ 6420.891832] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: cl_dsp_init: timeout with rom_status_reg (0x80000) read
[ 6420.891837] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 6420.891838] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: Boot iteration failed: 3/3
[ 6420.891840] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: fw_state: SOF_FW_BOOT_IN_PROGRESS (2)
[ 6420.891860] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: 0x06000010: module: ROM, state: CSE_IMR_REQUEST, waiting for: CSE_CSR, running
[ 6420.891894] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: extended rom status: 0x6000010 0x0 0x0 0x0 0x0 0x0 0x2001182 0x0
[ 6420.891896] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 6420.891919] kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x1010f0f successful
[ 6420.891928] kernel: snd_sof_intel_hda_common:hda_dsp_core_power_down: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f successful
[ 6420.891934] kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-icl 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask f
[ 6420.891936] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp init failed after 3 attempts with err: -110
[ 6420.891981] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: Failed to start DSP
[ 6420.891983] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: error: failed to boot DSP firmware -110
[ 6420.891986] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-icl 0000:00:1f.3: fw_state change: 2 -> 3
[ 6420.944854] kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x1d003c timedout
[ 6420.944860] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_reset_enter: timeout on HDA_DSP_REG_ADSPCS read
[ 6420.944863] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core reset failed: core_mask f
[ 6420.946161] kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-icl 0000:00:1f.3: fw_state change: 3 -> 0
[ 6420.946255] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: error: sof_probe_work failed err: -110
To Reproduce
~/sof-test/test-case/check-kmod-load-unload-after-playback.sh -l 5
Reproduction Rate Hard to tell, no reproductions during manual check.
Environment
- Kernel and Firmware
- Kernel: sof-dev/ad489ae90547
- SOF: main/7e4452dfbb0e
- Name of the topology file
- Topology: sof-hda-generic-4ch.tplg
- Name of the platform(s) on which the bug is observed.
- Platform: ICL_RVP_HDA
@keqiaozhang You just filed this bug without any reference meaning it's a brand new regression? Never seen before? If yes it and the reproduction are is high enough then it should be quick and easy to bisect.
For the record this was found in daily test 13622. journalctl -k output below with hostname and timestamps:
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof:sof_ipc3_get_cc_info: sof-audio-pci-intel-icl 0000:00:1f.3: Firmware info: used compiler XCC 12:0:8 <RG-2017.8-linux> used optimization flags -O2
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof:sof_ipc3_fw_parse_ext_man: sof-audio-pci-intel-icl 0000:00:1f.3: found sof_ext_man header type 3 size 0x30
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: sof-audio-pci-intel-icl 0000:00:1f.3: unknown sof_ext_man header type 3 size 0x30
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof:sof_ipc3_fw_parse_ext_man: sof-audio-pci-intel-icl 0000:00:1f.3: found sof_ext_man header type 4 size 0x20
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof:ipc3_fw_ext_man_get_dbg_abi_info: sof-audio-pci-intel-icl 0000:00:1f.3: Firmware: DBG_ABI 5:3:0
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof:sof_ipc3_fw_parse_ext_man: sof-audio-pci-intel-icl 0000:00:1f.3: found sof_ext_man header type 5 size 0x20
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof:ipc3_fw_ext_man_get_config_data: sof-audio-pci-intel-icl 0000:00:1f.3: manifest can hold up to 3 config elements
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof:ipc3_fw_ext_man_get_config_data: sof-audio-pci-intel-icl 0000:00:1f.3: get index 0 token 1 val 384
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof:ipc3_fw_ext_man_get_config_data: sof-audio-pci-intel-icl 0000:00:1f.3: get index 1 token 2 val 1
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof:ipc3_fw_ext_man_get_config_data: sof-audio-pci-intel-icl 0000:00:1f.3: get index 2 token 0 val 0
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-icl 0000:00:1f.3: fw_state change: 1 -> 2
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-icl 0000:00:1f.3: Debug PCIR: 00000002 at 00000048
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-icl 0000:00:1f.3: Debug PCIW: 00000000 at 00000048
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-icl 0000:00:1f.3: Debug PCIR: 00000000 at 00000044
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-icl 0000:00:1f.3: Debug PCIW: 00000004 at 00000044
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof:snd_sof_run_firmware: sof-audio-pci-intel-icl 0000:00:1f.3: booting DSP firmware
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-icl 0000:00:1f.3: period_bytes:0x0
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-icl 0000:00:1f.3: periods:1
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x40000 successful
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x40000 successful
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-icl 0000:00:1f.3: period_bytes:0x0
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-icl 0000:00:1f.3: periods:1
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_cl_boot_firmware: sof-audio-pci-intel-icl 0000:00:1f.3: Attempting iteration 0 of Core En/ROM load...
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_power_up: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f0f0f successful
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_leave: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f0f0e successful
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_run: sof-audio-pci-intel-icl 0000:00:1f.3: unstall/run core: core_mask = 1
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-icl 0000:00:1f.3: DSP core(s) enabled? 1 : core_mask 1
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:cl_dsp_init: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0xd4]=0x80000000 successful
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f0e0e successful
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_power_down: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x1010e0e successful
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-icl 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask e
Jun 29 23:18:52 sh-icl-rvp-hda-06 kernel: usbcore: registered new interface driver snd-usb-audio
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:cl_dsp_init: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x80000]=0x6000010 timedout
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x1010f0f successful
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_power_down: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f successful
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-icl 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask f
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_cl_boot_firmware: sof-audio-pci-intel-icl 0000:00:1f.3: Attempting iteration 1 of Core En/ROM load...
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_power_up: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f0f0f successful
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_leave: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f0f0e successful
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_run: sof-audio-pci-intel-icl 0000:00:1f.3: unstall/run core: core_mask = 1
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-icl 0000:00:1f.3: DSP core(s) enabled? 1 : core_mask 1
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:cl_dsp_init: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0xd4]=0x80000000 successful
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f0e0e successful
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_power_down: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x1010e0e successful
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-icl 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask e
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:cl_dsp_init: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x80000]=0x6000010 timedout
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x1010f0f successful
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_power_down: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f successful
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-icl 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask f
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_cl_boot_firmware: sof-audio-pci-intel-icl 0000:00:1f.3: Attempting iteration 2 of Core En/ROM load...
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_power_up: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f0f0f successful
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_leave: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f0f0e successful
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_run: sof-audio-pci-intel-icl 0000:00:1f.3: unstall/run core: core_mask = 1
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-icl 0000:00:1f.3: DSP core(s) enabled? 1 : core_mask 1
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:cl_dsp_init: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0xd4]=0x80000000 successful
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f0e0e successful
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_power_down: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x1010e0e successful
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-icl 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask e
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:cl_dsp_init: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x80000]=0x6000010 timedout
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: sof-audio-pci-intel-icl 0000:00:1f.3: cl_dsp_init: timeout with rom_status_reg (0x80000) read
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: sof-audio-pci-intel-icl 0000:00:1f.3: ------------[ DSP dump start ]------------
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: sof-audio-pci-intel-icl 0000:00:1f.3: Boot iteration failed: 3/3
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: sof-audio-pci-intel-icl 0000:00:1f.3: fw_state: SOF_FW_BOOT_IN_PROGRESS (2)
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: sof-audio-pci-intel-icl 0000:00:1f.3: 0x06000010: module: ROM, state: CSE_IMR_REQUEST, waiting for: CSE_CSR, running
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: sof-audio-pci-intel-icl 0000:00:1f.3: extended rom status: 0x6000010 0x0 0x0 0x0 0x0 0x0 0x2001182 0x0
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: sof-audio-pci-intel-icl 0000:00:1f.3: ------------[ DSP dump end ]------------
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x1010f0f successful
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_power_down: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f successful
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-icl 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask f
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp init failed after 3 attempts with err: -110
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: sof-audio-pci-intel-icl 0000:00:1f.3: Failed to start DSP
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: sof-audio-pci-intel-icl 0000:00:1f.3: error: failed to boot DSP firmware -110
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-icl 0000:00:1f.3: fw_state change: 2 -> 3
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x1d003c timedout
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_reset_enter: timeout on HDA_DSP_REG_ADSPCS read
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core reset failed: core_mask f
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-icl 0000:00:1f.3: fw_state change: 3 -> 0
Jun 29 23:18:53 sh-icl-rvp-hda-06 kernel: sof-audio-pci-intel-icl 0000:00:1f.3: error: sof_probe_work failed err: -110
@keqiaozhang You just filed this bug without any reference meaning it's a brand new regression? Never seen before? If yes it and the reproduction are is high enough then it should be quick and easy to bisect.
I just filed the bug first for daily summary, I need time to debug it, so I didn't say much in the description. I was planned to edit it after I have more clues about this issue.
- We observed this issue on ICL for the first time and I don't think we have a similar issue on other platforms.
- Not sure if it's a regression, hard to reproduce it. 500 iterations passed without errors.
@keqiaozhang, this can not be IMR boot since the final failure is after the third iteration. If there were IMR boot involved then we would have seen a failed IMR boot followed by 3 failed purge boot. Here, we have DSP boot failure when the modules are loaded and no IMR boot is requested. In the full dmesg this is clear: firmware loaded followed by the 3 failed boot attempts:
[ 6419.987297] kernel: snd_sof:snd_sof_load_firmware_raw: sof-audio-pci-intel-icl 0000:00:1f.3: request_firmware intel/sof/sof-icl.ri successful
...
[ 6419.987533] kernel: snd_sof_intel_hda_common:hda_dsp_cl_boot_firmware: sof-audio-pci-intel-icl 0000:00:1f.3: Attempting iteration 0 of Core En/ROM load...
...
[ 6420.288854] kernel: snd_sof_intel_hda_common:cl_dsp_init: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x80000]=0x6000010 timedout
...
[ 6420.288898] kernel: snd_sof_intel_hda_common:hda_dsp_cl_boot_firmware: sof-audio-pci-intel-icl 0000:00:1f.3: Attempting iteration 1 of Core En/ROM load...
...
[ 6420.590359] kernel: snd_sof_intel_hda_common:cl_dsp_init: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x80000]=0x6000010 timedout
...
[ 6420.590423] kernel: snd_sof_intel_hda_common:hda_dsp_cl_boot_firmware: sof-audio-pci-intel-icl 0000:00:1f.3: Attempting iteration 2 of Core En/ROM load...
...
[ 6420.891828] kernel: snd_sof_intel_hda_common:cl_dsp_init: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x80000]=0x6000010 timedout
[ 6420.891832] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: cl_dsp_init: timeout with rom_status_reg (0x80000) read
[ 6420.891837] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 6420.891838] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: Boot iteration failed: 3/3
[ 6420.891840] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: fw_state: SOF_FW_BOOT_IN_PROGRESS (2)
[ 6420.891860] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: 0x06000010: module: ROM, state: CSE_IMR_REQUEST, waiting for: CSE_CSR, running
[ 6420.891894] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: extended rom status: 0x6000010 0x0 0x0 0x0 0x0 0x0 0x2001182 0x0
[ 6420.891896] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 6420.891919] kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x1010f0f successful
[ 6420.891928] kernel: snd_sof_intel_hda_common:hda_dsp_core_power_down: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xf0f successful
[ 6420.891934] kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-icl 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask f
[ 6420.891936] kernel: sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp init failed after 3 attempts with err: -110
I can not recall change in the boot flow (the cold boot flow, that is) for a long time.
However the DSP do report CSE_IMR_REQUEST state, which is odd.
The logger and dmesg logs are out of sync.
logger.txt have INFO ipc: new cmd 0x90040000 which is a dtrace filter update, but there is no such a message sent according to the kernel log.
We need to move away from dmesg. We've gone a long way but we're not completely there yet:
- https://github.com/thesofproject/sof-test/issues/292
This is a very old bug and lost track. But no such issue on latest code base: stable-v2.2/4bf9059154c4 and tip sof-dev/a71433444f6b.
Closing this bug.