alsa-lib PA - snd_pcm_avail() returned a value that is exceptionally large

I hope this is the right place to report this. This occurred in relation to a crash. http://alsa-project.org/db/?f=52e8505d884682fc06adac4ab8ce92a4ca3e0870

E: [alsa-sink-ALC887-VD Analog] alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 177312 bytes (923 ms).
E: [alsa-sink-ALC887-VD Analog] alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA developers.
E: [alsa-sink-ALC887-VD Analog] alsa-util.c: snd_pcm_dump():
E: [alsa-sink-ALC887-VD Analog] alsa-util.c: Soft volume PCM
E: [alsa-sink-ALC887-VD Analog] alsa-util.c: Control: PCM Playback Volume
E: [alsa-sink-ALC887-VD Analog] alsa-util.c: min_dB: -51
E: [alsa-sink-ALC887-VD Analog] alsa-util.c: max_dB: 0
E: [alsa-sink-ALC887-VD Analog] alsa-util.c: resolution: 256
E: [alsa-sink-ALC887-VD Analog] alsa-util.c: Its setup is:
E: [alsa-sink-ALC887-VD Analog] alsa-util.c:   stream       : PLAYBACK
E: [alsa-sink-ALC887-VD Analog] alsa-util.c:   access       : MMAP_INTERLEAVED
E: [alsa-sink-ALC887-VD Analog] alsa-util.c:   format       : S16_LE
E: [alsa-sink-ALC887-VD Analog] alsa-util.c:   subformat    : STD
E: [alsa-sink-ALC887-VD Analog] alsa-util.c:   channels     : 2
E: [alsa-sink-ALC887-VD Analog] alsa-util.c:   rate         : 48000
E: [alsa-sink-ALC887-VD Analog] alsa-util.c:   exact rate   : 48000 (48000/1)
E: [alsa-sink-ALC887-VD Analog] alsa-util.c:   msbits       : 16
E: [alsa-sink-ALC887-VD Analog] alsa-util.c:   buffer_size  : 4800

Jul 18 '20 07:07 reezer

bug.txt I have the same issue and logs say it should be reported (but it doesn't say where). It happened several times before; my whole system is unusable for some time when this happens.

Dec 06 '20 18:12 kyrawertho

This started occurring to me as well, on a system (Kubuntu 20.10 on Lenovo ThinkPad T420s) where my configuration of both ALSA and Pulseaudio has been rock solid for years. Does anyone have an idea of how to approach debugging it?

Dec 11 '20 21:12 RogueScholar

The PA check is not 100%. The real time measurement is missing, so it may be possible, that there's a task scheduling glitch (gap).

This suggest also the log in the second comment which clearly identifies that the system is too much busy:

Web Content invoked oom-killer: gfp_mask=0x100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0

PA disables the stream stop (see stop_threshold) settings in the kernel, thus this situation may occur. Discuss this with PA developers.

EDIT: Add @tanuk for the discussion.

Dec 14 '20 07:12 perexg

Maybe we shouldn't tell users to report these problems to the ALSA developers if they are not actionable, or have those reports ever resulted in any kernel driver fixes?

Dec 17 '20 16:12 tanuk

The problem with those redirections is that there are many false-positive reports (they are here, in kernel bugzilla and ocassionally on the alsa-devel mailing list). If PA does not measure the real time for the ALSA calls, the behaviour is correct when the system is overloaded (no real time processing).

I suggest to print the error (or warning) and add the real time measurement (to exclude /or report/ the scheduler problems) when PA runs in the debug mode without the redirection. The drivers are more stable than they were a decade ago.

Dec 17 '20 17:12 perexg

I created this issue for PulseAudio: https://gitlab.freedesktop.org/pulseaudio/pulseaudio/-/issues/1078

Dec 18 '20 16:12 tanuk

~~In my case it seems that the problem was derived from thermald.service in Linux Mint 20.1 Ulyssa, for now I have no problem since disabling this service~~ https://github.com/alsa-project/alsa-lib/issues/141

It has happened to me again even without that

jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: snd_pcm_avail() returned a value that is exceptionally large: 353152 bytes (2001 ms).
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA developers.
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: snd_pcm_dump():
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: Soft volume PCM
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: Control: PCM Playback Volume
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: min_dB: -51
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: max_dB: 0
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: resolution: 256
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: Its setup is:
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   stream       : PLAYBACK
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   access       : MMAP_INTERLEAVED
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   format       : S16_LE
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   subformat    : STD
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   channels     : 2
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   rate         : 44100
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   exact rate   : 44100 (44100/1)
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   msbits       : 16
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   buffer_size  : 4408
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   period_size  : 1102
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   period_time  : 24988
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   tstamp_mode  : ENABLE
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   tstamp_type  : MONOTONIC
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   period_step  : 1
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   avail_min    : 1102
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   period_event : 1
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   start_threshold  : -1
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   stop_threshold   : 4962966789362286592
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   silence_threshold: 0
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   silence_size : 0
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   boundary     : 4962966789362286592
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: Slave: Hardware PCM card 0 'HDA Intel PCH' device 0 subdevice 0
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: Its setup is:
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   stream       : PLAYBACK
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   access       : MMAP_INTERLEAVED
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   format       : S16_LE
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   subformat    : STD
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   channels     : 2
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   rate         : 44100
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   exact rate   : 44100 (44100/1)
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   msbits       : 16
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   buffer_size  : 4408
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   period_size  : 1102
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   period_time  : 24988
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   tstamp_mode  : ENABLE
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   tstamp_type  : MONOTONIC
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   period_step  : 1
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   avail_min    : 1102
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   period_event : 1
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   start_threshold  : -1
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   stop_threshold   : 4962966789362286592
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   silence_threshold: 0
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   silence_size : 0
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   boundary     : 4962966789362286592
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   appl_ptr     : 36626144
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   hw_ptr       : 36710024
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: snd_pcm_delay() returned a value that is exceptionally large: -159128 bytes (-902 ms).
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA developers.
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: snd_pcm_dump():
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: Soft volume PCM
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: Control: PCM Playback Volume
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: min_dB: -51
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: max_dB: 0
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: resolution: 256
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: Its setup is:
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   stream       : PLAYBACK
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   access       : MMAP_INTERLEAVED
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   format       : S16_LE
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   subformat    : STD
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   channels     : 2
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   rate         : 44100
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   exact rate   : 44100 (44100/1)
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   msbits       : 16
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   buffer_size  : 4408
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   period_size  : 1102
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   period_time  : 24988
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   tstamp_mode  : ENABLE
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   tstamp_type  : MONOTONIC
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   period_step  : 1
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   avail_min    : 1102
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   period_event : 1
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   start_threshold  : -1
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   stop_threshold   : 4962966789362286592
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   silence_threshold: 0
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   silence_size : 0
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   boundary     : 4962966789362286592
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: Slave: Hardware PCM card 0 'HDA Intel PCH' device 0 subdevice 0
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]: Its setup is:
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   stream       : PLAYBACK
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   access       : MMAP_INTERLEAVED
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   format       : S16_LE
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   subformat    : STD
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   channels     : 2
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   rate         : 44100
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   exact rate   : 44100 (44100/1)
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   msbits       : 16
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   buffer_size  : 4408
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   period_size  : 1102
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   period_time  : 24988
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   tstamp_mode  : ENABLE
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   tstamp_type  : MONOTONIC
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   period_step  : 1
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   avail_min    : 1102
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   period_event : 1
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   start_threshold  : -1
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   stop_threshold   : 4962966789362286592
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   silence_threshold: 0
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   silence_size : 0
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   boundary     : 4962966789362286592
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   appl_ptr     : 36670224
jul 26 16:09:49 jeronimo17-GIGABYTE-AORUS-7-KB pulseaudio[1415]:   hw_ptr       : 36710048

I use Audacious a lot and had the buffer at 1000ms, that gave me a very high latency so the solution I had was to put tsched=0 in /etc/pulse/default.pa, I just read that the Intel seem to work better with tsched. I have left it as it comes and in Audacious the buffer at least 100ms now it seems that the latency is correct again

I don't know if tsched could be related to the error

Jun 01 '21 21:06 Jeronimo17

My laptop just froze for the second time in a few days. This time I checked the syslog and found the same message, which brought me here.

Just to be sure I understand correctly, this is a WONTFIX because the issue reported by this message is caused by some latency issue but is not necessarily an issue in ALSA itself, right?

I don't find any other lead in the syslog, so I can't do much more.

Should I report this to my distro (Debian)? Is there even a point doing so?

Jan 28 '22 12:01 lafrech

I finally disabled tsched=0 and with the latest kernel and Nvidia updates and removing the Xfwm4 compositor options.

Compositor XFCE4

I did not get this error and the laptop keyboard did not start up again.

I don't really know how it all relates but with this configuration it has been working fine for months now

System:    Kernel: 5.13.0-27-generic x86_64 bits: 64 Desktop: Xfce 4.16.0 Distro: Linux Mint 20.3 Una 
Machine:   Type: Laptop System: GIGABYTE product: AORUS 7 KB v: N/A serial: <filter> 
           Mobo: GIGABYTE model: AORUS 7 KB serial: <filter> UEFI: INSYDE v: FB06 date: 08/03/2020 
Battery:   ID-1: BAT0 charge: 40.6 Wh condition: 43.8/47.2 Wh (93%) 
CPU:       Topology: 6-Core model: Intel Core i7-10750H bits: 64 type: MT MCP L2 cache: 12.0 MiB 
           Speed: 3102 MHz min/max: 800/5000 MHz Core speeds (MHz): 1: 1968 2: 942 3: 800 4: 800 5: 800 
           6: 800 7: 800 8: 800 9: 1057 10: 809 11: 1274 12: 1078 
Graphics:  Device-1: Intel UHD Graphics driver: i915 v: kernel 
           Device-2: NVIDIA TU106 [GeForce RTX 2060] driver: nvidia v: 495.46 
           Display: x11 server: X.Org 1.20.13 driver: modesetting,nvidia unloaded: fbdev,nouveau,vesa 
           resolution: 1920x1080~144Hz 
           OpenGL: renderer: NVIDIA GeForce RTX 2060/PCIe/SSE2 v: 4.6.0 NVIDIA 495.46 
Audio:     Device-1: Intel Comet Lake PCH cAVS driver: snd_hda_intel 
           Device-2: NVIDIA TU106 High Definition Audio driver: snd_hda_intel 
           Sound Server: ALSA v: k5.13.0-27-generic 
Network:   Device-1: Intel Wi-Fi 6 AX200 driver: iwlwifi 
           IF: wlp12s0 state: down mac: <filter> 
           Device-2: Realtek RTL8111/8168/8411 PCI Express Gigabit Ethernet driver: r8169 
           IF: enp13s0f1 state: up speed: 1000 Mbps duplex: full mac: <filter> 
Drives:    Local Storage: total: 1.12 TiB used: 597.29 GiB (52.0%) 
           ID-1: /dev/nvme0n1 model: SX8200PNP-512GT-S size: 476.94 GiB 
           ID-2: /dev/sda model: Q-720 size: 670.69 GiB 
Partition: ID-1: / size: 144.03 GiB used: 46.78 GiB (32.5%) fs: ext4 dev: /dev/nvme0n1p4 
           ID-2: /home size: 192.12 GiB used: 137.32 GiB (71.5%) fs: ext4 dev: /dev/nvme0n1p5 
           ID-3: swap-1 size: 14.65 GiB used: 0 KiB (0.0%) fs: swap dev: /dev/nvme0n1p6 
Sensors:   System Temperatures: cpu: 40.0 C mobo: N/A gpu: nvidia temp: 40 C 
           Fan Speeds (RPM): cpu: 2071 
Info:      Processes: 326 Uptime: 55m Memory: 15.33 GiB used: 2.95 GiB (19.3%) Shell: bash inxi: 3.0.38

and in /etc/default/grub GRUB_CMDLINE_LINUX_DEFAULT="pcie_aspm=off nvidia-drm.modeset=1"

Jan 28 '22 13:01 Jeronimo17

alsa-lib alsa-lib copied to clipboard

PA - snd_pcm_avail() returned a value that is exceptionally large

alsa-lib
alsa-lib copied to clipboard