snd_pcm_avail() returned a value that is exceptionally large

Bug #1274115 reported by Bazilio on 2014-01-29
96
This bug affects 21 people
Affects Status Importance Assigned to Milestone
pulseaudio (Ubuntu)
Undecided
Unassigned

Bug Description

Sometimese sound begins stutter while listen to music or watching youtube. In syslog I see:
Jan 29 16:31:08 bazilio-laptop pulseaudio[2155]: [alsa-sink-ALC271X Analog] alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 866944 bytes (4914 ms).
Jan 29 16:31:08 bazilio-laptop pulseaudio[2155]: [alsa-sink-ALC271X 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.

I'm using Kubuntu 13.10
$ uname -a
Linux bazilio-laptop 3.11.0-15-generic #23-Ubuntu SMP Mon Dec 9 18:17:04 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux
$ kde4-config --version
Qt: 4.8.4
KDE Development Platform: 4.12.0
kde4-config: 1.0
$ pulseaudio --version
pulseaudio 4.0
$ alsactl --version
alsactl version 1.0.27.1

Bazilio (bazilio-recast1) wrote :
Bazilio (bazilio-recast1) wrote :
Raymond (superquad-vortex2) wrote :

Jan 29 16:31:08 bazilio-laptop pulseaudio[2155]: [alsa-sink-ALC271X Analog] alsa-util.c: start_threshold : -1
Jan 29 16:31:08 bazilio-laptop pulseaudio[2155]: [alsa-sink-ALC271X Analog] alsa-util.c: stop_threshold : 4611686018427387904
Jan 29 16:31:08 bazilio-laptop pulseaudio[2155]: [alsa-sink-ALC271X Analog] alsa-util.c: silence_threshold: 0
Jan 29 16:31:08 bazilio-laptop pulseaudio[2155]: [alsa-sink-ALC271X Analog] alsa-util.c: silence_size : 0
Jan 29 16:31:08 bazilio-laptop pulseaudio[2155]: [alsa-sink-ALC271X Analog] alsa-util.c: appl_ptr : 23472671
Jan 29 16:31:08 bazilio-laptop pulseaudio[2155]: [alsa-sink-ALC271X Analog] alsa-util.c: hw_ptr : 23673023

appl_pre is behind hw_ptr which mean pulseaudio did not send enough data to sound card driver

the driver does not stop or report underrun because pulseaudio set the stop threshold to bounadary instead of buffer size

Raymond (superquad-vortex2) wrote :

http://www.alsa-project.org/main/index.php/XRUN_Debug

Enable basic debugging and dump stack, check hardware pointer on the period update
 # Usefull to just see, if PCM stream is stopped for a reason (usually wrong audio process timing from scheduler)
 # And to check the values from driver
 echo 11 > /proc/asound/card0/pcm0p/xrun_debug

Changed in alsa-driver (Ubuntu):
status: New → Incomplete
affects: alsa-driver (Ubuntu) → pulseaudio (Ubuntu)
Raymond (superquad-vortex2) wrote :

you have to provide steps to reprodice the bug and pulseaudio verbose log when the bug occur

do the network busy for more than the buffer size of the sound card (0.371 second) if you are listening audio from remote site online ?

an 29 16:31:08 bazilio-laptop pulseaudio[2155]: [alsa-sink-ALC271X Analog] alsa-util.c: rate : 44100
Jan 29 16:31:08 bazilio-laptop pulseaudio[2155]: [alsa-sink-ALC271X Analog] alsa-util.c: exact rate : 44100 (44100/1)
Jan 29 16:31:08 bazilio-laptop pulseaudio[2155]: [alsa-sink-ALC271X Analog] alsa-util.c: msbits : 16
Jan 29 16:31:08 bazilio-laptop pulseaudio[2155]: [alsa-sink-ALC271X Analog] alsa-util.c: buffer_size : 16384
Jan 29 16:31:08 bazilio-laptop pulseaudio[2155]: [alsa-sink-ALC271X Analog] alsa-util.c: period_size : 8192
Jan 29 16:31:08 bazilio-laptop pulseaudio[2155]: [alsa-sink-ALC271X Analog] alsa-util.c: period_time : 185759

Bazilio (bazilio-recast1) wrote :

I have two cards:
ls -al /proc/asound/
total 0
dr-xr-xr-x 5 root root 0 янв. 30 10:52 .
dr-xr-xr-x 244 root root 0 янв. 30 10:32 ..
dr-xr-xr-x 3 root root 0 янв. 30 10:52 card0
dr-xr-xr-x 4 root root 0 янв. 30 10:52 card1
-r--r--r-- 1 root root 0 янв. 30 10:52 cards
-r--r--r-- 1 root root 0 янв. 30 10:52 devices
lrwxrwxrwx 1 root root 5 янв. 30 10:52 Generic -> card1
lrwxrwxrwx 1 root root 5 янв. 30 10:52 HDMI -> card0
-r--r--r-- 1 root root 0 янв. 30 10:52 hwdep
-r--r--r-- 1 root root 0 янв. 30 10:52 modules
-r--r--r-- 1 root root 0 янв. 30 10:52 pcm
dr-xr-xr-x 2 root root 0 янв. 30 10:52 seq
-r--r--r-- 1 root root 0 янв. 30 10:52 timers
-r--r--r-- 1 root root 0 янв. 30 10:52 version

This bug probably only about Generic -> card1
So I did
echo 11 > /proc/asound/card1/pcm0p/xrun_debug
but after reboot it returned to 0.
So I did it again and now it shows 11:
cat /proc/asound/card1/pcm0p/xrun_debug
11

Where can I see detailed logs?

It's difficult to provide steps to reproduce the bug.
I'm just writing some php code and listening to music in Amarok. Music is mp3 files on my hard disk.
I have running: netbeans, two virtualbox instances, mysql server.
I have 8GB memory, but only 3.5 used (as htop shows me).
Sometimes, maybe once a hour, sound begins stutter for 3-5 seconds, then it stops stutter and music continues to play normaly.
Sound quality is perfect, no problems at all! Only this stutters.
This bug was noticed while watching youtube. Same simptoms: video stops and sound stutter for 3-5 seconds, then continues to play normaly.

Maybe some kubuntus cron jobs produce big HDD load or run with high cpu priority?
Is it possible?

Raymond (superquad-vortex2) wrote :

the message only occur in system when you playback to those device which you have been enabled ,

 do your build the driver in debug mode ?

 ./configure --with-debug=verbose

Raymond (superquad-vortex2) wrote :

you can use

 # Enable basic debugging and dump stack, check hardware pointer on all updates
 # Usefull to just see, if PCM stream is stopped for a reason (usually wrong audio process timing from scheduler)
 # And to do the exact check the values from driver
 echo 27 > /proc/asound/card0/pcm0p/xrun_debug

or

# Enable basic debugging, do jiffies check and dump position on each period and hardware pointer update calls
 # Usefull when the lowlevel (specific) hardware driver is somehow broken
 echo 29 > /proc/asound/card0/pcm0p/xrun_debug

Bazilio (bazilio-recast1) wrote :

I don't use hdmi device. I don't now is there a problem with hdmi.

I didn't build the driver. It was present in system after I install it.
Maybe I have to install some *dbg packages?
I don't build software on my system, I only "apt-get install" it.

Bazilio (bazilio-recast1) wrote :

It happen again.
I was reading this post.

I attached whole syslog. It was at 11:47:04

Bazilio (bazilio-recast1) wrote :

Ok, I did
echo 27 > /proc/asound/card1/pcm0p/xrun_debug

Should I restart some service or I just have to wait?

Bazilio (bazilio-recast1) wrote :

New state:

Sound stuttered again at 12:23

I attached part of syslog

After doing
echo 27 > /proc/asound/card1/pcm0p/xrun_debug
it started to output many lines to syslog every second

Now after stuttering I didn't notice strings with "[alsa-sink-ALC271X Analog] alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large", but I noticed, that after 12:23:45 it was 5 seconds without any log and after that at 12:23:50 there are these strings:

Jan 30 12:23:50 bazilio-laptop kernel: [ 6672.962574] ath: phy0: Chip reset failed
Jan 30 12:23:50 bazilio-laptop kernel: [ 6672.962581] ath: phy0: Unable to reset channel, reset status -22
Jan 30 12:23:50 bazilio-laptop kernel: [ 6672.962726] ath: phy0: Unable to set channel

Is it about network?

Now I think strings about "snd_pcm_avail() returned a value that is exceptionally large" and sound stuttering are not interdependent.
I think that sound stuttering becouse there is some problems with "ath: phy0: Chip reset failed"
If so I'll have to fire another bug to another project, isn't it?

Can you help me to approve it?

Bazilio (bazilio-recast1) wrote :

I can confirm that sound stuttering and "ath: phy0: Chip reset failed" are the same problem.
I turned off debugging (echo 0 > /proc/asound/card1/pcm0p/xrun_debug) at 12:41

Sound stuttered again at 12:50 and in syslog there are only strings about "ath: phy0: Chip reset failed".

There is part of syslog at this time:

Jan 30 12:41:01 bazilio-laptop kernel: [ 7703.204852] hwptr_update: pcmC1D0p:0: pos=4709/8192/16384, hwptr=0/61100645/61100645/61095936
Jan 30 12:42:13 bazilio-laptop dhclient: DHCPREQUEST of 192.168.0.28 on eth0 to 192.168.0.166 port 67 (xid=0x5d3ba2b9)
Jan 30 12:42:13 bazilio-laptop dhclient: DHCPACK of 192.168.0.28 from 192.168.0.166
Jan 30 12:42:13 bazilio-laptop dhclient: bound to 192.168.0.28 -- renewal in 268 seconds.
Jan 30 12:42:13 bazilio-laptop NetworkManager[1247]: <info> (eth0): DHCPv4 state changed renew -> renew
Jan 30 12:42:13 bazilio-laptop NetworkManager[1247]: <info> address 192.168.0.28
Jan 30 12:42:13 bazilio-laptop NetworkManager[1247]: <info> prefix 23 (255.255.254.0)
Jan 30 12:42:13 bazilio-laptop NetworkManager[1247]: <info> gateway 192.168.1.1
Jan 30 12:42:13 bazilio-laptop NetworkManager[1247]: <info> hostname 'bazilio-laptop'
Jan 30 12:42:13 bazilio-laptop NetworkManager[1247]: <info> nameserver '192.168.0.166'
Jan 30 12:42:13 bazilio-laptop dbus[912]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Jan 30 12:42:13 bazilio-laptop dbus[912]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Jan 30 12:46:41 bazilio-laptop dhclient: DHCPREQUEST of 192.168.0.28 on eth0 to 192.168.0.166 port 67 (xid=0x5d3ba2b9)
Jan 30 12:46:41 bazilio-laptop dhclient: DHCPACK of 192.168.0.28 from 192.168.0.166
Jan 30 12:46:41 bazilio-laptop dhclient: bound to 192.168.0.28 -- renewal in 295 seconds.
Jan 30 12:46:41 bazilio-laptop NetworkManager[1247]: <info> (eth0): DHCPv4 state changed renew -> renew
Jan 30 12:46:41 bazilio-laptop NetworkManager[1247]: <info> address 192.168.0.28
Jan 30 12:46:41 bazilio-laptop NetworkManager[1247]: <info> prefix 23 (255.255.254.0)
Jan 30 12:46:41 bazilio-laptop NetworkManager[1247]: <info> gateway 192.168.1.1
Jan 30 12:46:41 bazilio-laptop NetworkManager[1247]: <info> hostname 'bazilio-laptop'
Jan 30 12:46:41 bazilio-laptop NetworkManager[1247]: <info> nameserver '192.168.0.166'
Jan 30 12:46:41 bazilio-laptop dbus[912]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Jan 30 12:46:41 bazilio-laptop dbus[912]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Jan 30 12:50:05 bazilio-laptop kernel: [ 8247.400336] ath: phy0: Chip reset failed
Jan 30 12:50:05 bazilio-laptop kernel: [ 8247.400343] ath: phy0: Unable to reset channel, reset status -22
Jan 30 12:50:05 bazilio-laptop kernel: [ 8247.400820] ath: phy0: Unable to set channel

Raymond (superquad-vortex2) wrote :

there are 5 seconds without log but pos and hwptr are still increasing

Jan 30 12:23:45 bazilio-laptop kernel: [ 6667.662941] hwptr_update: pcmC1D0p:0: pos=13147/8192/16384, hwptr=1/15430490/15430491/15417344
Jan 30 12:23:50 bazilio-laptop kernel: [ 6672.962574] ath: phy0: Chip reset failed
Jan 30 12:23:50 bazilio-laptop kernel: [ 6672.962581] ath: phy0: Unable to reset channel, reset status -22
Jan 30 12:23:50 bazilio-laptop kernel: [ 6672.962726] ath: phy0: Unable to set channel
Jan 30 12:23:50 bazilio-laptop kernel: [ 6672.962962] hwptr_update: pcmC1D0p:0: pos=1132/8192/16384, hwptr=4369/15430491/15434860/15417344

Bazilio (bazilio-recast1) wrote :

Excuse me, I'm not familiar with these pos and hwptr. I only see that something wrong and hear it while listen to music.
What can I do now? Should I collect some more info? Is it a pulseaudio bug or should I file a bug to other project?

Bazilio (bazilio-recast1) wrote :

Any suggestions?

Raymond (superquad-vortex2) wrote :

seem something wrong with your dhclient which may cause loss of network connection and of course this lead to sound card underrun when there is the loss of network

do this occur when you listen to audio in your computer or just from audio from network ?

Jan 30 12:42:13 bazilio-laptop dhclient: DHCPREQUEST of 192.168.0.28 on eth0 to 192.168.0.166 port 67 (xid=0x5d3ba2b9)
Jan 30 12:42:13 bazilio-laptop dhclient: DHCPACK of 192.168.0.28 from 192.168.0.166
Jan 30 12:42:13 bazilio-laptop dhclient: bound to 192.168.0.28 -- renewal in 268 seconds.
Jan 30 12:42:13 bazilio-laptop NetworkManager[1247]: <info> (eth0): DHCPv4 state changed renew -> renew
Jan 30 12:42:13 bazilio-laptop NetworkManager[1247]: <info> address 192.168.0.28
Jan 30 12:42:13 bazilio-laptop NetworkManager[1247]: <info> prefix 23 (255.255.254.0)
Jan 30 12:42:13 bazilio-laptop NetworkManager[1247]: <info> gateway 192.168.1.1
Jan 30 12:42:13 bazilio-laptop NetworkManager[1247]: <info> hostname 'bazilio-laptop'
Jan 30 12:42:13 bazilio-laptop NetworkManager[1247]: <info> nameserver '192.168.0.166'
Jan 30 12:42:13 bazilio-laptop dbus[912]: [system] Activating service name='org.

Bazilio (bazilio-recast1) wrote :

I isten to audio from my computer. Mp3 files are on my laptop's hdd.

When this occur I can see that all 4 cores of cpu are 100% loading. Despite this system not hangs. Mouse is moving and I can type text. Only sound is stuttering.

Bazilio (bazilio-recast1) wrote :

Any other suggestions?

Bazilio (bazilio-recast1) wrote :

I'm realy looking forward to solve this problem.
Maybe I filed the bug in the wrong place?
Should I collect more infomation to solve this or should I file a bug to another project?
Can someone help me with this?

Launchpad Janitor (janitor) wrote :

[Expired for pulseaudio (Ubuntu) because there has been no activity for 60 days.]

Changed in pulseaudio (Ubuntu):
status: Incomplete → Expired
Download full text (11.4 KiB)

I started experiencing this error recently. In my HP pavilion laptop, Ubuntu freezes all of a sudden and becomes unusable that I need to restart the machine. I could see the below errors in syslog that are logged exactly when the freeze happens:

Feb 18 11:33:19 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 358640 bytes (2033 ms).
Feb 18 11:33:20 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 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.
Feb 18 11:33:21 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: snd_pcm_dump():
Feb 18 11:33:21 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: Soft volume PCM
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: Control: PCM Playback Volume
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: min_dB: -51
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: max_dB: 0
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: resolution: 256
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: Its setup is:
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: stream : PLAYBACK
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: access : MMAP_INTERLEAVED
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: format : S16_LE
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: subformat : STD
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: channels : 2
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: rate : 44100
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: exact rate : 44100 (44100/1)
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: msbits : 16
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: buffer_size : 16384
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: period_size : 8192
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: period_time : 185759
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: tstamp_mode : ENABLE
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: period_step : 1
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: avail_min : 8192
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: period_event : 0
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: start_threshold : -1
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: stop_threshold : 4611686018427387904
Feb 18 11:33:22 Mukani pulseaudio[4637]: [alsa-sink-ALC3227 Analog] alsa-util.c: silence_threshold: 0
Feb 18 11:33:22...

I just started receiving this error in my laptop when it freezes sporadically. Please let me know if you need any additional info.

Changed in pulseaudio (Ubuntu):
status: Expired → New
Boomer (gbmr) wrote :

I also have similar issue.

Launchpad Janitor (janitor) wrote :

Status changed to 'Confirmed' because the bug affects multiple users.

Changed in pulseaudio (Ubuntu):
status: New → Confirmed
izar (izar00) wrote :

similar issue here-
laptop freezes and get this message in the log.

thinkpad carbon x1 (2nd gen)
ubuntu 15.04

jonnieo (jonnie-o) wrote :

I have the same bug. Lenovo X1 yoga. Laptop becomes completely unresponsive. Anyone found a way out?

jonnieo (jonnie-o) wrote :

More info: I have the same bug. Lenovo X1 yoga. Laptop becomes completely unresponsive. ubuntu 16.04, kernel 4.4.0-47-generic, pulsaudo

 Anyone found a way out?

daniel CURTIS (anoda) wrote :

Hi. I have the same problem with [alsa-sink] and snd_pcm_avail() which returned a value that is exceptionally large etc. When it happening, system is slowing down, sometimes freeze.

Description: Ubuntu 12.04.5 LTS
Alsa ver.: alsa-utils 1.0.25-1ubuntu5.2
PulseAudio ver.: pulseaudio 1:1.1-0ubuntu15.4

Best regards.

Stefan (stefan13) wrote :

On my Lenovo B590, I was watching an mp4 movie using VLC and the computer became completely unresponsive, even the command line would not log me in.
Mint 17.03 (Ubuntu 14.04)
ALSA 1.0.25+dfsg-0ubuntu4
VLC Plugin Pulse 2.1.6-0ubuntu14.04.2
Pulse Audio: 1:4.0-0ubuntu11.1

My relevant syslog is attached.

RexS (nalgritz9270) wrote :

Similar condition to Stefan, my Asus UX305LA became completely unresponsive when listening youtube music and the computer and I have to force close and restart.

Mint 18.1 Cinnamon 64-bit (Ubuntu 16.04)
ALSA 1.0.25+dfsg-0ubuntu5
Firefox Dev Edition: 58.0b12 (64-bit)
Pulse Audio: 1:8.0-0ubuntu3.7

My syslog is attached. The incident happened exactly at Dec 20 15:10 so I'm quite sure it's the issue.

Daniel van Vugt (vanvugt) wrote :

Now tracking in bug 1750947 (I think) to get a fix in 16.04.

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers