linux icon indicating copy to clipboard operation
linux copied to clipboard
verified publisher icon thesofproject

SoundWire: Dell XPS9320 - IPC timeout - playback stops.

Open plbossart opened this issue 3 years ago • 43 comments

Forking new issue from comment https://github.com/thesofproject/linux/issues/3777#issuecomment-1193978089 reported by @madsl

f I play anything on my speakers, the sound output will stop after one minute of playback (the media player is also unable to continue playing, the whole stream stops). And I can't get it back without rebooting. It's only when it's speakers, the DisplayPort output ports works.

The sound still works if I make powertop not enable Runtime PM on" PCI Device Intel Corporation Alder Lake PCH eSPI Controller" (/sys/bus/pci/devices/0000:00:1f.0/power/control))It seems to be because of running powertop --auto-tune. If I don't do that during boot, it stays on.

Shouldn't that work..?

plbossart avatar Jul 25 '22 17:07 plbossart

@madsl I havent' worked with powertop since the early 2010s, and I can't find a way to run this

root@plb-Latitude-9420:~# powertop --auto-tune
modprobe cpufreq_stats failedLoaded 750 prior measurements
RAPL device for cpu 0
RAPL device for cpu 0
Devfreq not enabled
glob returned GLOB_ABORTED
Leaving PowerTOP

Can you tell us more about your configuration, add the powertop logs and if possible add dynamic debug by adding this file sof-dyndbg.conf.txt as /etc/modprobe.d/sof-dyndbg.conf (reboot needed).

Thanks!

plbossart avatar Jul 25 '22 21:07 plbossart

@madsl there's also no link that I am aware of between PCI device 1f.0 (eSPI) and the 1f.3 (audio)

plbossart avatar Jul 25 '22 21:07 plbossart

I'll attach the commands that powertop --auto-tune runs on my machine, you can export it to a bash script with the help of this: https://github.com/jlmcgraw/apply_powertop_recommended_settings

I've commented out line 25 (as it is run on my 9320). If you uncomment that one and run the script, I think you'll be able to recreate the issue.

#!/bin/bash
set -eu               # Abort on errors and unset variables
IFS=$(printf '\n\t')  # IFS is only newline and tab

# Quit if we aren't root
if [ ${UID} -ne 0 ]
then
    echo -e "Root privileges are needed to modify power settings\n"
    exit 1
fi

# Autosuspend for USB device USB Bridge [MCHP]
echo 'auto' > '/sys/bus/usb/devices/3-8/power/control'

# Runtime PM for PCI Device Intel Corporation 12th Gen Core Processor Gaussian & Neural Accelerator
echo 'auto' > '/sys/bus/pci/devices/0000:00:08.0/power/control'

# Runtime PM for PCI Device Intel Corporation Alder Lake Innovation Platform Framework Processor Participant
echo 'auto' > '/sys/bus/pci/devices/0000:00:04.0/power/control'

# Runtime PM for PCI Device Intel Corporation Alder Lake PCH Shared SRAM
echo 'auto' > '/sys/bus/pci/devices/0000:00:14.2/power/control'

# Runtime PM for PCI Device Intel Corporation Alder Lake PCH eSPI Controller
# echo 'auto' > '/sys/bus/pci/devices/0000:00:1f.0/power/control'

# Runtime PM for PCI Device Intel Corporation Alder Lake-P PCH CNVi WiFi
echo 'auto' > '/sys/bus/pci/devices/0000:00:14.3/power/control'

# Runtime PM for PCI Device Intel Corporation Alder Lake-P PCH SPI Controller
echo 'auto' > '/sys/bus/pci/devices/0000:00:1f.5/power/control'

# Runtime PM for PCI Device Intel Corporation Device 4621
echo 'auto' > '/sys/bus/pci/devices/0000:00:00.0/power/control'

# Runtime PM for PCI Device Intel Corporation Device 465d
echo 'auto' > '/sys/bus/pci/devices/0000:00:05.0/power/control'

# Runtime PM for PCI Device Intel Corporation Device 51fc
echo 'auto' > '/sys/bus/pci/devices/0000:00:12.0/power/control'

# Runtime PM for PCI Device SK hynix Device 1959
echo 'auto' > '/sys/bus/pci/devices/0000:01:00.0/power/control'

# VM writeback timeout
echo '1500' > '/proc/sys/vm/dirty_writeback_centisecs'

# Wake status for USB device 3-10
echo 'enabled' > '/sys/bus/usb/devices/3-10/power/wakeup'

# Wake status for USB device 3-8
echo 'enabled' > '/sys/bus/usb/devices/3-8/power/wakeup'

# Wake status for USB device 3-9
echo 'enabled' > '/sys/bus/usb/devices/3-9/power/wakeup'

# Wake status for USB device usb1
echo 'enabled' > '/sys/bus/usb/devices/usb1/power/wakeup'

# Wake status for USB device usb3
echo 'enabled' > '/sys/bus/usb/devices/usb3/power/wakeup'

# Wake status for USB device usb4
echo 'enabled' > '/sys/bus/usb/devices/usb4/power/wakeup'

# Wake-on-lan status for device wlan0
echo 'enabled' > '/sys/class/net/wlan0/device/power/wakeup'

madsl avatar Jul 25 '22 21:07 madsl

How do you generate sound @madsl, i.e. do you see any problems with

speaker-test -Dhw:0,2 -c2 -r48000

That should play noise on your speakers on a SoundWire-based device.

I have a TGL-based platform with those codecs and I see no issue.

plbossart avatar Jul 25 '22 21:07 plbossart

You did remember to uncomment that line before testing?

I've tested with audacious with pulseaudio set as output, and with chromium / firefox.

madsl avatar Jul 25 '22 21:07 madsl

I can't replicate it with speaker-test, no....

I'm using pipewire 0.3.56 with default options, and audacious with pulseaudio output as mentioned.

madsl avatar Jul 25 '22 21:07 madsl

Maybe you're onto something, that it doesn't have anything to do with powertop. I might just have had bad luck in triggering it when I tested it out and created some false positives.

How can we debug this further?

madsl avatar Jul 25 '22 21:07 madsl 

auto
root@plb-Latitude-9420:~# speaker-test -Dhw:0,2 -c2 -r48000

.... works forever.

same with aplay.

I really don't see how this could impact pipewire.

plbossart avatar Jul 25 '22 21:07 plbossart

@madsl I think it's best if you retry with dynamic debug enabled and see if there's anything in the dmesg log that would cause the stream to stop.

plbossart avatar Jul 25 '22 21:07 plbossart

I sat PIPEWIRE_DEBUG=5 in the service, and retried:

[...]
juli 26 00:05:01 marhide pipewire[1303]: spa.loop: 0x5630a548a210: update 0000001d -> 00000019
juli 26 00:05:01 marhide pipewire[1303]: mod.protocol-native: connection 0x5630a534aea0: 22 read 56 bytes and 0 fds
juli 26 00:05:01 marhide pipewire[1303]: mod.protocol-native: 0x5630a532d560: got message 2 from 0
juli 26 00:05:01 marhide pipewire[1303]: pw.core: 0x5630a5312940: sync 1073742219 for resource 0
juli 26 00:05:01 marhide pipewire[1303]: mod.protocol-native: need flush
juli 26 00:05:01 marhide pipewire[1303]: spa.loop: 0x5630a5348890: update 00000019 -> 0000001d
juli 26 00:05:01 marhide pipewire[1303]: mod.protocol-native: connection 0x5630a534aea0: 22 written 56 bytes and 0 fds
juli 26 00:05:01 marhide pipewire[1303]: spa.loop: 0x5630a5348890: update 0000001d -> 00000019
juli 26 00:05:01 marhide pipewire[1303]: spa.alsa: hw:sofsoundwire,2: follower:0 match:0 rate:0,999934 bw:0,128000 thr:2048 del:2048 target:2048 err:0,000000 max:1024,000000
juli 26 00:05:04 marhide pipewire[1303]: spa.alsa: hw:sofsoundwire,2: follower:0 match:0 rate:0,999952 bw:0,128000 thr:2048 del:2064 target:2048 err:16,000000 max:1024,000000
juli 26 00:05:07 marhide pipewire[1303]: spa.alsa: hw:sofsoundwire,2: follower:0 match:0 rate:1,000041 bw:0,128000 thr:2048 del:2032 target:2048 err:-16,000000 max:1024,000000
juli 26 00:05:10 marhide pipewire[1303]: spa.alsa: hw:sofsoundwire,2: follower:0 match:0 rate:0,999907 bw:0,128000 thr:2048 del:2048 target:2048 err:0,000000 max:1024,000000
juli 26 00:05:13 marhide pipewire[1303]: spa.alsa: hw:sofsoundwire,2: follower:0 match:0 rate:0,999967 bw:0,128000 thr:2048 del:2064 target:2048 err:16,000000 max:1024,000000
juli 26 00:05:16 marhide pipewire[1303]: spa.alsa: hw:sofsoundwire,2: follower:0 match:0 rate:1,000022 bw:0,128000 thr:2048 del:2032 target:2048 err:-16,000000 max:1024,000000
juli 26 00:05:19 marhide pipewire[1303]: spa.alsa: hw:sofsoundwire,2: follower:0 match:0 rate:0,999939 bw:0,128000 thr:2048 del:2048 target:2048 err:0,000000 max:1024,000000
juli 26 00:05:22 marhide pipewire[1303]: spa.alsa: hw:sofsoundwire,2: follower:0 match:0 rate:0,999956 bw:0,128000 thr:2048 del:2064 target:2048 err:16,000000 max:1024,000000
juli 26 00:05:25 marhide pipewire[1303]: spa.alsa: hw:sofsoundwire,2: follower:0 match:0 rate:1,000018 bw:0,128000 thr:2048 del:2032 target:2048 err:-16,000000 max:1024,000000
juli 26 00:05:28 marhide pipewire[1303]: spa.alsa: hw:sofsoundwire,2: follower:0 match:0 rate:0,999939 bw:0,128000 thr:2048 del:2048 target:2048 err:0,000000 max:1024,000000
juli 26 00:05:31 marhide pipewire[1303]: spa.alsa: hw:sofsoundwire,2: follower:0 match:0 rate:0,999956 bw:0,128000 thr:2048 del:2064 target:2048 err:16,000000 max:1024,000000
juli 26 00:05:34 marhide pipewire[1303]: spa.alsa: hw:sofsoundwire,2: follower:0 match:0 rate:1,000018 bw:0,128000 thr:2048 del:2032 target:2048 err:-16,000000 max:1024,000000
juli 26 00:05:37 marhide pipewire[1303]: spa.alsa: hw:sofsoundwire,2: follower:0 match:0 rate:0,999911 bw:0,128000 thr:2048 del:2048 target:2048 err:0,000000 max:1024,000000
juli 26 00:05:40 marhide pipewire[1303]: spa.alsa: hw:sofsoundwire,2: follower:0 match:0 rate:0,999956 bw:0,128000 thr:2048 del:2064 target:2048 err:16,000000 max:1024,000000
juli 26 00:05:43 marhide pipewire[1303]: spa.alsa: hw:sofsoundwire,2: follower:0 match:0 rate:1,000018 bw:0,128000 thr:2048 del:2032 target:2048 err:-16,000000 max:1024,000000
juli 26 00:05:46 marhide pipewire[1303]: spa.alsa: hw:sofsoundwire,2: follower:0 match:0 rate:0,999939 bw:0,128000 thr:2048 del:2048 target:2048 err:0,000000 max:1024,000000
juli 26 00:05:48 marhide pipewire[1303]: spa.alsa: 0x5630a538fb58: early wakeup 4624 2048
juli 26 00:05:48 marhide pipewire[1303]: spa.alsa: 0x5630a538fb58: early wakeup 4624 2048
juli 26 00:05:48 marhide pipewire[1303]: spa.alsa: 0x5630a538fb58: early wakeup 4624 2048
juli 26 00:05:48 marhide pipewire[1303]: spa.alsa: 0x5630a538fb58: early wakeup 4624 2048
juli 26 00:05:48 marhide pipewire[1303]: spa.alsa: 0x5630a538fb58: early wakeup 4624 2048
juli 26 00:05:48 marhide pipewire[1303]: spa.alsa: 0x5630a538fb58: early wakeup 4624 2048
[... repeated endlessly...]

Those early wakeup-lines just kept repeating, and it was when the first line came the sound stopped.

madsl avatar Jul 25 '22 22:07 madsl

dmesg:

[  476.736098] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x60050000 (msg/reply size: 12/12)
[  476.736111] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[  476.736143] sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000081 rirb 00
[  476.736148] sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[  476.736175] sof-audio-pci-intel-tgl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  476.736178] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[  476.736180] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[  476.736182] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  476.736184] sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (6)
[  476.736214] sof-audio-pci-intel-tgl 0000:00:1f.3: 0x00000005: module: ROM, state: FW_ENTERED, running
[  476.736511] sof-audio-pci-intel-tgl 0000:00:1f.3: unexpected fault 0x00000000 trace 0x00004000
[  476.736514] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[  476.736547] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[  476.736554]  Speaker: ASoC: trigger FE cmd: 0 failed: -110
[  477.240116] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x60030000 (msg/reply size: 12/12)
[  477.240135] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  477.240202] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_free on 0000:00:1f.3: -110
[  477.752151] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  477.752167] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  477.752173] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for SDW1-Playback
[  477.752178] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_free: DAI config failed for widget 'ALH258.OUT'
[  478.256129] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  478.256152] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  478.256159] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for SDW1-Playback
[  478.256164] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_free: DAI config failed for widget 'ALH514.OUT'
[  478.832096] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  478.832114] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  478.832120] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  478.832126] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_setup: DAI config failed for widget HDA2.OUT
[  478.832133] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_dai_hw_params on iDisp3 Pin: -110
[  478.832215]  iDisp3: ASoC: __soc_pcm_hw_params() failed (-110)
[  478.832223]  HDMI 3: ASoC: dpcm_fe_dai_hw_params failed (-110)
[  479.336059] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x60010000 (msg/reply size: 108/20)
[  479.336076] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  479.336082] sof-audio-pci-intel-tgl 0000:00:1f.3: HW params ipc failed for stream 1
[  479.336087] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_params on 0000:00:1f.3: -110
[  479.336100]  HDMI 3: ASoC: __soc_pcm_hw_params() failed (-110)
[  479.839949] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  479.839962] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  479.839968] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  479.839971] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_free: DAI config failed for widget 'HDA2.OUT'
[  479.839987]  HDMI 3: ASoC: dpcm_fe_dai_hw_params failed (-110)
[  480.344095] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  480.344114] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  480.344121] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  480.344127] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_free: DAI config failed for widget 'HDA2.OUT'
[  480.848037] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  480.848052] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  480.848058] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  480.848063] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_setup: DAI config failed for widget HDA2.OUT
[  480.848069] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_dai_hw_params on iDisp3 Pin: -110
[  480.848144]  iDisp3: ASoC: __soc_pcm_hw_params() failed (-110)
[  480.848152]  HDMI 3: ASoC: dpcm_fe_dai_hw_params failed (-110)
[  481.352028] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  481.352041] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  481.352047] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  481.352051] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_free: DAI config failed for widget 'HDA2.OUT'
[  481.856029] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  481.856042] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  481.856047] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  481.856051] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_setup: DAI config failed for widget HDA2.OUT
[  481.856056] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_dai_hw_params on iDisp3 Pin: -110
[  481.856119]  iDisp3: ASoC: __soc_pcm_hw_params() failed (-110)
[  481.856124]  HDMI 3: ASoC: dpcm_fe_dai_hw_params failed (-110)
[  482.360812] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  482.360822] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  482.360826] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  482.360829] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_free: DAI config failed for widget 'HDA2.OUT'
[  482.864849] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  482.864863] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  482.864868] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  482.864872] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_setup: DAI config failed for widget HDA2.OUT
[  482.864877] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_dai_hw_params on iDisp3 Pin: -110
[  482.864937]  iDisp3: ASoC: __soc_pcm_hw_params() failed (-110)
[  482.864949]  HDMI 3: ASoC: dpcm_fe_dai_hw_params failed (-110)
[  483.367897] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  483.367916] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  483.367923] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  483.367929] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_free: DAI config failed for widget 'HDA2.OUT'
[  483.871799] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  483.871810] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  483.871814] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  483.871817] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_setup: DAI config failed for widget HDA2.OUT
[  483.871821] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_dai_hw_params on iDisp3 Pin: -110
[  483.871867]  iDisp3: ASoC: __soc_pcm_hw_params() failed (-110)
[  483.871873]  HDMI 3: ASoC: dpcm_fe_dai_hw_params failed (-110)
[  484.375888] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x60010000 (msg/reply size: 108/20)
[  484.375901] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  484.375905] sof-audio-pci-intel-tgl 0000:00:1f.3: HW params ipc failed for stream 1
[  484.375915] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_params on 0000:00:1f.3: -110
[  484.375924]  HDMI 3: ASoC: __soc_pcm_hw_params() failed (-110)
[  484.879959] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  484.879976] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  484.879983] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  484.879988] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_free: DAI config failed for widget 'HDA2.OUT'
[  484.880015]  HDMI 3: ASoC: dpcm_fe_dai_hw_params failed (-110)
[  485.384672] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  485.384682] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  485.384687] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  485.384690] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_free: DAI config failed for widget 'HDA2.OUT'
[  485.887751] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  485.887763] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  485.887767] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  485.887771] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_setup: DAI config failed for widget HDA2.OUT
[  485.887775] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_dai_hw_params on iDisp3 Pin: -110
[  485.887835]  iDisp3: ASoC: __soc_pcm_hw_params() failed (-110)
[  485.887841]  HDMI 3: ASoC: dpcm_fe_dai_hw_params failed (-110)
[  486.391841] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  486.391851] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  486.391856] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  486.391859] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_free: DAI config failed for widget 'HDA2.OUT'
[  486.895747] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  486.895756] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  486.895759] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  486.895762] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_setup: DAI config failed for widget HDA2.OUT
[  486.895765] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_dai_hw_params on iDisp3 Pin: -110
[  486.895802]  iDisp3: ASoC: __soc_pcm_hw_params() failed (-110)
[  486.895806]  HDMI 3: ASoC: dpcm_fe_dai_hw_params failed (-110)
[  487.399756] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  487.399768] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  487.399772] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  487.399776] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_free: DAI config failed for widget 'HDA2.OUT'
[  487.903703] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  487.903712] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  487.903715] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  487.903717] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_setup: DAI config failed for widget HDA2.OUT
[  487.903721] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_dai_hw_params on iDisp3 Pin: -110
[  487.903759]  iDisp3: ASoC: __soc_pcm_hw_params() failed (-110)
[  487.903763]  HDMI 3: ASoC: dpcm_fe_dai_hw_params failed (-110)
[  488.407769] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x80010000 (msg/reply size: 216/12)
[  488.407777] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  488.407780] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set dai config for iDisp3
[  488.407782] sof-audio-pci-intel-tgl 0000:00:1f.3: hda_ctrl_dai_widget_free: DAI config failed for widget 'HDA2.OUT'
[  491.408539] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x30110000 (msg/reply size: 12/12)
[  491.408548] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  491.408552] sof-audio-pci-intel-tgl 0000:00:1f.3: failed to free widget PIPELINE.8.HDA2.OUT
[  491.911690] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x90050000 (msg/reply size: 8/12)
[  491.911698] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  491.911701] sof-audio-pci-intel-tgl 0000:00:1f.3: DMA_TRACE_FREE failed with error: -110
[  492.415682] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x40010000 (msg/reply size: 76/12)
[  492.415691] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  492.415694] sof-audio-pci-intel-tgl 0000:00:1f.3: ctx_save IPC error: -110, proceeding with suspend
[  495.084446] sof-audio-pci-intel-tgl 0000:00:1f.3: IMR restore failed, trying to cold boot
[  495.206295] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx error for 0x30130000 (msg/reply size: 12/12): -22
[  495.206307] sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to restore pipeline after resume -22
[  495.206315] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_pm_runtime_get on 0000:00:1f.3: -22
[  495.206322]  iDisp3: __soc_pcm_open() failed (-22)
[  495.206326]  HDMI 3: ASoC: dpcm_be_dai_startup() failed at iDisp3 (-22)
[  495.206330]  HDMI 3: dpcm_fe_dai_startup() failed (-22)

madsl avatar Jul 25 '22 22:07 madsl

oh, that's pretty scary @madsl, I've not seen this one before. Indeed if we have an IPC error it's game over usually.

Can you attach the full dmesg log (not paste) so that we can figure out when this happens?

Also we need to confirm which kernel you are using (we can figure out the firmware from the dmesg log).

plbossart avatar Jul 25 '22 22:07 plbossart

  1. booted
  2. Started audacious, playing song.
  3. Stream stops between 1 and 2 minutes played. Nothing in dmesg yet.
  4. I try systemctl --user restart pipewire Then all those errors pops up in dmesg.

Attached are the dmesg: dmesg_tgl_ipc.log

madsl avatar Jul 25 '22 22:07 madsl

did you edit the log @madsl? There's a significant gap

[   11.759963] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[  206.305186] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x60050000 (msg/reply size: 12/12)

makes it hard to see what happened when you start playing in step2) above.

plbossart avatar Jul 25 '22 23:07 plbossart

No, I did not edit it. It was the time it took before I ran systemctl --user restart pipewire. I checked many times before to be sure. It's the restart step that makes the kernel spew out all those lines, nothing happened before it (in dmesg).

madsl avatar Jul 25 '22 23:07 madsl

I had to trigger the stream stopping first with audacious, so it takes a little while. The stream stopping makes no output in dmesg.

madsl avatar Jul 25 '22 23:07 madsl

@madsl Did you enable dynamic debug with the step in https://github.com/thesofproject/linux/issues/3783#issuecomment-1194630673? There should be all kinds of logs related to topology parsing and stream trigger.

The platform must be in some sort of zombie state before pipewire is restarted.

plbossart avatar Jul 25 '22 23:07 plbossart

Ah, sorry, I didn't catch that comment!

I redid the audacious -> restart pulseaudio test now (went a bit faster this time): dmesg_tgl_ipc_dbg.log

madsl avatar Jul 26 '22 08:07 madsl

@madsl now I don't see any issues with the last results? Is this a Heisenbug where adding dynamic debug makes things work ok?

plbossart avatar Jul 26 '22 15:07 plbossart

Well, the stream still stops though...

madsl avatar Jul 26 '22 16:07 madsl

it's really hard to figure out what goes on. Initially it seems PulseAudio opens/closes the devices multiple times to figure out the capabilities. Then around 79s there's again a set of open/close.

Can you try to wait a bit and make the transitions longer before starting your playback, and re-initializing PulseAudio?

plbossart avatar Jul 26 '22 16:07 plbossart

I managed to get an error with dyndbg.

  1. boot
  2. systemctl --user restart pipewire-pulse pipewire wireplumber
  3. play song in audacious
  4. stream stops
  5. systemctl --user restart pipewire-pulse pipewire wireplumber
  6. dmesg fills up with error

dmesg_tgl_ipc_dbg_2.log

madsl avatar Jul 26 '22 19:07 madsl

I also went back to vanilla "powertop --auto-tune" during boot since it didn't seem to make a difference in the end.

madsl avatar Jul 26 '22 19:07 madsl

ok, so I would guess this segment is where the stream stops, after about 60s of playback. Can you confirm that the song is longer? It's possible that there's an xrun that isn't well handled.

[   33.394240] snd_sof:sof_pcm_open: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: open stream 2 dir 0
[   33.394245] snd_sof:sof_pcm_open: sof-audio-pci-intel-tgl 0000:00:1f.3: period min 192 max 16384 bytes
[   33.394248] snd_sof:sof_pcm_open: sof-audio-pci-intel-tgl 0000:00:1f.3: period count 2 max 16
[   33.394250] snd_sof:sof_pcm_open: sof-audio-pci-intel-tgl 0000:00:1f.3: buffer max 65536 bytes
[   33.394641] snd_soc_rt1316_sdw:rt1316_sdw_hw_params: rt1316-sdca sdw:1:025d:1316:01: rt1316_sdw_hw_params rt1316-aif
[   33.394657] snd_soc_rt1316_sdw:rt1316_sdw_hw_params: rt1316-sdca sdw:2:025d:1316:01: rt1316_sdw_hw_params rt1316-aif
[   33.394700] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x80010000
[   33.394970] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x80010000
[   33.395200] snd_sof:sof_pcm_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: hw params stream 2 dir 0
[   33.395211] snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x40000 successful
[   33.395258] snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x40000 successful
[   33.395264] snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-tgl 0000:00:1f.3: period_bytes:0x2000
[   33.395266] snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-tgl 0000:00:1f.3: periods:8
[   33.395322] snd_sof:sof_ipc3_pcm_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: stream_tag 1
[   33.395330] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60010000
[   33.395954] snd_sof_intel_hda_common:hda_set_stream_data_offset: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: stream dir 0, posn mailbox offset is 790908
[   33.402959] snd_sof:sof_pcm_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 1
[   33.403546] snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x2014001e successful
[   33.403553] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60040000
[   96.322072] snd_sof:sof_pcm_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 0
[   96.322080] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60050000
[   96.828590] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x60050000 (msg/reply size: 12/12)
[   96.828605] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[   96.828638] sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000081 rirb 00
[   96.828643] sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[   96.828671] sof-audio-pci-intel-tgl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[   96.828674] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[   96.828677] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[   96.828678] sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[   96.828681] sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (6)
[   96.828712] sof-audio-pci-intel-tgl 0000:00:1f.3: 0x00000005: module: ROM, state: FW_ENTERED, running
[   96.829040] sof-audio-pci-intel-tgl 0000:00:1f.3: unexpected fault 0x00000000 trace 0x00004000
[   96.829044] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------

I can't figure out what happens after that, you would want a LOONNNGGG pause between step 4 and step 5 to allow us to check what happens.

plbossart avatar Jul 26 '22 20:07 plbossart

Another point @madsl is that you are using the firmware 2.1

sof-audio-pci-intel-tgl 0000:00:1f.3: Firmware info: version 2:1:1-3964a

it would be interesting if you could try with the latest 2.2 release

sudo mv /lib/firmware/intel/sof/ /lib/firmware/intel/sof-backup/
sudo mv /lib/firmware/intel/sof-tplg/ /lib/firmware/intel/sof-tplg-backup/
git clone https://github.com/thesofproject/sof-bin.git
cd sof-bin
sudo ./install.sh v2.2.x/v2.2

reboot and retest. Thanks.

plbossart avatar Jul 26 '22 20:07 plbossart

It took a bit longer with 2.2 firmware before the bug triggered, I think the song got to about 3:45 before it happened. It seems kinda random though. Restarted services both before and after this time too. dmesg_tgl_ipc_dbg_3.log

madsl avatar Jul 27 '22 09:07 madsl

It did not trigger the IPC bug it seems? And I'm able to bring the audio to life again by restarting the services. I'll try again without debug enabled.

madsl avatar Jul 27 '22 09:07 madsl

Hm no dice. No debug. For this test I just booted and started audacious right away. Stream stops after 59 seconds, I do restart of those three services, and then IPC bug hits dmesg. I'll try again and see if I can trigger IPC bug with debug. dmesg_tgl_ipc_3.log

madsl avatar Jul 27 '22 09:07 madsl

  1. boot (with debug)
  2. systemctl --user restart pipewire-pulse pipewire wireplumber
  3. play song in audacious
  4. stream stops (about 45 seconds this time)
  5. systemctl --user restart pipewire-pulse pipewire wireplumber
  6. restart audacious and play song, it works
  7. stream stops
  8. repeat cycle two or three more times
  9. finally the IPC bug triggers and I can't get sound back

the dmesg log is so large that you can't see the boot sequence...

dmesg_tgl_ipc_dbg_4.log

madsl avatar Jul 27 '22 09:07 madsl

@madsl would this transition be where playback stops?

[   35.553251] snd_sof:sof_pcm_open: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: open stream 2 dir 0
[   35.553262] snd_sof:sof_pcm_open: sof-audio-pci-intel-tgl 0000:00:1f.3: period min 192 max 16384 bytes
[   35.553264] snd_sof:sof_pcm_open: sof-audio-pci-intel-tgl 0000:00:1f.3: period count 2 max 16
[   35.553265] snd_sof:sof_pcm_open: sof-audio-pci-intel-tgl 0000:00:1f.3: buffer max 65536 bytes
[   35.553559] snd_soc_rt1316_sdw:rt1316_sdw_hw_params: rt1316-sdca sdw:1:025d:1316:01: rt1316_sdw_hw_params rt1316-aif
[   35.553563] snd_soc_rt1316_sdw:rt1316_sdw_hw_params: rt1316-sdca sdw:2:025d:1316:01: rt1316_sdw_hw_params rt1316-aif
[   35.553601] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x80010000
[   35.553873] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x80010000
[   35.554101] snd_sof:sof_pcm_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: hw params stream 2 dir 0
[   35.554108] snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x40000 successful
[   35.554127] snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x40000 successful
[   35.554129] snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-tgl 0000:00:1f.3: period_bytes:0x2000
[   35.554130] snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-tgl 0000:00:1f.3: periods:8
[   35.554154] snd_sof:sof_ipc3_pcm_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: stream_tag 1
[   35.554161] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60010000
[   35.554774] snd_sof_intel_hda_common:hda_set_stream_data_offset: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: stream dir 0, posn mailbox offset is 790908
[   35.560401] snd_sof:sof_pcm_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 1
[   35.560856] snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x2014001e successful
[   35.560860] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60040000
[  120.401924] snd_sof:sof_pcm_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 2 dir 0 cmd 0
[  120.401933] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60050000
[  120.402136] snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x20140000 successful
[  120.402140] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60030000
[  120.402503] snd_sof:sof_pcm_hw_free: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: free stream 2 dir 0
[  120.404245] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x80010000
[  120.404437] snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x80010000
[  120.404673] snd_sof:sof_pcm_close: sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: close stream 2 dir 0

it's really hard to follow, since there's immediately a bunch of open/close. Or is this a case where the playback stops 'silently' or someone gets muted. From the ALSA perspective the stream is still playing, as measured by the 'stop' happening at 120s, which could be a result of your restarting the service.

That would be a new one

plbossart avatar Jul 27 '22 16:07 plbossart