Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

[BUG] ] audio crashes and stops working after sleep (Dell 9720 w/ Alder Lake PCH-P audio) #5212

Open
eighthave opened this issue Oct 21, 2024 · 8 comments
Assignees
Labels
bug Something isn't working P2 Critical bugs or normal features

Comments

@eighthave
Copy link

Describe the bug

The built-in audio is totally stuck, both the speaker and when I plug in a headset. It seems to be related to when the laptop is put to sleep. When I plug in a USB audio device, everything works fine. I'm the same machine as #5213, but it seems this is a different bug, based on the log output, but with the same or similar results.

To Reproduce

  1. Boot computer
  2. confirm audio works
  3. use the computer normally
  4. put the computer to sleep
  5. wake it up

Audio stuck.

Reproduction Rate

It happens most of the time after a fresh reboot. After a while, it sometimes gets unstuck and stays unstuck for a bit.

Expected behavior

Audio to work fine after sleep, and all the time.

Impact

Built-in audio does not work at all, it makes it impossible to do online meetings, listen to music, watch videos, etc.

Environment

  1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
    • Kernel: Debian's linux-image-amd64 (6.10.11-1~bpo12+1) from bookworm-backports
    • SOF: Debian's firmware-sof-signed (2.2.5-1)
  2. Name of the topology file
    • Topology: {FILE}
  3. Name of the platform(s) on which the bug is observed.
    • Platform: Debian/bookworm on amd64.

Screenshots or console output

dmesg

audio-stuck-dmesg.txt.zip

# grep -i -e 'ASoC: error' -e soundwire -e pipewire -e alsa /var/log/syslog|grep 2024-10-21
2024-10-21T06:07:25.014047+02:00 monolith kernel: [38714.518345] soundwire_intel soundwire_intel.link.0: intel_pm_prepare: pm_runtime_resume failed: -16
2024-10-21T06:07:25.014048+02:00 monolith kernel: [38714.518364] soundwire_intel soundwire_intel.link.1: intel_pm_prepare: pm_runtime_resume failed: -16
2024-10-21T06:07:25.014048+02:00 monolith kernel: [38714.518372] soundwire_intel soundwire_intel.link.2: intel_pm_prepare: pm_runtime_resume failed: -16
2024-10-21T06:07:25.014049+02:00 monolith kernel: [38714.518378] soundwire_intel soundwire_intel.link.3: intel_pm_prepare: pm_runtime_resume failed: -16
2024-10-21T06:07:25.014049+02:00 monolith kernel: [38714.519961] soundwire_intel soundwire_intel.link.3: intel_suspend: invalid config: parent is suspended
2024-10-21T06:07:25.014050+02:00 monolith kernel: [38714.519970] soundwire_intel soundwire_intel.link.2: intel_suspend: invalid config: parent is suspended
2024-10-21T06:07:25.014050+02:00 monolith kernel: [38714.519977] soundwire_intel soundwire_intel.link.1: intel_suspend: invalid config: parent is suspended
2024-10-21T06:07:25.014051+02:00 monolith kernel: [38714.519983] soundwire_intel soundwire_intel.link.0: intel_suspend: invalid config: parent is suspended
2024-10-21T06:07:25.014064+02:00 monolith kernel: [70600.180063] Modules linked in: snd_usb_audio snd_usbmidi_lib snd_rawmidi hid_jabra typec_displayport cdc_mbim cdc_wdm cdc_ncm cdc_ether usbnet r8152 mii libphy usbhid cdc_acm ccm rfcomm snd_seq_dummy snd_hrtimer snd_seq snd_seq_device cmac algif_hash algif_skcipher af_alg xt_LOG nf_log_syslog xt_tcpudp wireguard xt_conntrack libchacha20poly1305 nf_conntrack chacha_x86_64 poly1305_x86_64 nf_defrag_ipv6 nf_defrag_ipv4 nft_compat curve25519_x86_64 libcurve25519_generic libchacha ip6_udp_tunnel udp_tunnel nf_tables nfnetlink overlay qrtr snd_ctl_led snd_soc_sof_sdw snd_sof_probes snd_soc_intel_hda_dsp_common bnep snd_soc_rt711_sdca snd_soc_rt715_sdca snd_hda_codec_hdmi snd_soc_rt1316_sdw regmap_sdw_mbq regmap_sdw snd_soc_dmic binfmt_misc snd_sof_pci_intel_tgl snd_sof_pci_intel_cnl snd_sof_intel_hda_generic soundwire_intel nls_ascii soundwire_generic_allocation soundwire_cadence nls_cp437 vfat snd_sof_intel_hda_common fat snd_sof_intel_hda_mlink snd_sof_intel_hda snd_sof_pci iwlmvm snd_sof_xtensa_dsp snd_sof snd_sof_utils
2024-10-21T06:07:25.014065+02:00 monolith kernel: [70600.180096]  snd_soc_hdac_hda snd_soc_acpi_intel_match snd_soc_acpi soundwire_bus mac80211 snd_soc_avs intel_uncore_frequency intel_uncore_frequency_common x86_pkg_temp_thermal snd_soc_hda_codec intel_powerclamp snd_hda_ext_core coretemp snd_soc_core kvm_intel snd_compress snd_pcm_dmaengine libarc4 uvcvideo snd_hda_intel kvm snd_intel_dspcfg snd_intel_sdw_acpi videobuf2_vmalloc snd_hda_codec uvc videobuf2_memops videobuf2_v4l2 snd_hda_core iwlwifi snd_hwdep btusb snd_pcm videodev hid_sensor_als btrtl hid_sensor_trigger mei_pxp processor_thermal_device_pci btintel mei_hdcp dell_laptop iTCO_wdt hid_sensor_iio_common snd_timer processor_thermal_device industrialio_triggered_buffer intel_pmc_bxt btbcm dell_wmi rapl kfifo_buf processor_thermal_wt_hint intel_rapl_msr dell_smbios videobuf2_common dell_wmi_sysman btmtk dcdbas intel_cstate bluetooth intel_uncore mc dell_wmi_ddv dell_smm_hwmon pcspkr firmware_attributes_class dell_wmi_descriptor wmi_bmof industrialio iTCO_vendor_support cfg80211 processor_thermal_rfim ucsi_acpi
2024-10-21T06:07:25.014116+02:00 monolith kernel: [70600.430644] soundwire_intel soundwire_intel.link.0: Failed to power up link: -11
2024-10-21T06:07:25.014116+02:00 monolith kernel: [70600.430659] soundwire_intel soundwire_intel.link.0: intel_resume failed: -11
2024-10-21T06:07:25.014140+02:00 monolith kernel: [70600.430664] soundwire_intel soundwire_intel.link.0: PM: dpm_run_callback(): pm_generic_resume returns -11
2024-10-21T06:07:25.014142+02:00 monolith kernel: [70600.430682] soundwire_intel soundwire_intel.link.0: PM: failed to resume: error -11
2024-10-21T06:07:25.014142+02:00 monolith kernel: [70600.431792] soundwire_intel soundwire_intel.link.1: Failed to power up link: -11
2024-10-21T06:07:25.014142+02:00 monolith kernel: [70600.431796] soundwire_intel soundwire_intel.link.1: intel_resume failed: -11
2024-10-21T06:07:25.014143+02:00 monolith kernel: [70600.431800] soundwire_intel soundwire_intel.link.1: PM: dpm_run_callback(): pm_generic_resume returns -11
2024-10-21T06:07:25.014143+02:00 monolith kernel: [70600.431811] soundwire_intel soundwire_intel.link.1: PM: failed to resume: error -11
2024-10-21T06:07:25.014144+02:00 monolith kernel: [70600.432911] soundwire_intel soundwire_intel.link.2: Failed to power up link: -11
2024-10-21T06:07:25.014144+02:00 monolith kernel: [70600.432915] soundwire_intel soundwire_intel.link.2: intel_resume failed: -11
2024-10-21T06:07:25.014144+02:00 monolith kernel: [70600.432919] soundwire_intel soundwire_intel.link.2: PM: dpm_run_callback(): pm_generic_resume returns -11
2024-10-21T06:07:25.014145+02:00 monolith kernel: [70600.432928] soundwire_intel soundwire_intel.link.2: PM: failed to resume: error -11
2024-10-21T06:07:25.014145+02:00 monolith kernel: [70600.434038] soundwire_intel soundwire_intel.link.3: Failed to power up link: -11
2024-10-21T06:07:25.014145+02:00 monolith kernel: [70600.434044] soundwire_intel soundwire_intel.link.3: intel_resume failed: -11
2024-10-21T06:07:25.014146+02:00 monolith kernel: [70600.434050] soundwire_intel soundwire_intel.link.3: PM: dpm_run_callback(): pm_generic_resume returns -11
2024-10-21T06:07:25.014146+02:00 monolith kernel: [70600.434068] soundwire_intel soundwire_intel.link.3: PM: failed to resume: error -11
2024-10-21T06:07:25.016435+02:00 monolith kernel: [70600.441685] soundwire_intel soundwire_intel.link.3: sdw_cdns_clock_stop failed: IP_MCP_CONTROL_SW_RST is not cleared
2024-10-21T06:07:25.016437+02:00 monolith kernel: [70600.441690] soundwire_intel soundwire_intel.link.3: sdw_cdns_clock_stop failed: MCP_CONTROL_CLK_STOP_CLR is not cleared
2024-10-21T06:07:25.016437+02:00 monolith kernel: [70600.441692] soundwire_intel soundwire_intel.link.3: sdw_cdns_clock_stop failed: MCP_CONTROL_HW_RST is not cleared
2024-10-21T06:07:25.016438+02:00 monolith kernel: [70600.441860] soundwire_intel soundwire_intel.link.1: sdw_cdns_clock_stop failed: IP_MCP_CONTROL_SW_RST is not cleared
2024-10-21T06:07:25.016439+02:00 monolith kernel: [70600.441863] soundwire_intel soundwire_intel.link.1: sdw_cdns_clock_stop failed: MCP_CONTROL_CLK_STOP_CLR is not cleared
2024-10-21T06:07:25.016439+02:00 monolith kernel: [70600.441865] soundwire_intel soundwire_intel.link.1: sdw_cdns_clock_stop failed: MCP_CONTROL_HW_RST is not cleared
2024-10-21T06:07:25.548431+02:00 monolith kernel: [70600.971116] soundwire_intel soundwire_intel.link.3: IO transfer timed out, cmd 3 device 7 addr 45 len 1
2024-10-21T06:07:25.548440+02:00 monolith kernel: [70600.971139] soundwire sdw-master-0-3: trf on Slave 7 failed:-110 write addr 45 count 0
2024-10-21T06:07:25.548441+02:00 monolith kernel: [70600.971145] soundwire_intel soundwire_intel.link.3: prepare clock stop failed -110
2024-10-21T06:07:25.548442+02:00 monolith kernel: [70600.971147] soundwire_intel soundwire_intel.link.3: intel_stop_bus: cannot stop clock: -110
2024-10-21T06:07:25.548442+02:00 monolith kernel: [70600.971150] soundwire_intel soundwire_intel.link.3: intel_link_power_down: Unbalanced power-up/down calls
2024-10-21T06:07:25.548443+02:00 monolith kernel: [70600.971169] soundwire_intel soundwire_intel.link.2: IO transfer timed out, cmd 3 device 1 addr 45 len 1
2024-10-21T06:07:25.548443+02:00 monolith kernel: [70600.971190] soundwire sdw-master-0-2: trf on Slave 1 failed:-110 write addr 45 count 0
2024-10-21T06:07:25.548444+02:00 monolith kernel: [70600.971194] soundwire_intel soundwire_intel.link.2: prepare clock stop failed -110
2024-10-21T06:07:25.548444+02:00 monolith kernel: [70600.971195] soundwire_intel soundwire_intel.link.2: intel_stop_bus: cannot stop clock: -110
2024-10-21T06:07:25.548444+02:00 monolith kernel: [70600.971200] soundwire_intel soundwire_intel.link.1: IO transfer timed out, cmd 3 device 1 addr 45 len 1
2024-10-21T06:07:25.548444+02:00 monolith kernel: [70600.971213] soundwire sdw-master-0-1: trf on Slave 1 failed:-110 write addr 45 count 0
2024-10-21T06:07:25.548445+02:00 monolith kernel: [70600.971218] soundwire_intel soundwire_intel.link.1: prepare clock stop failed -110
2024-10-21T06:07:25.548445+02:00 monolith kernel: [70600.971219] soundwire_intel soundwire_intel.link.1: intel_stop_bus: cannot stop clock: -110
2024-10-21T06:07:25.548446+02:00 monolith kernel: [70600.971243] soundwire_intel soundwire_intel.link.2: intel_link_power_down: Unbalanced power-up/down calls
2024-10-21T06:07:25.548446+02:00 monolith kernel: [70600.971251] soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 3 device 6 addr 45 len 1
2024-10-21T06:07:25.548446+02:00 monolith kernel: [70600.971257] soundwire sdw-master-0-0: trf on Slave 6 failed:-110 write addr 45 count 0
2024-10-21T06:07:25.548447+02:00 monolith kernel: [70600.971260] soundwire_intel soundwire_intel.link.0: prepare clock stop failed -110
2024-10-21T06:07:25.548447+02:00 monolith kernel: [70600.971260] soundwire_intel soundwire_intel.link.0: intel_stop_bus: cannot stop clock: -110
2024-10-21T06:07:25.548451+02:00 monolith kernel: [70600.975027] soundwire_intel soundwire_intel.link.1: intel_link_power_down: Unbalanced power-up/down calls
2024-10-21T06:07:25.552534+02:00 monolith kernel: [70600.975107] soundwire_intel soundwire_intel.link.0: intel_link_power_down: Unbalanced power-up/down calls
2024-10-21T06:09:36.673653+02:00 monolith pipewire[2752]: I spa.alsa [alsa-pcm.c:1096:spa_alsa_open]: 0x5618e978c408: ALSA device open '_ucm0001.hw:sofsoundwire,2' playback
2024-10-21T06:09:36.673794+02:00 monolith pipewire[2752]: E spa.alsa [alsa-pcm.c:1098:spa_alsa_open]: '_ucm0001.hw:sofsoundwire,2': playback open failed: Device or resource busy
2024-10-21T06:09:36.673856+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:1863:spa_alsa_enum_format]: opened:0 format:0 started:0
2024-10-21T06:09:36.673891+02:00 monolith pipewire[2752]: I spa.alsa [alsa-pcm.c:1096:spa_alsa_open]: 0x5618e978c408: ALSA device open '_ucm0001.hw:sofsoundwire,2' playback
2024-10-21T06:09:36.673919+02:00 monolith pipewire[2752]: E spa.alsa [alsa-pcm.c:1098:spa_alsa_open]: '_ucm0001.hw:sofsoundwire,2': playback open failed: Device or resource busy
2024-10-21T06:09:36.673945+02:00 monolith pipewire[2752]: spa.audioadapter: params Spa:Enum:ParamId:EnumFormat: 0:0 (follower format) Device or resource busy
2024-10-21T06:09:36.673979+02:00 monolith pipewire[2752]: pw.node: (alsa_output.pci-0000_00_1f.3-platform-sof_sdw.HiFi__Speaker__sink-59) suspended -> error (Start error: Device or resource busy)
2024-10-21T06:09:36.676504+02:00 monolith kernel: [70732.098641] soundwire_intel soundwire_intel.link.1: ASoC: error at snd_soc_pcm_component_pm_runtime_get on soundwire_intel.link.1: -16
2024-10-21T06:09:36.676511+02:00 monolith kernel: [70732.098648]  SDW1-Playback: ASoC: error at __soc_pcm_open on SDW1-Playback: -16
2024-10-21T06:09:36.676511+02:00 monolith kernel: [70732.098649]  Speaker: ASoC: error at dpcm_be_dai_startup on Speaker: -16
2024-10-21T06:09:36.676512+02:00 monolith kernel: [70732.098651]  Speaker: ASoC: error at dpcm_fe_dai_startup on Speaker: -16
2024-10-21T06:09:36.676512+02:00 monolith kernel: [70732.098715] soundwire_intel soundwire_intel.link.1: ASoC: error at snd_soc_pcm_component_pm_runtime_get on soundwire_intel.link.1: -16
2024-10-21T06:09:36.676513+02:00 monolith kernel: [70732.098716]  SDW1-Playback: ASoC: error at __soc_pcm_open on SDW1-Playback: -16
2024-10-21T06:09:36.676513+02:00 monolith kernel: [70732.098717]  Speaker: ASoC: error at dpcm_be_dai_startup on Speaker: -16
2024-10-21T06:09:36.676513+02:00 monolith kernel: [70732.098718]  Speaker: ASoC: error at dpcm_fe_dai_startup on Speaker: -16
2024-10-21T06:09:41.680983+02:00 monolith pipewire[2752]: pw.node: (alsa_output.pci-0000_00_1f.3-platform-sof_sdw.HiFi__Speaker__sink-59) suspended -> error ((null))
2024-10-21T06:09:41.681438+02:00 monolith pipewire[2752]: pw.link: 0x5618ead1c500: one of the nodes is in error out:idle in:error
2024-10-21T06:09:41.681588+02:00 monolith pipewire[2752]: pw.link: 0x5618e99fe3f0: one of the nodes is in error out:idle in:error
2024-10-21T06:11:44.666153+02:00 monolith pipewire[2752]: I spa.alsa [alsa-pcm.c:1096:spa_alsa_open]: 0x5618e978c408: ALSA device open '_ucm0001.hw:sofsoundwire,2' playback
2024-10-21T06:11:44.667014+02:00 monolith pipewire[2752]: E spa.alsa [alsa-pcm.c:1098:spa_alsa_open]: '_ucm0001.hw:sofsoundwire,2': playback open failed: Device or resource busy
2024-10-21T06:11:44.667035+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:1863:spa_alsa_enum_format]: opened:0 format:0 started:0
2024-10-21T06:11:44.667051+02:00 monolith pipewire[2752]: I spa.alsa [alsa-pcm.c:1096:spa_alsa_open]: 0x5618e978c408: ALSA device open '_ucm0001.hw:sofsoundwire,2' playback
2024-10-21T06:11:44.667064+02:00 monolith pipewire[2752]: E spa.alsa [alsa-pcm.c:1098:spa_alsa_open]: '_ucm0001.hw:sofsoundwire,2': playback open failed: Device or resource busy
2024-10-21T06:11:44.667077+02:00 monolith pipewire[2752]: spa.audioadapter: params Spa:Enum:ParamId:EnumFormat: 0:0 (follower format) Device or resource busy
2024-10-21T06:11:44.667091+02:00 monolith pipewire[2752]: pw.node: (alsa_output.pci-0000_00_1f.3-platform-sof_sdw.HiFi__Speaker__sink-59) suspended -> error (Start error: Device or resource busy)
2024-10-21T06:11:44.668417+02:00 monolith kernel: [70860.089754] soundwire_intel soundwire_intel.link.1: ASoC: error at snd_soc_pcm_component_pm_runtime_get on soundwire_intel.link.1: -16
2024-10-21T06:11:44.668420+02:00 monolith kernel: [70860.089762]  SDW1-Playback: ASoC: error at __soc_pcm_open on SDW1-Playback: -16
2024-10-21T06:11:44.668421+02:00 monolith kernel: [70860.089765]  Speaker: ASoC: error at dpcm_be_dai_startup on Speaker: -16
2024-10-21T06:11:44.668421+02:00 monolith kernel: [70860.089767]  Speaker: ASoC: error at dpcm_fe_dai_startup on Speaker: -16
2024-10-21T06:11:44.668422+02:00 monolith kernel: [70860.089851] soundwire_intel soundwire_intel.link.1: ASoC: error at snd_soc_pcm_component_pm_runtime_get on soundwire_intel.link.1: -16
2024-10-21T06:11:44.668422+02:00 monolith kernel: [70860.089854]  SDW1-Playback: ASoC: error at __soc_pcm_open on SDW1-Playback: -16
2024-10-21T06:11:44.668422+02:00 monolith kernel: [70860.089856]  Speaker: ASoC: error at dpcm_be_dai_startup on Speaker: -16
2024-10-21T06:11:44.668423+02:00 monolith kernel: [70860.089857]  Speaker: ASoC: error at dpcm_fe_dai_startup on Speaker: -16
2024-10-21T06:11:49.673476+02:00 monolith pipewire[2752]: pw.node: (alsa_output.pci-0000_00_1f.3-platform-sof_sdw.HiFi__Speaker__sink-59) suspended -> error ((null))
2024-10-21T06:11:49.673666+02:00 monolith pipewire[2752]: pw.link: 0x5618ea3febe0: one of the nodes is in error out:idle in:error
2024-10-21T06:11:49.673732+02:00 monolith pipewire[2752]: pw.link: 0x5618ea3f82d0: one of the nodes is in error out:idle in:error
2024-10-21T06:12:01.259980+02:00 monolith pipewire[2752]: I spa.alsa [alsa-pcm.c:1096:spa_alsa_open]: 0x5618e978c408: ALSA device open '_ucm0001.hw:sofsoundwire,2' playback
2024-10-21T06:12:01.260125+02:00 monolith pipewire[2752]: E spa.alsa [alsa-pcm.c:1098:spa_alsa_open]: '_ucm0001.hw:sofsoundwire,2': playback open failed: Device or resource busy
2024-10-21T06:12:01.260150+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:1863:spa_alsa_enum_format]: opened:0 format:0 started:0
2024-10-21T06:12:01.260172+02:00 monolith pipewire[2752]: I spa.alsa [alsa-pcm.c:1096:spa_alsa_open]: 0x5618e978c408: ALSA device open '_ucm0001.hw:sofsoundwire,2' playback
2024-10-21T06:12:01.260190+02:00 monolith pipewire[2752]: E spa.alsa [alsa-pcm.c:1098:spa_alsa_open]: '_ucm0001.hw:sofsoundwire,2': playback open failed: Device or resource busy
2024-10-21T06:12:01.260209+02:00 monolith pipewire[2752]: spa.audioadapter: params Spa:Enum:ParamId:EnumFormat: 0:0 (follower format) Device or resource busy
2024-10-21T06:12:01.260228+02:00 monolith pipewire[2752]: pw.node: (alsa_output.pci-0000_00_1f.3-platform-sof_sdw.HiFi__Speaker__sink-59) suspended -> error (Start error: Device or resource busy)
2024-10-21T06:12:01.260425+02:00 monolith kernel: [70876.683291] soundwire_intel soundwire_intel.link.1: ASoC: error at snd_soc_pcm_component_pm_runtime_get on soundwire_intel.link.1: -16
2024-10-21T06:12:01.260434+02:00 monolith kernel: [70876.683304]  SDW1-Playback: ASoC: error at __soc_pcm_open on SDW1-Playback: -16
2024-10-21T06:12:01.260435+02:00 monolith kernel: [70876.683307]  Speaker: ASoC: error at dpcm_be_dai_startup on Speaker: -16
2024-10-21T06:12:01.260435+02:00 monolith kernel: [70876.683309]  Speaker: ASoC: error at dpcm_fe_dai_startup on Speaker: -16
2024-10-21T06:12:01.260436+02:00 monolith kernel: [70876.683372] soundwire_intel soundwire_intel.link.1: ASoC: error at snd_soc_pcm_component_pm_runtime_get on soundwire_intel.link.1: -16
2024-10-21T06:12:01.260437+02:00 monolith kernel: [70876.683373]  SDW1-Playback: ASoC: error at __soc_pcm_open on SDW1-Playback: -16
2024-10-21T06:12:01.260437+02:00 monolith kernel: [70876.683374]  Speaker: ASoC: error at dpcm_be_dai_startup on Speaker: -16
2024-10-21T06:12:01.260439+02:00 monolith kernel: [70876.683376]  Speaker: ASoC: error at dpcm_fe_dai_startup on Speaker: -16
2024-10-21T06:12:03.706209+02:00 monolith pipewire[2752]: pw.link: 0x5618ea3febe0: one of the nodes is in error out:suspended in:error
2024-10-21T06:12:03.706346+02:00 monolith pipewire[2752]: pw.link: 0x5618e991e780: one of the nodes is in error out:suspended in:error
2024-10-21T06:12:38.504386+02:00 monolith pipewire[2752]: I spa.alsa [alsa-pcm.c:1096:spa_alsa_open]: 0x5618e978c408: ALSA device open '_ucm0001.hw:sofsoundwire,2' playback
2024-10-21T06:12:38.504419+02:00 monolith kernel: [70913.927228] soundwire_intel soundwire_intel.link.1: ASoC: error at snd_soc_pcm_component_pm_runtime_get on soundwire_intel.link.1: -16
2024-10-21T06:12:38.504433+02:00 monolith kernel: [70913.927235]  SDW1-Playback: ASoC: error at __soc_pcm_open on SDW1-Playback: -16
2024-10-21T06:12:38.504434+02:00 monolith kernel: [70913.927237]  Speaker: ASoC: error at dpcm_be_dai_startup on Speaker: -16
2024-10-21T06:12:38.504434+02:00 monolith kernel: [70913.927238]  Speaker: ASoC: error at dpcm_fe_dai_startup on Speaker: -16
2024-10-21T06:12:38.504435+02:00 monolith kernel: [70913.927279] soundwire_intel soundwire_intel.link.1: ASoC: error at snd_soc_pcm_component_pm_runtime_get on soundwire_intel.link.1: -16
2024-10-21T06:12:38.504442+02:00 monolith kernel: [70913.927281]  SDW1-Playback: ASoC: error at __soc_pcm_open on SDW1-Playback: -16
2024-10-21T06:12:38.504443+02:00 monolith kernel: [70913.927282]  Speaker: ASoC: error at dpcm_be_dai_startup on Speaker: -16
2024-10-21T06:12:38.504443+02:00 monolith kernel: [70913.927282]  Speaker: ASoC: error at dpcm_fe_dai_startup on Speaker: -16
@eighthave eighthave added the bug Something isn't working label Oct 21, 2024
@lgirdwood
Copy link
Member

@eighthave lots of soundwire errors in the log - looks like the link fails to power up after suspend and then cascades. This could be the SDW controller or SDW codec, can you confirm SDW codec ID ?

2024-10-20T12:07:37.184178+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]: Hardware PCM card 0 'sof-soundwire' device 2 subdevice 0
2024-10-20T12:07:37.184208+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]: Its setup is:
2024-10-20T12:07:37.184234+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   stream       : PLAYBACK
2024-10-20T12:07:37.184265+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   access       : MMAP_INTERLEAVED
2024-10-20T12:07:37.184292+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   format       : S32_LE
2024-10-20T12:07:37.184319+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   subformat    : STD
2024-10-20T12:07:37.184349+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   channels     : 2
2024-10-20T12:07:37.184374+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   rate         : 48000
2024-10-20T12:07:37.184400+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   exact rate   : 48000 (48000/1)
2024-10-20T12:07:37.184425+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   msbits       : 32
2024-10-20T12:07:37.184453+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   buffer_size  : 8192
2024-10-20T12:07:37.184477+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   period_size  : 1024
2024-10-20T12:07:37.184504+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   period_time  : 21333
2024-10-20T12:07:37.824495+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   tstamp_mode  : ENABLE
2024-10-20T12:07:37.824572+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   tstamp_type  : MONOTONIC
2024-10-20T12:07:37.824595+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   period_step  : 1
2024-10-20T12:07:37.824609+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   avail_min    : 1024
2024-10-20T12:07:37.824623+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   period_event : 0
2024-10-20T12:07:37.824642+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   start_threshold  : 9223372036854775807
2024-10-20T12:07:37.824656+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   stop_threshold   : 8192
2024-10-20T12:07:37.824673+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   silence_threshold: 0
2024-10-20T12:07:37.824687+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   silence_size : 0
2024-10-20T12:07:37.824705+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   boundary     : 4611686018427387904
2024-10-20T12:07:37.824720+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   appl_ptr     : 75776
2024-10-20T12:07:37.824737+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   hw_ptr       : 92368
2024-10-20T12:07:37.824753+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:2488:do_start]: 0x5618e978c408: snd_pcm_start linked:0
2024-10-20T12:07:37.825848+02:00 monolith pipewire[2752]: E spa.alsa [alsa-pcm.c:2490:do_start]: hw:sofsoundwire,2p: snd_pcm_start: Connection timed out
2024-10-20T12:07:37.825917+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:2488:do_start]: 0x5618e978c408: snd_pcm_start linked:0
2024-10-20T12:07:37.826151+02:00 monolith kernel: [ 5813.122579] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
2024-10-20T12:07:37.830144+02:00 monolith kernel: [ 5813.124629] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -22
2024-10-20T12:07:38.334962+02:00 monolith pipewire[2752]: E spa.alsa [alsa-pcm.c:2490:do_start]: hw:sofsoundwire,2p: snd_pcm_start: Invalid argument
2024-10-20T12:07:38.335099+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:2488:do_start]: 0x5618e978c408: snd_pcm_start linked:0
2024-10-20T12:07:38.338267+02:00 monolith kernel: [ 5813.632970] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
2024-10-20T12:07:38.850458+02:00 monolith kernel: [ 5814.144538] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
2024-10-20T12:07:39.359285+02:00 monolith pipewire[2752]: E spa.alsa [alsa-pcm.c:2490:do_start]: hw:sofsoundwire,2p: snd_pcm_start: Connection timed out
2024-10-20T12:07:39.359458+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:3690:spa_alsa_pause]: 0x5618e978c408: pause
2024-10-20T12:07:39.359533+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:2475:do_drop]: 0x5618e978c408: snd_pcm_drop linked:0
2024-10-20T12:07:39.359590+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm-sink.c:750:impl_node_port_set_io]: 0x5618e978c408: io 1 (nil) 0
2024-10-20T12:07:39.359655+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm-sink.c:575:port_set_format]: clear format
2024-10-20T12:07:39.359718+02:00 monolith pipewire[2752]: I spa.alsa [alsa-pcm.c:1164:spa_alsa_close]: 0x5618e978c408: Device 'hw:sofsoundwire,2p' closing
2024-10-20T12:07:39.362397+02:00 monolith kernel: [ 5814.656906] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
2024-10-20T12:07:44.994261+02:00 monolith kernel: [ 5820.288414] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_free on 0000:00:1f.3: -110
2024-10-20T12:27:43.393697+02:00 monolith kernel: [ 7016.089097] soundwire_intel soundwire_intel.link.0: intel_pm_prepare: pm_runtime_resume failed: -16
2024-10-20T12:27:43.393698+02:00 monolith kernel: [ 7016.089117] soundwire_intel soundwire_intel.link.1: intel_pm_prepare: pm_runtime_resume failed: -16
2024-10-20T12:27:43.393700+02:00 monolith kernel: [ 7016.089126] soundwire_intel soundwire_intel.link.2: intel_pm_prepare: pm_runtime_resume failed: -16
2024-10-20T12:27:43.393701+02:00 monolith kernel: [ 7016.089136] soundwire_intel soundwire_intel.link.3: intel_pm_prepare: pm_runtime_resume failed: -16
2024-10-20T12:27:43.393702+02:00 monolith kernel: [ 7016.091375] soundwire_intel soundwire_intel.link.3: intel_suspend: invalid config: parent is suspended
2024-10-20T12:27:43.393704+02:00 monolith kernel: [ 7016.091395] soundwire_intel soundwire_intel.link.2: intel_suspend: invalid config: parent is suspended
2024-10-20T12:27:43.393707+02:00 monolith kernel: [ 7016.091404] soundwire_intel soundwire_intel.link.1: intel_suspend: invalid config: parent is suspended
2024-10-20T12:27:43.393708+02:00 monolith kernel: [ 7016.091414] soundwire_intel soundwire_intel.link.0: intel_suspend: invalid config: parent is suspended
2024-10-20T12:27:43.393722+02:00 monolith kernel: [ 7017.258797] soundwire_intel soundwire_intel.link.0: runtime PM trying to activate child device soundwire_intel.link.0 but parent (0000:00:1f.3) is not active
2024-10-20T12:27:43.393724+02:00 monolith kernel: [ 7017.259839] soundwire_intel soundwire_intel.link.0: Failed to power up link: -11
2024-10-20T12:27:43.393725+02:00 monolith kernel: [ 7017.259850] soundwire_intel soundwire_intel.link.0: intel_resume failed: -11
2024-10-20T12:27:43.393726+02:00 monolith kernel: [ 7017.259857] soundwire_intel soundwire_intel.link.0: PM: dpm_run_callback(): pm_generic_resume returns -11
2024-10-20T12:27:43.393727+02:00 monolith kernel: [ 7017.259873] soundwire_intel soundwire_intel.link.0: PM: failed to resume: error -11
2024-10-20T12:27:43.393729+02:00 monolith kernel: [ 7017.259875] soundwire_intel soundwire_intel.link.1: runtime PM trying to activate child device soundwire_intel.link.1 but parent (0000:00:1f.3) is not active

@bardliao
Copy link
Collaborator

@eighthave We need more debug trace to get what happened. Can you copy sof-dyndbg.conf.txt as /etc/modprobe.d/sof-dyndbg.conf reboot and attach the full kernel log with the issue? Does the issue happen only when a headset is plugged in? Or it happens without headset, too?

2024-10-20T12:27:43.393697+02:00 monolith kernel: [ 7016.089097] soundwire_intel soundwire_intel.link.0: intel_pm_prepare: pm_runtime_resume failed: -16
2024-10-20T12:27:43.393698+02:00 monolith kernel: [ 7016.089117] soundwire_intel soundwire_intel.link.1: intel_pm_prepare: pm_runtime_resume failed: -16
2024-10-20T12:27:43.393700+02:00 monolith kernel: [ 7016.089126] soundwire_intel soundwire_intel.link.2: intel_pm_prepare: pm_runtime_resume failed: -16
2024-10-20T12:27:43.393701+02:00 monolith kernel: [ 7016.089136] soundwire_intel soundwire_intel.link.3: intel_pm_prepare: pm_runtime_resume failed: -16

and

2024-10-20T12:27:43.393724+02:00 monolith kernel: [ 7017.259839] soundwire_intel soundwire_intel.link.0: Failed to power up link: -11
2024-10-20T12:27:43.393725+02:00 monolith kernel: [ 7017.259850] soundwire_intel soundwire_intel.link.0: intel_resume failed: -11
2024-10-20T12:27:43.393726+02:00 monolith kernel: [ 7017.259857] soundwire_intel soundwire_intel.link.0: PM: dpm_run_callback(): pm_generic_resume returns -11
2024-10-20T12:27:43.393727+02:00 monolith kernel: [ 7017.259873] soundwire_intel soundwire_intel.link.0: PM: failed to resume: error -11

Where the error code -16 is -EBUSY and -11 is -EAGAIN. I suspect something has been wrong before the error was reported.

@eighthave
Copy link
Author

It happened with and without a headset plugged into the 3.5mm headphone jack. I don't think it is related to plugging it in either, like I could reboot and not plug headphones in, and it would happen. I might be wrong, but I think that's the case.

I've added that modprobe config, and I'll reply once it happens again. It seems to be working OK now after a reboot.

@lgirdwood I'm not sure what "SDW codec ID" is exactly, could it be "rt714"?

@ujfalusi
Copy link
Collaborator

Looks like a kernel issue, moving.

@ujfalusi ujfalusi transferred this issue from thesofproject/sof Oct 22, 2024
@ujfalusi
Copy link
Collaborator

@eighthave, couple of questions to help us to progress:

  • is this a regression? Iow, the issue appeared after kernel/sof-firmware/pipewire/alsa-ucm-utils update or it is a new install and no prior record is known
  • can you attach the output of alsa-info.sh ?
  • can you attach a kernel log right after boot (with the sof-dyndbg.conf in place)?
  • The computer sleep means normal suspend (s2_idle) or hibernation or just leaving the laptop as idle
  • Are you able to test older or newer kernel?

Notes: what PW does is quite strange as it opens and closes the audio quite frequently, in just about a second.

The last OK start:

2024-10-20T12:07:35.253119+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:2445:do_prepare]: 0x5618e978c408: start threshold:2048 duration:2048 rate:48000 follower:0 match:0 resample:0
2024-10-20T12:07:35.253137+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:2356:set_swparams]: state after sw_params:
2024-10-20T12:07:35.253154+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]: Hardware PCM card 0 'sof-soundwire' device 2 subdevice 0
2024-10-20T12:07:35.253177+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]: Its setup is:
2024-10-20T12:07:35.253191+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   stream       : PLAYBACK
2024-10-20T12:07:35.253203+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   access       : MMAP_INTERLEAVED
2024-10-20T12:07:35.253223+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   format       : S32_LE
2024-10-20T12:07:35.253247+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   subformat    : STD
2024-10-20T12:07:35.253262+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   channels     : 2
2024-10-20T12:07:35.253278+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   rate         : 48000
2024-10-20T12:07:35.253292+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   exact rate   : 48000 (48000/1)
2024-10-20T12:07:35.253310+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   msbits       : 32
2024-10-20T12:07:35.253323+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   buffer_size  : 8192
2024-10-20T12:07:35.253336+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   period_size  : 1024
2024-10-20T12:07:35.253355+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   period_time  : 21333
2024-10-20T12:07:35.253368+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   tstamp_mode  : ENABLE
2024-10-20T12:07:35.253386+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   tstamp_type  : MONOTONIC
2024-10-20T12:07:35.253399+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   period_step  : 1
2024-10-20T12:07:35.253418+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   avail_min    : 1024
2024-10-20T12:07:35.253431+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   period_event : 0
2024-10-20T12:07:35.253447+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   start_threshold  : 9223372036854775807
2024-10-20T12:07:35.253464+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   stop_threshold   : 8192
2024-10-20T12:07:35.253478+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   silence_threshold: 0
2024-10-20T12:07:35.253491+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   silence_size : 0
2024-10-20T12:07:35.253505+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   boundary     : 4611686018427387904
2024-10-20T12:07:35.253518+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   appl_ptr     : 6144
2024-10-20T12:07:35.253533+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   hw_ptr       : 32544
2024-10-20T12:07:35.257137+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:2488:do_start]: 0x5618e978c408: snd_pcm_start linked:0
2024-10-20T12:07:36.195343+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:2739:update_time]: hw:sofsoundwire,2p: follower:0 match:0 rate:0,999488 bw:0,128000 thr:2048 del:2064 target:2048 err:16,000000 max:1024,000000
2024-10-20T12:07:37.183989+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:2475:do_drop]: 0x5618e978c408: snd_pcm_drop linked:0

First playback fail:

2024-10-20T12:07:37.184074+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:2445:do_prepare]: 0x5618e978c408: start threshold:2048 duration:2048 rate:48000 follower:0 match:0 resample:0
2024-10-20T12:07:37.184144+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:2356:set_swparams]: state after sw_params:
2024-10-20T12:07:37.184178+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]: Hardware PCM card 0 'sof-soundwire' device 2 subdevice 0
2024-10-20T12:07:37.184208+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]: Its setup is:
2024-10-20T12:07:37.184234+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   stream       : PLAYBACK
2024-10-20T12:07:37.184265+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   access       : MMAP_INTERLEAVED
2024-10-20T12:07:37.184292+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   format       : S32_LE
2024-10-20T12:07:37.184319+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   subformat    : STD
2024-10-20T12:07:37.184349+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   channels     : 2
2024-10-20T12:07:37.184374+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   rate         : 48000
2024-10-20T12:07:37.184400+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   exact rate   : 48000 (48000/1)
2024-10-20T12:07:37.184425+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   msbits       : 32
2024-10-20T12:07:37.184453+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   buffer_size  : 8192
2024-10-20T12:07:37.184477+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   period_size  : 1024
2024-10-20T12:07:37.184504+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   period_time  : 21333
2024-10-20T12:07:37.824495+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   tstamp_mode  : ENABLE
2024-10-20T12:07:37.824572+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   tstamp_type  : MONOTONIC
2024-10-20T12:07:37.824595+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   period_step  : 1
2024-10-20T12:07:37.824609+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   avail_min    : 1024
2024-10-20T12:07:37.824623+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   period_event : 0
2024-10-20T12:07:37.824642+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   start_threshold  : 9223372036854775807
2024-10-20T12:07:37.824656+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   stop_threshold   : 8192
2024-10-20T12:07:37.824673+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   silence_threshold: 0
2024-10-20T12:07:37.824687+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   silence_size : 0
2024-10-20T12:07:37.824705+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   boundary     : 4611686018427387904
2024-10-20T12:07:37.824720+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   appl_ptr     : 75776
2024-10-20T12:07:37.824737+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:641:log_write]:   hw_ptr       : 92368
2024-10-20T12:07:37.824753+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:2488:do_start]: 0x5618e978c408: snd_pcm_start linked:0
2024-10-20T12:07:37.825848+02:00 monolith pipewire[2752]: E spa.alsa [alsa-pcm.c:2490:do_start]: hw:sofsoundwire,2p: snd_pcm_start: Connection timed out
2024-10-20T12:07:37.825917+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:2488:do_start]: 0x5618e978c408: snd_pcm_start linked:0
2024-10-20T12:07:37.826151+02:00 monolith kernel: [ 5813.122579] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
2024-10-20T12:07:37.830144+02:00 monolith kernel: [ 5813.124629] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -22
2024-10-20T12:07:38.334962+02:00 monolith pipewire[2752]: E spa.alsa [alsa-pcm.c:2490:do_start]: hw:sofsoundwire,2p: snd_pcm_start: Invalid argument
2024-10-20T12:07:38.335099+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:2488:do_start]: 0x5618e978c408: snd_pcm_start linked:0
2024-10-20T12:07:38.338267+02:00 monolith kernel: [ 5813.632970] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
2024-10-20T12:07:38.850458+02:00 monolith kernel: [ 5814.144538] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
2024-10-20T12:07:39.359285+02:00 monolith pipewire[2752]: E spa.alsa [alsa-pcm.c:2490:do_start]: hw:sofsoundwire,2p: snd_pcm_start: Connection timed out
2024-10-20T12:07:39.359458+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:3690:spa_alsa_pause]: 0x5618e978c408: pause
2024-10-20T12:07:39.359533+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm.c:2475:do_drop]: 0x5618e978c408: snd_pcm_drop linked:0
2024-10-20T12:07:39.359590+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm-sink.c:750:impl_node_port_set_io]: 0x5618e978c408: io 1 (nil) 0
2024-10-20T12:07:39.359655+02:00 monolith pipewire[2752]: D spa.alsa [alsa-pcm-sink.c:575:port_set_format]: clear format
2024-10-20T12:07:39.359718+02:00 monolith pipewire[2752]: I spa.alsa [alsa-pcm.c:1164:spa_alsa_close]: 0x5618e978c408: Device 'hw:sofsoundwire,2p' closing
2024-10-20T12:07:39.362397+02:00 monolith kernel: [ 5814.656906] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
2024-10-20T12:07:44.994261+02:00 monolith kernel: [ 5820.288414] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_free on 0000:00:1f.3: -110

Quite long delay to report pm runtime resume fail:

2024-10-20T12:27:43.393697+02:00 monolith kernel: [ 7016.089097] soundwire_intel soundwire_intel.link.0: intel_pm_prepare: pm_runtime_resume failed: -16
2024-10-20T12:27:43.393698+02:00 monolith kernel: [ 7016.089117] soundwire_intel soundwire_intel.link.1: intel_pm_prepare: pm_runtime_resume failed: -16
2024-10-20T12:27:43.393700+02:00 monolith kernel: [ 7016.089126] soundwire_intel soundwire_intel.link.2: intel_pm_prepare: pm_runtime_resume failed: -16
2024-10-20T12:27:43.393701+02:00 monolith kernel: [ 7016.089136] soundwire_intel soundwire_intel.link.3: intel_pm_prepare: pm_runtime_resume failed: -16
2024-10-20T12:27:43.393702+02:00 monolith kernel: [ 7016.091375] soundwire_intel soundwire_intel.link.3: intel_suspend: invalid config: parent is suspended
2024-10-20T12:27:43.393704+02:00 monolith kernel: [ 7016.091395] soundwire_intel soundwire_intel.link.2: intel_suspend: invalid config: parent is suspended
2024-10-20T12:27:43.393707+02:00 monolith kernel: [ 7016.091404] soundwire_intel soundwire_intel.link.1: intel_suspend: invalid config: parent is suspended
2024-10-20T12:27:43.393708+02:00 monolith kernel: [ 7016.091414] soundwire_intel soundwire_intel.link.0: intel_suspend: invalid config: parent is suspended

@eighthave
Copy link
Author

is this a regression? Iow, the issue appeared after kernel/sof-firmware/pipewire/alsa-ucm-utils update or it is a new install and no prior record is known

This is an older install, there have been a series of issues with the sound that have been getting fixed. This seems like familiar symptoms but with different log output.

can you attach the output of alsa-info.sh ?

http://alsa-project.org/db/?f=5f5f365f50016df24719b2579b777ff655d6b7d5

can you attach a kernel log right after boot (with the sof-dyndbg.conf in place)?

Yes, I'll do so after I reboot next time (I'm in the middle of my work day)

The computer sleep means normal suspend (s2_idle) or hibernation or just leaving the laptop as idle

Sleep as in closing the laptop lid. I use a default Debian config for that, so I believe that means s2_idle

Are you able to test older or newer kernel?

I'm using Debian's kernels with Secure Boot on, so I could test those. With older kernels, I had other related issues, so it probably won't be so helpful, e.g #5213

@bardliao
Copy link
Collaborator

I installed Debian 12 on my Tiger Lake laptop which has the same audio codecs as Dell 9720. And audio works just fine. I start YouTube, and closed the lid, then open it after some minutes. YouTube was continue playing with no issue. I am using the default kernel from the Debian 12 image.
Linux version 6.1.0-26-amd64 ([email protected]) (gcc-12 (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40) #1 SMP PREEMPT_DYNAMIC Debian 6.1.112-1 (2024-09-30)

@lgirdwood
Copy link
Member

@eighthave one other thing to check is that you are up to date with system FW i.e. can you run fwupdmgr as audio software and firmware has many interaction with system FW for PM and HW IO.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working P2 Critical bugs or normal features
Projects
None yet
Development

No branches or pull requests

4 participants