Skip to content

LNL/SDW AOIC: major regression with PIO commands #4889

Closed
#4896
Closed
LNL/SDW AOIC: major regression with PIO commands#4889
#4896
Labels
LNLApplies to Lunar Lake platformSDWApplies to SoundWire bus for codec connection

Description

@plbossart
plbossart
opened on Mar 28, 2024

from Intel daily tests #/result/planresultdetail/39251?model=LNLM_SDW_AIOC&testcase=check-sof-logger

[ 4685.789060] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: error: failed to reset HDA controller gctl 0x1
[ 4685.789067] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: error: failed to reset controller during suspend
[ 4685.789070] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: error: failed to power down DSP during suspend -5
[ 4685.789076] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -5)
[ 4688.184905] kernel: soundwire_intel soundwire_intel.link.0: intel_link_power_up: hdac_bus_eml_sdw_power_up failed: -5
[ 4688.184915] kernel: soundwire_intel soundwire_intel.link.0: intel_resume_runtime: power_up failed after bus reset: -5
[ 4688.184919] kernel: soundwire_intel soundwire_intel.link.0: ASoC: error at snd_soc_pcm_component_pm_runtime_get on soundwire_intel.link.0: -5
[ 4688.184923] kernel:  SDW0-Playback: ASoC: error at __soc_pcm_open on SDW0-Playback: -5
[ 4688.184926] kernel:  Jack Out: ASoC: error at dpcm_be_dai_startup on Jack Out: -5
[ 4688.184928] kernel:  Jack Out: ASoC: error at dpcm_fe_dai_startup on Jack Out: -5
[ 4688.186628] kernel: soundwire_intel soundwire_intel.link.0: ASoC: error at snd_soc_pcm_component_pm_runtime_get on soundwire_intel.link.0: -22
[ 4688.191686] kernel: soundwire_intel soundwire_intel.link.2: intel_link_power_up: hdac_bus_eml_sdw_power_up failed: -5
[ 4688.191701] kernel: soundwire_intel soundwire_intel.link.2: intel_resume_runtime: power_up failed after bus reset: -5
[ 4688.191707] kernel: soundwire_intel soundwire_intel.link.2: ASoC: error at snd_soc_pcm_component_pm_runtime_get on soundwire_intel.link.2: -5
[ 4688.191713] kernel:  SDW2-Playback: ASoC: error at __soc_pcm_open on SDW2-Playback: -5
[ 4688.191717] kernel:  Speaker: ASoC: error at dpcm_be_dai_startup on Speaker: -5
[ 4688.191721] kernel:  Speaker: ASoC: error at dpcm_fe_dai_startup on Speaker: -5
[ 4688.193344] kernel: soundwire_intel soundwire_intel.link.0: ASoC: error at snd_soc_pcm_component_pm_runtime_get on soundwire_intel.link.0: -22
[ 4688.195635] kernel: soundwire_intel soundwire_intel.link.2: ASoC: error at snd_soc_pcm_component_pm_runtime_get on soundwire_intel.link.2: -22
[ 4688.200113] kernel: soundwire_intel soundwire_intel.link.1: intel_link_power_up: hdac_bus_eml_sdw_power_up failed: -5
[ 4688.200116] kernel: soundwire_intel soundwire_intel.link.1: intel_resume_runtime: power_up failed after bus reset: -5
[ 4688.200119] kernel: soundwire_intel soundwire_intel.link.1: ASoC: error at snd_soc_pcm_component_pm_runtime_get on soundwire_intel.link.1: -5
[ 4688.200121] kernel:  SDW1-Capture: ASoC: error at __soc_pcm_open on SDW1-Capture: -5
[ 4688.200123] kernel:  Microphone: ASoC: error at dpcm_be_dai_startup on Microphone: -5
[ 4688.200124] kernel:  Microphone: ASoC: error at dpcm_fe_dai_startup on Microphone: -5

That's super bad...

manual tests run on a different device jf-lnlm-rvp-sdw-1 show this

[  363.370649] kernel: hdaudio ehdaudio0D7: no AFG or MFG node found
[  363.370671] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: device init failed for hdac device
[  367.530144] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: error: failed to reset HDA controller gctl 0x1
[  367.530180] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: error: failed to reset controller during suspend
[  367.530196] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: error: failed to power down DSP during suspend -5
[  367.530228] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -5)
[  373.581625] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc4_tx_msg_unlocked: ipc message send for 0x44000000|0x31400008 failed: -19
[  373.581627] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: sof_ipc4_set_get_data: large config set failed at offset 0: -19
[  373.671146] kernel: soundwire_intel soundwire_intel.link.0: intel_link_power_up: hdac_bus_eml_sdw_power_up failed: -5
[  373.671168] kernel: soundwire_intel soundwire_intel.link.0: intel_resume failed: -5
[  373.671178] kernel: soundwire_intel soundwire_intel.link.0: PM: dpm_run_callback(): pm_generic_resume+0x0/0x30 returns -5
[  373.671215] kernel: soundwire_intel soundwire_intel.link.0: PM: failed to resume: error -5
[  373.674568] kernel: soundwire_intel soundwire_intel.link.1: intel_link_power_up: hdac_bus_eml_sdw_power_up failed: -5
[  373.674570] kernel: soundwire_intel soundwire_intel.link.1: intel_resume failed: -5
[  373.674571] kernel: soundwire_intel soundwire_intel.link.1: PM: dpm_run_callback(): pm_generic_resume+0x0/0x30 returns -5
[  373.674575] kernel: soundwire_intel soundwire_intel.link.1: PM: failed to resume: error -5
[  373.677853] kernel: soundwire_intel soundwire_intel.link.2: intel_link_power_up: hdac_bus_eml_sdw_power_up failed: -5
[  373.677855] kernel: soundwire_intel soundwire_intel.link.2: intel_resume failed: -5
[  373.677856] kernel: soundwire_intel soundwire_intel.link.2: PM: dpm_run_callback(): pm_generic_resume+0x0/0x30 returns -5
[  373.677858] kernel: soundwire_intel soundwire_intel.link.2: PM: failed to resume: error -5
[  373.681192] kernel: soundwire_intel soundwire_intel.link.3: intel_link_power_up: hdac_bus_eml_sdw_power_up failed: -5
[  373.681193] kernel: soundwire_intel soundwire_intel.link.3: intel_resume failed: -5
[  373.681194] kernel: soundwire_intel soundwire_intel.link.3: PM: dpm_run_callback(): pm_generic_resume+0x0/0x30 returns -5
[  373.681196] kernel: soundwire_intel soundwire_intel.link.3: PM: failed to resume: error -5
[  373.787757] kernel: soundwire_intel soundwire_intel.link.3: sdw_cdns_clock_stop failed: IP_MCP_CONTROL_SW_RST is not cleared
[  373.789266] kernel: soundwire_intel soundwire_intel.link.3: sdw_cdns_clock_stop failed: MCP_CONTROL_CMD_RST is not cleared
[  373.789363] kernel: soundwire_intel soundwire_intel.link.3: sdw_cdns_clock_stop failed: MCP_CONTROL_SOFT_RST is not cleared
[  373.790132] kernel: soundwire_intel soundwire_intel.link.3: sdw_cdns_clock_stop failed: MCP_CONTROL_CLK_STOP_CLR is not cleared
[  373.790136] kernel: soundwire_intel soundwire_intel.link.3: sdw_cdns_clock_stop failed: MCP_CONFIG_UPDATE_BIT is not cleared
[  373.790138] kernel: soundwire_intel soundwire_intel.link.3: sdw_cdns_clock_stop failed: MCP_CONTROL_HW_RST is not cleared
[  373.790155] kernel: soundwire_intel soundwire_intel.link.2: sdw_cdns_clock_stop failed: IP_MCP_CONTROL_SW_RST is not cleared
[  373.790159] kernel: soundwire_intel soundwire_intel.link.2: sdw_cdns_clock_stop failed: MCP_CONTROL_CMD_RST is not cleared
[  373.790160] kernel: soundwire_intel soundwire_intel.link.2: sdw_cdns_clock_stop failed: MCP_CONTROL_SOFT_RST is not cleared
[  373.790162] kernel: soundwire_intel soundwire_intel.link.2: sdw_cdns_clock_stop failed: MCP_CONTROL_CLK_STOP_CLR is not cleared
[  373.790175] kernel: soundwire_intel soundwire_intel.link.2: sdw_cdns_clock_stop failed: MCP_CONFIG_UPDATE_BIT is not cleared
[  373.790177] kernel: soundwire_intel soundwire_intel.link.2: sdw_cdns_clock_stop failed: MCP_CONTROL_HW_RST is not cleared
[  373.790189] kernel: soundwire_intel soundwire_intel.link.1: sdw_cdns_clock_stop failed: IP_MCP_CONTROL_SW_RST is not cleared
[  373.790192] kernel: soundwire_intel soundwire_intel.link.1: sdw_cdns_clock_stop failed: MCP_CONTROL_CMD_RST is not cleared
[  373.790194] kernel: soundwire_intel soundwire_intel.link.1: sdw_cdns_clock_stop failed: MCP_CONTROL_SOFT_RST is not cleared
[  373.790195] kernel: soundwire_intel soundwire_intel.link.1: sdw_cdns_clock_stop failed: MCP_CONTROL_CLK_STOP_CLR is not cleared
[  373.790198] kernel: soundwire_intel soundwire_intel.link.1: sdw_cdns_clock_stop failed: MCP_CONFIG_UPDATE_BIT is not cleared
[  373.790209] kernel: soundwire_intel soundwire_intel.link.1: sdw_cdns_clock_stop failed: MCP_CONTROL_HW_RST is not cleared
[  373.790220] kernel: soundwire_intel soundwire_intel.link.0: sdw_cdns_clock_stop failed: IP_MCP_CONTROL_SW_RST is not cleared
[  373.790245] kernel: soundwire_intel soundwire_intel.link.0: sdw_cdns_clock_stop failed: MCP_CONTROL_CMD_RST is not cleared
[  373.790247] kernel: soundwire_intel soundwire_intel.link.0: sdw_cdns_clock_stop failed: MCP_CONTROL_SOFT_RST is not cleared
[  373.790249] kernel: soundwire_intel soundwire_intel.link.0: sdw_cdns_clock_stop failed: MCP_CONTROL_CLK_STOP_CLR is not cleared
[  373.790251] kernel: soundwire_intel soundwire_intel.link.0: sdw_cdns_clock_stop failed: MCP_CONFIG_UPDATE_BIT is not cleared
[  373.790253] kernel: soundwire_intel soundwire_intel.link.0: sdw_cdns_clock_stop failed: MCP_CONTROL_HW_RST is not cleared

which is even worse - something is clearly not quite right.

We'll need to bisect this one further, I don't recall seeing all this before. @fredoh9 @marc-hb @bardliao @kv2019i @ujfalusi FYI

Activity

  1. plbossart commented on Mar 28, 2024

    @plbossart
    plbossart
    on Mar 28, 2024
    MemberAuthor

    It looks like this is an issue with kmod-load-unload tests that get stuck, and then suspend happens due to idleness and everything goes South

    TPLG=/lib/firmware/intel/sof-ipc4-tplg/sof-lnl-rt711-l0-rt1316-l23-rt714-l1.tplg MODEL=LNLM_SDW_AIOC SOF_TEST_INTERVAL=5 /root/sof-test/test-case/check-kmod-load-unload.sh |

    [   37.010608] snd_soc_rt711_sdca:rt711_sdca_interrupt_callback: rt711-sdca sdw:0:0:025d:0711:01: rt711_sdca_interrupt_callback control_port_stat=4, sdca_cascade=1
[   37.011085] input: sof-soundwire Headset Jack as /devices/pci0000:00/0000:00:1f.3/sof_sdw/sound/card0/input5
[   37.011689] soundwire_cadence:cdns_update_slave_status_work: soundwire_intel soundwire_intel.link.0: Slave status change: 0x20000000
[   37.042263] snd_soc_rt711_sdca:rt711_sdca_headset_detect: rt711-sdca sdw:0:0:025d:0711:01: rt711_sdca_headset_detect, detected_mode=0x0
[   37.042271] snd_soc_rt711_sdca:rt711_sdca_jack_detect_handler: rt711-sdca sdw:0:0:025d:0711:01: in rt711_sdca_jack_detect_handler, jack_type=0x0
[   37.042273] snd_soc_rt711_sdca:rt711_sdca_jack_detect_handler: rt711-sdca sdw:0:0:025d:0711:01: in rt711_sdca_jack_detect_handler, btn_type=0x0
[   37.042275] snd_soc_rt711_sdca:rt711_sdca_jack_detect_handler: rt711-sdca sdw:0:0:025d:0711:01: in rt711_sdca_jack_detect_handler, scp_sdca_stat1=0x1, scp_sdca_stat2=0x0
[   37.439398] snd_soc_rt711_sdca:rt711_sdca_interrupt_callback: rt711-sdca sdw:0:0:025d:0711:01: rt711_sdca_interrupt_callback control_port_stat=4, sdca_cascade=1
[   37.473795] snd_soc_rt711_sdca:rt711_sdca_headset_detect: rt711-sdca sdw:0:0:025d:0711:01: rt711_sdca_headset_detect, detected_mode=0x3
[   37.473826] snd_soc_rt711_sdca:rt711_sdca_jack_detect_handler: rt711-sdca sdw:0:0:025d:0711:01: in rt711_sdca_jack_detect_handler, jack_type=0x1
[   37.473841] snd_soc_rt711_sdca:rt711_sdca_jack_detect_handler: rt711-sdca sdw:0:0:025d:0711:01: in rt711_sdca_jack_detect_handler, btn_type=0x0
[   37.473853] snd_soc_rt711_sdca:rt711_sdca_jack_detect_handler: rt711-sdca sdw:0:0:025d:0711:01: in rt711_sdca_jack_detect_handler, scp_sdca_stat1=0x1, scp_sdca_stat2=0x0
[   40.502777] soundwire_bus:sdw_bus_wait_for_clk_prep_deprep: soundwire sdw-master-0-3: clock stop prepare done slave:15
[   40.502905] soundwire_bus:sdw_bus_wait_for_clk_prep_deprep: soundwire sdw-master-0-2: clock stop prepare done slave:15
[   40.502978] soundwire_bus:sdw_bus_wait_for_clk_prep_deprep: soundwire sdw-master-0-1: clock stop prepare done slave:15
[   40.503038] soundwire_bus:sdw_bus_wait_for_clk_prep_deprep: soundwire sdw-master-0-0: clock stop prepare done slave:15
[   40.503609] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc tx      : 0x44000000|0x3060004c: MOD_LARGE_CONFIG_SET [data size: 76]
[   40.504345] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc tx reply: 0x64000000|0x3060004c: MOD_LARGE_CONFIG_SET
[   40.504418] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc tx done : 0x44000000|0x3060004c: MOD_LARGE_CONFIG_SET [data size: 76]
[   40.506576] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc tx      : 0x47000000|0x0: MOD_SET_DX [data size: 8]
[   40.664042] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc tx reply: 0x67000000|0x0: MOD_SET_DX
[   40.664130] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc tx done : 0x47000000|0x0: MOD_SET_DX [data size: 8]
[   40.664325] snd_sof_pci_intel_mtl:mtl_enable_interrupts: sof-audio-pci-intel-lnl 0000:00:1f.3: FW Poll Status: reg[0x1800]=0x0 successful
[   40.664369] snd_sof_pci_intel_mtl:mtl_enable_interrupts: sof-audio-pci-intel-lnl 0000:00:1f.3: FW Poll Status: reg[0x1140]=0x0 successful
[   40.665467] snd_sof_pci_intel_mtl:mtl_dsp_core_power_down: sof-audio-pci-intel-lnl 0000:00:1f.3: FW Poll Status: reg[0x178d04]=0x2000000 successful
[   40.666758] snd_sof_pci_intel_mtl:mtl_power_down_dsp: sof-audio-pci-intel-lnl 0000:00:1f.3: FW Poll Status: reg[0x1000]=0x0 successful
[   40.666872] snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-lnl 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
[   40.666892] snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-lnl 0000:00:1f.3: Debug PCIW: 00000010 at  00000044
[   40.766852] sof-audio-pci-intel-lnl 0000:00:1f.3: error: failed to reset HDA controller gctl 0x1
[   40.766892] sof-audio-pci-intel-lnl 0000:00:1f.3: error: failed to reset controller during suspend
[   40.766911] sof-audio-pci-intel-lnl 0000:00:1f.3: error: failed to power down DSP during suspend -5
[   40.766931] snd_sof:sof_set_fw_state: sof-audio-pci-intel-lnl 0000:00:1f.3: fw_state change: 7 -> 0
[   40.766949] sof-audio-pci-intel-lnl 0000:00:1f.3: can't suspend (snd_sof_runtime_suspend [snd_sof] returned -5)

    I guess we need to sort this out...I don't recall seeing all this when I was doing all my LNL BPT/BRA work a couple of months ago.

    @bardliao if you can reproduce/confirm the issue that would be great.

  2. plbossart
    added
    SDWApplies to SoundWire bus for codec connection
    LNLApplies to Lunar Lake platform
    on Mar 28, 2024

  3. marc-hb commented on Mar 29, 2024

    @marc-hb
    marc-hb
    on Mar 29, 2024
    Collaborator

    I don't remember anything that bad recently so it should be bisectable somehow.

  4. plbossart commented on Mar 29, 2024

    @plbossart
    plbossart
    on Mar 29, 2024
    MemberAuthor

    I went back to the last PR I tested on this platform, which was precisely aimed at fixing kmod-load-unload issues
    #4849 commit 32f632b

    With this branch, I don't see any error proper at the kernel level. The sof-test do fail however, but I have no explanation for the results.

    declare -- cmd="journalctl_cmd --since=@1711729127"
2024-03-29 16:18:49 UTC [INFO] checking if firmware is loaded successfully
Polling 'sof_firmware_boot_complete --since=@1711729127' every 1s for 3s
2024-03-29 16:18:52 UTC [ERROR] Failed to load firmware after module insertion
2024-03-29 16:18:52 UTC [INFO] Starting func_exit_handler(1)
2024-03-29 16:18:52 UTC [ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2024-03-29 16:18:52 UTC [ERROR]  die()  @  /root/sof-test/case-lib/lib.sh
2024-03-29 16:18:52 UTC [ERROR]  main()  @  /root/sof-test/test-case/check-kmod-load-unload.sh:97
2024-03-29 16:18:52 UTC [INFO] pkill -TERM -f mtrace-reader.py
2024-03-29 16:18:52 UTC [ERROR] mtrace-reader.py was already dead
2024-03-29 16:18:52 UTC [INFO] ktime=511 sof-test PID=2665: ending
2024-03-29 16:18:52 UTC [INFO] Test Result: FAIL!

    log.txt

  5. plbossart commented on Mar 29, 2024

    @plbossart
    plbossart
    on Mar 29, 2024
    MemberAuthor

    The firmware boot complete log is show in dmesg

    [ 1099.218270] snd_sof:snd_sof_run_firmware: sof-audio-pci-intel-lnl 0000:00:1f.3: firmware boot complete

    But somehow we need to wait a bit on this platform.

    root@jf-lnlm-rvp-sdw-1:~/sof-test# tools/kmod/sof_insert.sh 
MODPROBE	snd_soc_da7213		 
MODPROBE	snd_soc_da7219		 
MODPROBE	snd_soc_pcm512x_i2c		 
MODPROBE	snd_soc_wm8804_i2c		 
MODPROBE	snd_soc_rt274		 
MODPROBE	snd_soc_rt286		 
MODPROBE	snd_soc_rt298		 
MODPROBE	snd_soc_rt700		 
MODPROBE	snd_soc_rt711		 
MODPROBE	snd_soc_rt711_sdca		 
MODPROBE	snd_soc_rt712_sdca		 
MODPROBE	snd_soc_rt712_sdca_dmic		 
MODPROBE	snd_soc_rt715		 
MODPROBE	snd_soc_rt715_sdca		 
MODPROBE	snd_soc_rt1308		 
MODPROBE	snd_soc_rt1308_sdw		 
MODPROBE	snd_soc_rt1316_sdw		 
MODPROBE	snd_soc_rt1318_sdw		 
MODPROBE	snd_soc_sdw_mockup		 
MODPROBE	snd_soc_rt1011		 
MODPROBE	snd_soc_rt5640		 
MODPROBE	snd_soc_rt5645		 
MODPROBE	snd_soc_rt5651		 
MODPROBE	snd_soc_rt5660		 
MODPROBE	snd_soc_rt5670		 
MODPROBE	snd_soc_rt5677		 
MODPROBE	snd_soc_rt5677_spi		 
MODPROBE	snd_soc_rt5682_i2c		 
MODPROBE	snd_soc_rt5682_sdw		 
MODPROBE	snd_soc_max98090		 
MODPROBE	snd_soc_ts3a227e		 
MODPROBE	snd_soc_max98357a		 
MODPROBE	snd_soc_max98363		 
MODPROBE	snd_soc_max98373_sdw		 
MODPROBE	snd_soc_max98373_i2c		 
MODPROBE	snd_soc_max98390		 
MODPROBE	snd_soc_es8316		 
MODPROBE	snd_soc_es8326		 
SKIP    	snd_soc_wm8960 	(not in tree)
MODPROBE	snd_sof		 
MODPROBE	snd_sof_acpi		 
MODPROBE	snd_sof_acpi_intel_byt		 
MODPROBE	snd_sof_acpi_intel_bdw		 
MODPROBE	snd_sof_pci		 
MODPROBE	snd_sof_pci_intel_tng		 
MODPROBE	snd_sof_pci_intel_skl		 
MODPROBE	snd_sof_pci_intel_apl		 
MODPROBE	snd_sof_pci_intel_cnl		 
MODPROBE	snd_sof_pci_intel_icl		 
MODPROBE	snd_sof_pci_intel_tgl		 
MODPROBE	snd_sof_pci_intel_mtl		 
MODPROBE	snd_sof_pci_intel_lnl		 
SKIP    	snd_sof_of 	(not in tree)
SKIP    	imx_common 	(not in tree)
MODPROBE	snd_sof_xtensa_dsp		 
SKIP    	snd_sof_imx8 	(not in tree)
SKIP    	snd_sof_imx8m 	(not in tree)
MODPROBE	snd_usb_audio		 
root@jf-lnlm-rvp-sdw-1:~/sof-test# dmesg | grep -i 'sof.*firmware[[:blank:]]*boot[[:blank:]]*complete'
root@jf-lnlm-rvp-sdw-1:~/sof-test# dmesg | grep -i 'sof.*firmware[[:blank:]]*boot[[:blank:]]*complete'
[ 1462.942576] snd_sof:snd_sof_run_firmware: sof-audio-pci-intel-lnl 0000:00:1f.3: firmware boot complete

    The boot complete is only shown in the second filter. The boot takes a bit more time, probably because of some delay somewhere.

    @marc-hb @fredoh9 can you remind me how this is configured?

  6. plbossart commented on Mar 29, 2024

    @plbossart
    plbossart
    on Mar 29, 2024
    MemberAuthor

    At any rate, this error is 100% reproducible with the latest kernel topic/sof-dev commit f3f97ec

    sof-test/tools/kmod/sof_remove.sh
    sof-test/tools/kmod/sof_insert.sh

    This also happens with the PR #4849 merged at commit b506cd8

    So my money is on merges between

    a) the base of PR #4849
    Merge pull request #4805 from ujfalusi/merge/sound-upstream-20240205 8ea8586

    b) intermediate point
    Merge pull request #4815 from ujfalusi/merge/sound-upstream-20240213
    1cf5eac

    c)
    and the base where this PR #4849 was merged.
    Merge pull request #4850 from plbossart/merge/sound-upstream-20240306 19db44b

    Gah.

  7. plbossart commented on Mar 29, 2024

    @plbossart
    plbossart
    on Mar 29, 2024
    MemberAuthor

    b) seems to work fine, so now bisecting between b) and c)...

  8. plbossart commented on Mar 29, 2024

    @plbossart
    plbossart
    on Mar 29, 2024
    MemberAuthor

    Very surprising results @ujfalusi @marc-hb

    9bb1cad55c2a5e0acad1528bd00953fcf61b138a is the first bad commit
commit 9bb1cad55c2a5e0acad1528bd00953fcf61b138a
Author: Peter Ujfalusi <peter.ujfalusi@linux.intel.com>
Date:   Wed Mar 6 11:11:41 2024 +0200

    ASoC: SOF: Intel: hda-bus: Use PIO mode for Lunar Lake
    
    It is recommended that on Lunar Lake the PIO (immediate command response)
    is used instead of CORB/RIRB for commands/verbs.
    
    Signed-off-by: Peter Ujfalusi <peter.ujfalusi@linux.intel.com>

 sound/soc/sof/intel/hda-bus.c | 5 +++++
 1 file changed, 5 insertions(+)
  9. plbossart
    added a commit that references this issue on Mar 29, 2024

    Revert "ASoC: SOF: Intel: hda-bus: Use PIO mode for Lunar Lake"

    4321b72

  10. plbossart commented on Mar 29, 2024

    @plbossart
    plbossart
    on Mar 29, 2024
    MemberAuthor

    I can confirm that reverting this commit solves the issue on LNL SDW AOIC - no problem with the controller. Without this patch, we can see this error 100% during kmod load/unload tests

    [ 4685.789060] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: error: failed to reset HDA controller gctl 0x1
[ 4685.789067] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: error: failed to reset controller during suspend
[ 4685.789070] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: error: failed to power down DSP during suspend -5
  11. plbossart
    changed the title [-]LNL/SDW AOIC tests fail big time[/-] [+]LNL/SDW AOIC: major regression with PIO commands[/+] on Mar 29, 2024

  12. plbossart commented on Mar 29, 2024

    @plbossart
    plbossart
    on Mar 29, 2024
    MemberAuthor

    @kv2019i @ujfalusi comments welcome. There are three possible explanations I could come up with:

    a) the SoundWire solution relies on hdac_hda for LNL, so maybe setting the pio has a side effect in the SoundWire flows?
    b) there's something problematic with the PIO commands used for DisplayAudio and this has ripple effects.
    c) the PIO commands require something additional to make sure all in-flights command complete before resetting the controller

    At any rate it's urgent that LNL be added to kernel PR CI and the daily tests looked at more closely.

  13. plbossart
    added a commit that references this issue on Apr 1, 2024

    ASoC: SOF: Intel: hda-ctrl: add missing WAKE_STS clear

    fb332ed

  14. ujfalusi commented on Apr 2, 2024

    @ujfalusi
    ujfalusi
    on Apr 2, 2024
    Collaborator

    I can confirm that reverting this commit solves the issue on LNL SDW AOIC - no problem with the controller. Without this patch, we can see this error 100% during kmod load/unload tests

    [ 4685.789060] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: error: failed to reset HDA controller gctl 0x1
[ 4685.789067] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: error: failed to reset controller during suspend
[ 4685.789070] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: error: failed to power down DSP during suspend -5

    That series should have only effect on CORB/RIRB handling, which afaik only used for HDA links, not SDW.

  15. ujfalusi commented on Apr 2, 2024

    @ujfalusi
    ujfalusi
    on Apr 2, 2024
    Collaborator

    @kv2019i @ujfalusi comments welcome. There are three possible explanations I could come up with:

    a) the SoundWire solution relies on hdac_hda for LNL, so maybe setting the pio has a side effect in the SoundWire flows?
    b) there's something problematic with the PIO commands used for DisplayAudio and this has ripple effects.
    c) the PIO commands require something additional to make sure all in-flights command complete before resetting the controller

    At any rate it's urgent that LNL be added to kernel PR CI and the daily tests looked at more closely.

    d) what about the WAKE_STS clear patch? The PIO mode somehow brought this deficit up? Doing that only for SDW where the CORB should not been used in the first place?

  16. ujfalusi commented on Apr 2, 2024

    @ujfalusi
    ujfalusi
    on Apr 2, 2024
    Collaborator

    @plbossart, @marc-hb, just for the record: before merging #4844 we run several rounds of LNL tests in CI (I think they were daily tests) on it and all came back clean.

  17. ujfalusi commented on Apr 2, 2024

    @ujfalusi
    ujfalusi
    on Apr 2, 2024
    Collaborator

    @plbossart, with this diff we will know if SDW is using the command interface on LNL:

    diff --git a/sound/hda/hdac_controller.c b/sound/hda/hdac_controller.c
index b5c833b9f8b9..c40bed8469d9 100644
--- a/sound/hda/hdac_controller.c
+++ b/sound/hda/hdac_controller.c
@@ -383,6 +383,8 @@ static int snd_hdac_bus_get_response_rirb(struct hdac_bus *bus,
  */
 int snd_hdac_bus_send_cmd(struct hdac_bus *bus, unsigned int val)
 {
+	dev_warn(bus->dev, "[HDA command infra] %s - ENTER (val: %#x)",
+		 __func__, val);
 	if (bus->use_pio_for_commands)
 		return snd_hdac_bus_send_cmd_pio(bus, val);
 
@@ -401,6 +403,8 @@ EXPORT_SYMBOL_GPL(snd_hdac_bus_send_cmd);
 int snd_hdac_bus_get_response(struct hdac_bus *bus, unsigned int addr,
 			      unsigned int *res)
 {
+	dev_warn(bus->dev, "[HDA command infra] %s - ENTER (addr: %#x)",
+		 __func__, addr);
 	if (bus->use_pio_for_commands)
 		return snd_hdac_bus_get_response_pio(bus, addr, res);

    then

    dmesg -w | grep "HDA command infra"

  18. ujfalusi commented on Apr 2, 2024

    @ujfalusi
    ujfalusi
    on Apr 2, 2024
    Collaborator

    Interestingly the issue is visible even before the PIO mode, see test result 38429, it is from 01.03.2024, so it is not caused by the PIO support we just overlooked it before...
    I'm not sure which is the better thing.

  19. plbossart
    added a commit that references this issue on Apr 2, 2024

    ASoC: SOF: Intel: hda-ctrl: add missing WAKE_STS clear

    f6018f6
  20. plbossart
    closed this as completedin #4896on Apr 4, 2024
  21. plbossart
    added 2 commits that reference this issue on Apr 4, 2024

    ASoC: SOF: Intel: hda-ctrl: add missing WAKE_STS clear

    b02b375

    ASoC: SOF: Intel: hda-ctrl: add missing WAKE_STS clear

    0ee0fd0
  22. intel-lab-lkp
    added a commit that references this issue on Apr 8, 2024

    ASoC: SOF: Intel: hda-ctrl: add missing WAKE_STS clear

    bd5863f
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    LNLApplies to Lunar Lake platformSDWApplies to SoundWire bus for codec connection

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions