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.

Sign up for GitHub

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

Jump to bottom

[BUG][JSL]Failed to load FW on JSL #8625

Closed
Henrythek opened this issue Dec 14, 2023 · 12 comments
Closed

[BUG][JSL]Failed to load FW on JSL #8625

Henrythek opened this issue Dec 14, 2023 · 12 comments
Labels
bug Something isn't working as expected

Comments

@Henrythek
Copy link

Describe the bug

The sof DSP failed to boot and the dmesg shows FW Poll Status: reg[0x4]=0xffffffff

timedout on JSL.

The problem looks like #4916 but the error code is different.

To Reproduce

Select to use sof on JSL.

Reproduction Rate

10/10

Expected behavior

DSP firmware boots normally and the start-up process goes on.

Impact

firmware boot failure.

Environment

  1. Kernel: 6.3.0
  2. SOF: 2.0 [sof-bin/v2.0.x/sof-v2.0 at main · thesofproject/sof-bin (github.com)](https://github.com/thesofproject/sof-bin/tree/main/v2.0.x/sof-v2.0)
  3. Platform: JSL

Screenshots or console output

[ 4.523805] snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xffffffff successful
[ 4.574055] snd_sof_intel_hda_common:hda_dsp_core_power_down: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xffffffff timedout
[ 4.574062] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_power_down: timeout on HDA_DSP_REG_ADSPCS read
[ 4.574066] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core power down fail mask 3: -110
[ 4.574069] 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...
[ 4.574075] snd_sof_intel_hda_common:hda_dsp_core_power_up: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xffffffff successful
[ 4.624432] snd_sof_intel_hda_common:hda_dsp_core_reset_leave: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xffffffff timedout
[ 4.624440] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_reset_leave: timeout on HDA_DSP_REG_ADSPCS read
[ 4.624444] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core start failed -110
[ 4.624449] sof-audio-pci-intel-icl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 4.624450] sof-audio-pci-intel-icl 0000:00:1f.3: Boot iteration failed: 3/3
[ 4.624452] sof-audio-pci-intel-icl 0000:00:1f.3: fw_state: SOF_FW_BOOT_IN_PROGRESS (2)
[ 4.624457] sof-audio-pci-intel-icl 0000:00:1f.3: 0xffffffff: unknown ROM status value
[ 4.624476] sof-audio-pci-intel-icl 0000:00:1f.3: extended rom status: 0xffffffff 0xffffffff 0xffffffff 0xffffffff 0xffffffff 0xffffffff 0xffffffff 0xffffffff
[ 4.624478] sof-audio-pci-intel-icl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 4.624485] snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xffffffff successful
[ 4.674531] snd_sof_intel_hda_common:hda_dsp_core_power_down: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xffffffff timedout
[ 4.674540] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_power_down: timeout on HDA_DSP_REG_ADSPCS read
[ 4.674544] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core power down fail mask 3: -110
[ 4.674547] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp init failed after 3 attempts with err: -5
[ 4.674566] sof-audio-pci-intel-icl 0000:00:1f.3: Failed to start DSP
[ 4.674568] sof-audio-pci-intel-icl 0000:00:1f.3: error: failed to boot DSP firmware -5
[ 4.674571] snd_sof:sof_set_fw_state: sof-audio-pci-intel-icl 0000:00:1f.3: fw_state change: 2 -> 3
[ 4.725086] 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
[ 4.725094] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_reset_enter: timeout on HDA_DSP_REG_ADSPCS read
[ 4.725098] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core reset failed: core_mask 3
[ 4.725293] snd_sof:sof_set_fw_state: sof-audio-pci-intel-icl 0000:00:1f.3: fw_state change: 3 -> 0
[ 4.725296] sof-audio-pci-intel-icl 0000:00:1f.3: error: sof_probe_work failed err: -5
dmesg1.log
@Henrythek Henrythek added the bug Something isn't working as expected label Dec 14, 2023
@keqiaozhang
Copy link
Collaborator

@Henrythek please try with https://github.com/thesofproject/sof-bin/tree/main/v2.2.x/sof-v2.2/

@Henrythek
Copy link
Author

@keqiaozhang I tried sof-v2.2 but it still doesn't work.
Here is the dmesg log, it looks like the same error:
[ 4.451633] sof-audio-pci-intel-icl 0000:00:1f.3: DSP detected with PCI class/subclass/prog-if info 0x040100
[ 4.451756] sof-audio-pci-intel-icl 0000:00:1f.3: enabling device (0000 -> 0002)
[ 4.452021] sof-audio-pci-intel-icl 0000:00:1f.3: DSP detected with PCI class/subclass/prog-if 0x040100
[ 4.452192] sof-audio-pci-intel-icl 0000:00:1f.3: bound 0000:00:02.0 (ops i915_audio_component_bind_ops [i915])
[ 4.459520] sof-audio-pci-intel-icl 0000:00:1f.3: use msi interrupt mode
[ 4.505779] sof-audio-pci-intel-icl 0000:00:1f.3: NHLT_DEVICE_I2S detected, ssp_mask 0x1
[ 4.505788] sof-audio-pci-intel-icl 0000:00:1f.3: Overriding topology with MCLK mask 0x1 from NHLT
[ 4.505791] sof-audio-pci-intel-icl 0000:00:1f.3: hda codecs found, mask 4
[ 4.562696] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_reset_leave: timeout on HDA_DSP_REG_ADSPCS read
[ 4.613056] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_power_down: timeout on HDA_DSP_REG_ADSPCS read
[ 4.613133] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core power down fail mask 3: -110
[ 4.663664] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_reset_leave: timeout on HDA_DSP_REG_ADSPCS read
[ 4.714889] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_power_down: timeout on HDA_DSP_REG_ADSPCS read
[ 4.714899] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core power down fail mask 3: -110
[ 4.765238] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_reset_leave: timeout on HDA_DSP_REG_ADSPCS read
[ 4.765248] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core start failed -110
[ 4.765252] sof-audio-pci-intel-icl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 4.765254] sof-audio-pci-intel-icl 0000:00:1f.3: Boot iteration failed: 3/3
[ 4.765256] sof-audio-pci-intel-icl 0000:00:1f.3: fw_state: SOF_FW_BOOT_IN_PROGRESS (2)
[ 4.765261] sof-audio-pci-intel-icl 0000:00:1f.3: 0xffffffff: unknown ROM status value
[ 4.765282] sof-audio-pci-intel-icl 0000:00:1f.3: extended rom status: 0xffffffff 0xffffffff 0xffffffff 0xffffffff 0xffffffff 0xffffffff 0xffffffff 0xffffffff
[ 4.765284] sof-audio-pci-intel-icl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 4.815655] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_power_down: timeout on HDA_DSP_REG_ADSPCS read
[ 4.815664] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core power down fail mask 3: -110
[ 4.815667] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp init failed after 3 attempts with err: -5
[ 4.815680] sof-audio-pci-intel-icl 0000:00:1f.3: Failed to start DSP
[ 4.815682] sof-audio-pci-intel-icl 0000:00:1f.3: error: failed to boot DSP firmware -5
[ 4.866197] RTL8211E Gigabit Ethernet r8169-0-100:00: attached PHY driver (mii_bus:phy_addr=r8169-0-100:00, irq=MAC)
[ 4.866406] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_reset_enter: timeout on HDA_DSP_REG_ADSPCS read
[ 4.866426] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core reset failed: core_mask 3
[ 4.866805] sof-audio-pci-intel-icl 0000:00:1f.3: error: sof_probe_work failed err: -5
dmesg2.log

@lgirdwood
Copy link
Member

I think something odd here as IIRC I2S and HDA may be using the same pins. I've also not seen both HDA and I2S codec used together on a device at the same time. There are codecs that can switch between I2S mode and HDA mode though,.

> [ 4.505779] sof-audio-pci-intel-icl 0000:00:1f.3: NHLT_DEVICE_I2S detected, ssp_mask 0x1
> [ 4.505788] sof-audio-pci-intel-icl 0000:00:1f.3: Overriding topology with MCLK mask 0x1 from NHLT
> [ 4.505791] sof-audio-pci-intel-icl 0000:00:1f.3: hda codecs found, mask 4
> [ 4.562696] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_reset_leave: timeout on HDA_DSP_REG_ADSPCS read
> [ 4.613056] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_power_down: timeout on HDA_DSP_REG_ADSPCS read
> [ 4.613133] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core power down fail mask 3: -110

e.g. the NHLT is data supplied by the OEM and it can occasionally contain data errors and this makes me suspicious the NHLT is wrong.

[    0.375525] Hardware name: To be filled by O.E.M. To be filled by O.E.M./To be filled by O.E.M., BIOS XMSY-BI-M8_J_X01R110-F00A-000-8.5W-90C-B 06/08/2022
[    0.375527] Call Trace:
[    0.375530]  <TASK>
[    0.375532]  dump_stack_lvl+0x48/0x70
[    0.375538]  dump_stack+0x10/0x20
[    0.375540]  sysfs_warn_dup+0x5c/0x70
[    0.375543]  sysfs_do_create_link_sd.isra.0+0xd6/0xe0
[    0.375546]  sysfs_create_link+0x25/0x40
[    0.375547]  device_add+0x2cf/0x860
[    0.375551]  __power_supply_register+0x26b/0x450
[    0.375554]  power_supply_register+0x13/0x20
[    0.375556]  acpi_ac_add+0x117/0x1d0
[    0.375559]  acpi_device_probe+0x47/0x180

@Henrythek are you able to describe the HW in more detail. What codec HDA or I2S does the device use, if its HDA you will need to override the NHLT data. @plbossart @ujfalusi fyi.

@Henrythek
Copy link
Author

@lgirdwood The device use ES8336 as IIS codec, here is the APIC NHLT DSDT, please check.
DSDT shows ES8336 here:
Name (_ADR, Zero) // _ADR: Address
Name (_HID, "ESSX8336") // _HID: Hardware ID
Name (_CID, "ESSX8336") // _CID: Compatible ID
Name (_DDN, "ES8336") // _DDN: DOS Device Name
Name (_UID, One) // _UID: Unique ID
APIC.log
DSDT.log
NHLT.log

@keqiaozhang
Copy link
Collaborator

Very interesting. I have one JSL device uses a ES8336 as HDA codec and I installed sof-bin sof-bin-v2.2-rc1, everything is working normally.

aplay -l
**** List of PLAYBACK Hardware Devices ****
card 0: sofessx8336 [sof-essx8336], device 0: ES8336 (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: sofessx8336 [sof-essx8336], device 5: HDMI 1 (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: sofessx8336 [sof-essx8336], device 6: HDMI 2 (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: sofessx8336 [sof-essx8336], device 7: HDMI 3 (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0

@ujfalusi
Copy link
Contributor

Something more fundamental is not quite right here. We are failing to enable DSP cores so the firmware is not even booting up.

[    4.562696] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_reset_leave: timeout on HDA_DSP_REG_ADSPCS read
[    4.613056] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_power_down: timeout on HDA_DSP_REG_ADSPCS read
[    4.613133] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core power down fail mask 3: -110
[    4.663664] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_reset_leave: timeout on HDA_DSP_REG_ADSPCS read
[    4.714889] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_power_down: timeout on HDA_DSP_REG_ADSPCS read
[    4.714899] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core power down fail mask 3: -110
[    4.765238] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_reset_leave: timeout on HDA_DSP_REG_ADSPCS read
[    4.765248] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core start failed -110
[    4.765252] sof-audio-pci-intel-icl 0000:00:1f.3: ------------[ DSP dump start ]------------
[    4.765254] sof-audio-pci-intel-icl 0000:00:1f.3: Boot iteration failed: 3/3
[    4.765256] sof-audio-pci-intel-icl 0000:00:1f.3: fw_state: SOF_FW_BOOT_IN_PROGRESS (2)
[    4.765261] sof-audio-pci-intel-icl 0000:00:1f.3: 0xffffffff: unknown ROM status value
[    4.765282] sof-audio-pci-intel-icl 0000:00:1f.3: extended rom status:  0xffffffff 0xffffffff 0xffffffff 0xffffffff 0xffffffff 0xffffffff 0xffffffff 0xffffffff
[    4.765284] sof-audio-pci-intel-icl 0000:00:1f.3: ------------[ DSP dump end ]------------
[    4.815655] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_power_down: timeout on HDA_DSP_REG_ADSPCS read
[    4.815664] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core power down fail mask 3: -110
[    4.815667] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp init failed after 3 attempts with err: -5
[    4.815680] sof-audio-pci-intel-icl 0000:00:1f.3: Failed to start DSP

The DSP is just not powered up.
Earlier we have failing AC charger registration, likely caused by incorrect ACPI (double registering ADP1)

[    0.374766] ACPI: \_SB_.PR00: Found 3 idle states
[    0.375474] ACPI: AC: AC Adapter [ADP1] (on-line)
[    0.375520] sysfs: cannot create duplicate filename '/class/power_supply/ADP1'
...
[    0.375617] ac: probe of ACPI0003:01 failed with error -17

@plbossart
Copy link
Member

I am with @ujfalusi it's more likely to be a power or signature issue. We've got countless reports of issues with ES8336, but it's mostly about the codec configuration. This is more of an ACPI or DSP configuration issue.

I note that the kernel is not the mainline or stable, it's a derivative of 6.3,

[    0.000000] Linux version 6.3.0-1213 (root@everestsemi-OptiPlex-7090) (gcc (Ubuntu 9.5.0-1ubuntu1~22.04) 9.5.0, GNU ld (GNU Binutils for Ubuntu) 2.38) #6 SMP PREEMPT_DYNAMIC Wed Dec 13 11:19:21 CST 2023

so the first order of business is to update to the 6.6 kernel and re-check. We can't support a kernel we know nothing about.

@Henrythek
Copy link
Author

@plbossart The same in kernel 6.6.
dmesg3.log
I am trying to install windows to check the condition, because customers reported that in windows it's working normally，If it works normally, does it mean that the configuration of ACPI and DSP in the bios is correct?

@ujfalusi
Copy link
Contributor

@Henrythek, can you please add create /etc/modprobe.d/sof-dyndbg.conf with the following content, reboot and attach the dmesg?

# ACPI
options snd_sof_acpi dyndbg=+pmf
options snd_sof_acpi_intel_byt dyndbg=+pmf
options snd_sof_acpi_intel_bdw dyndbg=+pmf
options snd_sof_intel_byt dyndbg=+pmf
options snd_sof_intel_bdw dyndbg=+pmf

# PCI
options snd_sof_pci dyndbg=+pmf
options snd_sof_pci_intel_apl dyndbg=+pmf
options snd_sof_pci_intel_cnl dyndbg=+pmf
options snd_sof_pci_intel_icl dyndbg=+pmf
options snd_sof_pci_intel_tgl dyndbg=+pmf
options snd_sof_pci_intel_mtl dyndbg=+pmf
options snd_sof_pci_intel_lnl dyndbg=+pmf

# DSP selection
options snd_intel_dspcfg dyndbg=+pmf
options snd_intel_sdw_acpi dyndbg=+pmf

# SOF internals
options snd_sof_intel_hda_common dyndbg=+pmf
options snd_sof_intel_hda_generic dyndbg=+pmf
options snd_sof_intel_hda_mlink dyndbg=+pmf
options snd_sof_intel_hda dyndbg=+pmf
options snd_sof dyndbg=+pmf
options snd_sof_nocodec dyndbg=+pmf

# HDA
options snd_hda_intel dyndbg=+pmf
options snd-hda-codec-realtek dyndbg=+pmf
options snd-hda-codec-generic dyndbg=+pmf
options snd-hda-codec-hdmi dyndbg=+pmf
options snd-hda-codec dyndbg=+pmf

# SoundWire core
options soundwire_bus dyndbg=+pmf
options soundwire_generic_allocation dyndbg=+pmf
options soundwire_cadence dyndbg=+pmf
options soundwire_intel_init dyndbg=+pmf
options soundwire_intel dyndbg=+pmf

It looks to me that the DSP control register is constant 0xffffffff, bits are not transitioning to 0.
We never get to the point where we would be trying to load the firmware, we fail earlier when trying to unstall the core. Power up passes (it waits for bit to change to 1), unstall waits for bit to be cleared.
With dyndbg we should see the register value which results a timeout.

@Henrythek
Copy link
Author

@ujfalusi The dmesg after add /etc/modprobe.d/sof-dyndbg.conf is here, please check:
dmesg_4.log

@ujfalusi
Copy link
Contributor

Thanks for the kernel log, it confirms my suspicion:

[    4.745101] 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...
[    4.745172] snd_sof_intel_hda_common:hda_dsp_core_power_up: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xffffffff successful
[    4.795307] snd_sof_intel_hda_common:hda_dsp_core_reset_leave: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xffffffff timedout
[    4.795316] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_reset_leave: timeout on HDA_DSP_REG_ADSPCS read
[    4.795390] snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xffffffff successful
[    4.845742] snd_sof_intel_hda_common:hda_dsp_core_power_down: sof-audio-pci-intel-icl 0000:00:1f.3: FW Poll Status: reg[0x4]=0xffffffff timedout
[    4.845752] sof-audio-pci-intel-icl 0000:00:1f.3: error: hda_dsp_core_power_down: timeout on HDA_DSP_REG_ADSPCS read
[    4.845832] sof-audio-pci-intel-icl 0000:00:1f.3: error: dsp core power down fail mask 3: -110

HDA_DSP_REG_ADSPCS never changes from 0xffffffff.
HDA is accessible, but the DSP is not.

@Henrythek
Copy link
Author

Thank you for all the support. After further confirmation, it has been discovered that the issue is due to the absence of IIS in this Intel chip model.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working as expected
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@plbossart @lgirdwood @ujfalusi @keqiaozhang @Henrythek