alsa-project / alsa-lib

The Advanced Linux Sound Architecture (ALSA) - library
GNU Lesser General Public License v2.1
344 stars 173 forks source link

PA poll wakeup issue (was: bug in the ALSA driver 'snd_hda_intel') #90

Open Mysgym opened 3 years ago

Mysgym commented 3 years ago

Hello, after spending some time troubleshooting an issue with an audio interface (using snd_hda_intel). I've stumbled upon this message from PulseAudio in the journal : Oct 17 18:30:58 LaptopName pulseaudio[1782]: E: [alsa-sink-ALC256 Analog] alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write. Oct 17 18:30:58 LaptopName pulseaudio[1782]: E: [alsa-sink-ALC256 Analog] alsa-sink.c: Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA developers. Oct 17 18:30:58 LaptopName pulseaudio[1782]: E: [alsa-sink-ALC256 Analog] alsa-sink.c: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail. So I filed a bug report

This is Manjaro on Kernel 5.8

ghost commented 3 years ago

Got the same error: Dez 31 13:21:48 emnet pulseaudio[923]: GetManagedObjects() failed: org.freedesktop.systemd1.NoSuchUnit: Unit dbus-org.bluez.service not found. Dez 31 13:59:49 emnet pulseaudio[923]: ALSA weckte uns auf, um neue Daten auf das Gerät zu schreiben, doch es gab nichts zum Schreiben! Dez 31 13:59:49 emnet pulseaudio[923]: Dies ist höchstwahrscheinlich ein Fehler im ALSA-Treiber »snd_hda_intel«. Bitte melden Sie diesen Fehler den ALSA-Entwicklern. Dez 31 13:59:49 emnet pulseaudio[923]: Wir wurden durch das POLLOUT-Set geweckt, allerdings lieferte ein anschließender snd_pcm_avail() den Wert 0 oder einen anderen Wert < min_avail. Arch Linux Kernel: 5.10.3-arch1-1 DE: GNOME 3.38.2 GPU: NVIDIA GeForce GTX 1660 GPU Driver: NVIDIA 455.45.01 CPU: AMD Ryzen 5 2600 (12) @ 3.400GHz

deadlysyn commented 3 years ago

Got similar error:

Jan 26 11:31:04 monolith pulseaudio[1224]: ALSA woke us up to read new data from the device, but there was actually nothing to read.
Jan 26 11:31:04 monolith pulseaudio[1224]: Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA developers.
Jan 26 11:31:04 monolith pulseaudio[1224]: We were woken up with POLLIN set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
[    4.502625] snd_hda_intel 0000:0b:00.1: Handle vga_switcheroo audio client
[    4.502628] snd_hda_intel 0000:0b:00.1: Force to non-snoop mode
[    4.502675] snd_hda_intel 0000:0d:00.4: enabling device (0000 -> 0002)
[    5.826667] snd_hda_intel 0000:0b:00.1: bound 0000:0b:00.0 (ops amdgpu_dm_audio_component_bind_ops [amdgpu])

Arch Linux Kernel: 5.10.10-arch1-1 DE: n/a (bspwm) GPU: AMD Radeon RX 5700 XT GPU Driver: amdgpu 19.1.0-2 CPU: AMD Ryzen 9 3950X

outloudvi commented 3 years ago

I got the similar logging with a slightly different environment:

pulseaudio[2169]: ALSA woke us up to write new data to the device, but there was actually nothing to write.
pulseaudio[2169]: Most likely this is a bug in the ALSA driver 'snd_usb_audio'. Please report this issue to the ALSA developers.
pulseaudio[2169]: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.

It's Arch Linux on kernel 5.11.1-arch1-1 with a Type-C earphone.

ElisDN commented 2 years ago

Same issue on Ubuntu 21.10 with 5.13.0-23-generic:

pulseaudio[2014]: ALSA woke us up to write new data to the device, but there was actually nothing to write.
pulseaudio[2014]: Most likely this is a bug in the ALSA driver 'snd_usb_audio'. Please report this issue to the ALSA developers.
pulseaudio[2014]: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.

Device: RodeCaster Pro

perexg commented 1 year ago

Just for the reference: It is really not clear if the bug is in ALSA or PulseAudio code. The PulseAudio does not do any realtime checks. If someone can reproduce this problem with a simple test code, we can work to improve ours (alsa drivers or alsa-lib).

Jeffry84 commented 1 year ago

Just for the reference: It is really not clear if the bug is in ALSA or PulseAudio code. The PulseAudio does not do any realtime checks. If someone can reproduce this problem with a simple test code, we can work to improve ours (alsa drivers or alsa-lib).

How may I help? I'm not very knowledgeable but as I'm having a similar issue on a HP x2 210 (the driver seems to be "snd_soc_sst_byt_cht_cx2072x").

Long story as short as possible: after a while (from seconds to a few minutes) instead of playing sounds from a medium (music, video) every sound stops and a continuous beeping sound starts playing. Any audio/video medium pauses and it's impossible to resume it (if Play is pressed it pauses immediately after), and the only way to stop it is to stop playing or close the application and wait. It's unfortunately quite a deal breaker, almost as not having any sound at all.

perexg commented 1 year ago

snd_soc_sst_byt_cht_cx2072x after a while (from seconds to a few minutes) instead of playing sounds from a medium (music, video) every sound stops and a continuous beeping sound starts playing

It's more likely a specific driver issue. Report it to the authors of the specific driver (Intel team) - https://github.com/thesofproject/linux/commits/topic/sof-dev/sound/soc/intel/boards/bytcht_cx2072x.c .

Bulwagga commented 1 year ago

Having the same issue on a 3B+ raspberry pi running Buster and OpenVoiceOS.

ovos-systemd-dinkum-listener[692]: 2022-12-22 06:56:23.800 - OVOS - ovos_dinkum_listener.service:_before_start:216 - INFO - Starting service... ovos-systemd-dinkum-listener[692]: 2022-12-22 06:56:23.832 - OVOS - ovos_dinkum_listener.service:_connect_to_bus:277 - INFO - Connected to Mycroft Core message bus ovos-systemd-dinkum-listener[692]: 2022-12-22 06:56:23.841 - OVOS - ovos_dinkum_listener.voice_loop.hotwords:load_hotword_engines:64 - INFO - creating hotword engines ovos-systemd-dinkum-listener[692]: 2022-12-22 06:56:23.949 - OVOS - ovos_plugin_manager.wakewords:load_module:134 - INFO - Loading "hey_mycroft" wake word via ovos-ww-> pulseaudio[647]: ALSA woke us up to read new data from the device, but there was actually nothing to read. pulseaudio[647]: Most likely this is a bug in the ALSA driver 'snd_usb_audio'. Please report this issue to the ALSA developers. pulseaudio[647]: We were woken up with POLLIN set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.

CaptainCoward commented 10 months ago

This kinda started on me out of nowhere without doing any update. I don't even know when it happens and so far only noticed the "Issues" through checking my journal. There is nothing related to it before or after and i also checked dmesg in case something got disconnected. But nothing I get the same 3 Error lines with the only difference that it mentions the "snd_usb_audio" instead of "intel_hda_audio"

pulseaudio[1031]: ALSA woke us up to read new data from the device, but there was actually nothing to read. pulseaudio[1031: Most likely this is a bug in the ALSA driver 'snd_usb_audio'. Please report this issue to the ALSA developers. pulseaudio[1031]: We were woken up with POLLIN set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.

davidngrc commented 9 months ago

I was on Proxmox 7.0 to 7.4, pass-through a usb audio headphone to ubuntu 22.04 desktop, no problem at all. I backup the ubuntu, and new install Proxmox 8 + kernel 6.2.16-12, I restore the original ubuntu. now I watch youtube, it will play for a while, then it stop.

in /var/log/syslog I saw

22:10:27 pc-name kernel: [ 457.985239] xhci_hcd 0000:07:1b.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 11 comp_code 1 22:10:27 pc-name kernel: [ 457.985258] xhci_hcd 0000:07:1b.0: Looking for event-dma 000000038fba0080 trb-start 000000038fba0070 trb-end 000000038fba0070 seg-start 000000038fba0000 seg-end 000000038fba0ff0 22:10:27 pc-name systemd[2249]: pulseaudio.service: Main process exited, code=killed, status=9/KILL 22:10:27 pc-name systemd[2249]: pulseaudio.service: Failed with result 'signal'. 22:10:27 pc-name firefox_firefox.desktop[5745]: [Child 5745, AudioIPC Client Callback] WARNING: 7efdd12763a0 StateCallback() state 1 cubeb error: file /build/firefox/parts/firefox/build/dom/media/AudioStream.cpp:662 22:10:27 pc-name firefox_firefox.desktop[5745]: [Child 5745, MediaDecoderStateMachine #2] WARNING: Decoder=7efde6ca7700 [OnMediaSinkAudioError]: file /build/firefox/parts/firefox/build/dom/media/MediaDecoderStateMachine.cpp:4567 22:10:27 pc-name systemd[2249]: pulseaudio.service: Consumed 1.580s CPU time. 22:10:28 pc-name systemd[2249]: pulseaudio.service: Scheduled restart job, restart counter is at 1. 22:10:28 pc-name systemd[2249]: Stopped Sound Service. 22:10:28 pc-name systemd[2249]: pulseaudio.service: Consumed 1.580s CPU time. 22:10:28 pc-name systemd[2249]: Starting Sound Service... 22:10:28 pc-name rtkit-daemon[1516]: Successfully made thread 6324 of process 6324 owned by '1000' high priority at nice level -11. 22:10:28 pc-name rtkit-daemon[1516]: Supervising 6 threads of 5 processes of 1 users. 22:10:28 pc-name pulseaudio[6324]: Stale PID file, overwriting. 22:10:28 pc-name pulseaudio[6324]: Failed to find a working profile. 22:10:28 pc-name pulseaudio[6324]: Failed to load module "module-alsa-card" (argument: "device_id="2" name="pci-0000_00_1b.0" card_name="alsa_card.pci-0000_00_1b.0" namereg_fail=false tsched=yes fixed_latency_range=no ignore_dB=no deferred_volume=yes use_ucm=yes avoid_resampling=no card_properties="module-udev-detect.discovered=1""): initialization failed. 22:10:28 pc-name pulseaudio[6324]: The decibel volume range for element 'PCM' (-5200 dB - -200 dB) has negative maximum. Disabling the decibel range. 22:10:28 pc-name pulseaudio[6324]: message repeated 4 times: [ The decibel volume range for element 'PCM' (-5200 dB - -200 dB) has negative maximum. Disabling the decibel range.] 22:10:28 pc-name pulseaudio[6324]: Disabling timer-based scheduling because running inside a VM. 22:10:28 pc-name rtkit-daemon[1516]: Supervising 6 threads of 5 processes of 1 users. 22:10:28 pc-name rtkit-daemon[1516]: Successfully made thread 6325 of process 6324 owned by '1000' RT at priority 5. 22:10:28 pc-name rtkit-daemon[1516]: Supervising 7 threads of 5 processes of 1 users. 22:10:28 pc-name pulseaudio[6324]: Disabling timer-based scheduling because running inside a VM. 22:10:28 pc-name rtkit-daemon[1516]: Supervising 7 threads of 5 processes of 1 users. 22:10:28 pc-name rtkit-daemon[1516]: Successfully made thread 6326 of process 6324 owned by '1000' RT at priority 5. 22:10:28 pc-name rtkit-daemon[1516]: Supervising 8 threads of 5 processes of 1 users. 22:10:28 pc-name pulseaudio[6324]: Disabling timer-based scheduling because running inside a VM. 22:10:28 pc-name rtkit-daemon[1516]: Supervising 8 threads of 5 processes of 1 users. 22:10:28 pc-name rtkit-daemon[1516]: Successfully made thread 6327 of process 6324 owned by '1000' RT at priority 5. 22:10:28 pc-name rtkit-daemon[1516]: Supervising 9 threads of 5 processes of 1 users. 22:10:28 pc-name dbus-daemon[1131]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.144' (uid=1000 pid=6324 comm="/usr/bin/pulseaudio --daemonize=no --log-target=jo" label="unconfined") 22:10:28 pc-name systemd[1]: Condition check resulted in Bluetooth service being skipped. 22:10:28 pc-name systemd[2249]: Started Sound Service. 22:10:32 pc-name gsd-media-keys[2806]: Unable to get default sink 22:10:32 pc-name gsd-media-keys[2806]: Unable to get default source 22:10:32 pc-name pulseaudio[6324]: ALSA woke us up to write new data to the device, but there was actually nothing to write. 22:10:32 pc-name pulseaudio[6324]: Most likely this is a bug in the ALSA driver 'snd_usb_audio'. Please report this issue to the ALSA developers. 22:10:32 pc-name pulseaudio[6324]: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail. 22:10:39 pc-name systemd[2249]: Started Application launched by gnome-shell. 22:10:39 pc-name dbus-daemon[2271]: [session uid=1000 pid=2271] Activating via systemd: service name='org.gnome.Terminal' unit='gnome-terminal-server.service' requested by ':1.115' (uid=1000 pid=6337 comm="/usr/bin/gnome-terminal.real " label="unconfined") 22:10:39 pc-name systemd[2249]: Created slice Slice /app/org.gnome.Terminal. 22:10:39 pc-name systemd[2249]: Starting GNOME Terminal Server... 22:10:39 pc-name dbus-daemon[2271]: [session uid=1000 pid=2271] Successfully activated service 'org.gnome.Terminal' 22:10:39 pc-name systemd[2249]: Started GNOME Terminal Server. 22:10:40 pc-name kernel: [ 470.308426] perf: interrupt took too long (3225 > 3221), lowering kernel.perf_event_max_sample_rate to 62000 22:10:40 pc-name systemd[2249]: Started VTE child process 6361 launched by gnome-terminal-server process 6340.

Impasse52 commented 8 months ago

Also got this on Fedora 38 with PulseAudio (installed through dnf swap pipewire). I heard a popping/distortion sound while watching a video on YouTube on Firefox and found the following when inspecting journalctl -xe:

ott 20 11:45:16 fedora pulseaudio[20241]: ALSA woke us up to write new data to the device, but there was actually nothing to write.
ott 20 11:45:16 fedora pulseaudio[20241]: Most likely this is a bug in the ALSA driver 'snd_usb_audio'. Please report this issue to the ALSA developers.
ott 20 11:45:16 fedora pulseaudio[20241]: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
fancsali commented 7 months ago

It seems to me, postmarketOS is suffering from the same recently. Odd thing, it started out of the blue a few weeks ago...

Nov 14 11:14:08 <hostname> user.err pulseaudio[8617]: [alsa-sink-Analog HiFi-0] alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write.
Nov 14 11:14:08 <hostname> user.err pulseaudio[8617]: [alsa-sink-Analog HiFi-0] alsa-sink.c: Most likely this is a bug in the ALSA driver 'snd_soc_rockchip_max98090'. Please report this issue to the ALSA developers.
Nov 14 11:14:08 <hostname> user.err pulseaudio[8617]: [alsa-sink-Analog HiFi-0] alsa-sink.c: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.

Machine is an Asus C100P (google-veyron-minnie), running pmOS/Alpine edge, with PulseAudio 16.1.

greenozon commented 5 days ago

it's 2024 and we still hitting this error:

cat /etc/issue
Ubuntu 22.04.4 LTS \n \l

uname -a
Linux tplevo347 5.15.0-112-generic #122-Ubuntu SMP Thu May 23 07:48:21 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux

pulseaudio --version
pulseaudio 15.99.1

dpkg -l pulseaudio
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name           Version                    Architecture Description
+++-==============-==========================-============-=================================
ii  pulseaudio     1:15.99.1+dfsg1-1ubuntu2.2 amd64        PulseAudio sound server
(END)

from dmesg:

Jun 29 19:59:23 tplevo347 pulseaudio[2519]: ALSA woke us up to write new data to the device, but there was actually nothing to write.
Jun 29 19:59:23 tplevo347 pulseaudio[2519]: Most likely this is a bug in the ALSA driver 'snd_usb_audio'. Please report this issue to the ALSA developers.
Jun 29 19:59:23 tplevo347 pulseaudio[2519]: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.

Lenovo Thinkpad T460