Bug 22172

Summary: alsa-util.c: snd_pcm_avail_delay() returned strange values: delay 0 is less than avail 32
Product: Drivers Reporter: Tobias (devnull)
Component: Sound(ALSA)Assignee: Jaroslav Kysela (perex)
Status: CLOSED UNREPRODUCIBLE    
Severity: normal CC: devnull, florian, maciej.rutecki, rjw, seven.steps, teg, tiwai
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 2.6.37-rc1 Subsystem:
Regression: Yes Bisected commit-id:
Bug Depends on:    
Bug Blocks: 16444    

Description Tobias 2010-11-06 09:33:11 UTC
I am starting to see this in syslog:


Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c: snd_pcm_avail_delay() returned strange values: delay 0 is less than avail 32.
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA developers.
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c: snd_pcm_dump():
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c: Soft volume PCM
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c: Control: PCM Playback Volume
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c: min_dB: -51
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c: max_dB: 0
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c: resolution: 256
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c: Its setup is:
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   stream       : CAPTURE
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   access       : MMAP_INTERLEAVED
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   format       : S16_LE
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   subformat    : STD
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   channels     : 2
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   rate         : 44100
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   exact rate   : 44100 (44100/1)
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   msbits       : 16
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   buffer_size  : 16384
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   period_size  : 8192
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   period_time  : 185759
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   tstamp_mode  : ENABLE
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   period_step  : 1
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   avail_min    : 15502
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   period_event : 0
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   start_threshold  : -1
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   stop_threshold   : 4611686018427387904
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   silence_threshold: 0
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   silence_size : 0
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   boundary     : 4611686018427387904
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c: Slave: Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c: Its setup is:
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   stream       : CAPTURE
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   access       : MMAP_INTERLEAVED
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   format       : S16_LE
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   subformat    : STD
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   channels     : 2
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   rate         : 44100
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   exact rate   : 44100 (44100/1)
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   msbits       : 16
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   buffer_size  : 16384
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   period_size  : 8192
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   period_time  : 185759
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   tstamp_mode  : ENABLE
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   period_step  : 1
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   avail_min    : 15502
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   period_event : 0
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   start_threshold  : -1
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   stop_threshold   : 4611686018427387904
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   silence_threshold: 0
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   silence_size : 0
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   boundary     : 4611686018427387904
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   appl_ptr     : 15536
Nov  6 10:21:11 lucid pulseaudio[1490]: alsa-util.c:   hw_ptr       : 15536
Comment 1 Tobias 2010-11-06 09:36:04 UTC
Probably related:

Nov  6 08:48:06 lucid pulseaudio[10496]: alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write!
Nov  6 08:48:06 lucid pulseaudio[10496]: alsa-sink.c: Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA deve
lopers.
Nov  6 08:48:06 lucid pulseaudio[10496]: alsa-sink.c: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value <
 min_avail.

Forgot to add device info:

00:1b.0 Audio device: Intel Corporation N10/ICH 7 Family High Definition Audio Controller (rev 02)
Comment 2 Daniel T Chen 2010-12-05 20:23:33 UTC
Please use http://www.alsa-project.org/alsa-info.sh
Comment 3 Tom Gundersen 2010-12-12 02:54:57 UTC
I'm observing a similar problem. Here is my alsa-info: <http://www.alsa-project.org/db/?f=2edaf27ae5afd76f0767e82d31d4515c134ef18c>.

And here is my syslog output:

Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c: snd_pcm_avail_delay() returned strange values: delay 0 is less than avail 16.
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA developers.
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c: snd_pcm_dump():
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c: Soft volume PCM
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c: Control: PCM Playback Volume
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c: min_dB: -51
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c: max_dB: 0
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c: resolution: 256
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c: Its setup is:
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   stream       : CAPTURE
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   access       : MMAP_INTERLEAVED
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   format       : S16_LE
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   subformat    : STD
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   channels     : 2
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   rate         : 44100
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   exact rate   : 44100 (44100/1)
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   msbits       : 16
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   buffer_size  : 16384
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   period_size  : 8192
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   period_time  : 185759
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   tstamp_mode  : ENABLE
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   period_step  : 1
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   avail_min    : 15502
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   period_event : 0
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   start_threshold  : -1
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   stop_threshold   : 4611686018427387904
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   silence_threshold: 0
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   silence_size : 0
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   boundary     : 4611686018427387904
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c: Slave: Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c: Its setup is:
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   stream       : CAPTURE
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   access       : MMAP_INTERLEAVED
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   format       : S16_LE
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   subformat    : STD
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   channels     : 2
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   rate         : 44100
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   exact rate   : 44100 (44100/1)
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   msbits       : 16
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   buffer_size  : 16384
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   period_size  : 8192
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   period_time  : 185759
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   tstamp_mode  : ENABLE
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   period_step  : 1
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   avail_min    : 15502
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   period_event : 0
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   start_threshold  : -1
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   stop_threshold   : 4611686018427387904
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   silence_threshold: 0
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   silence_size : 0
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   boundary     : 4611686018427387904
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   appl_ptr     : 15520
Dec 12 02:53:20 dell pulseaudio[756]: alsa-util.c:   hw_ptr       : 15520
Comment 4 Florian Mickler 2011-03-29 21:48:13 UTC
Is this still happening onĀ 2.6.38.y?
Comment 5 Florian Mickler 2011-04-20 20:03:31 UTC
*ping*
Comment 6 Tom Gundersen 2011-04-20 22:42:32 UTC
Sorry for the slow response.

I have not seen this in a while (using 2.6.39-rcX). I will report back if I do.
Comment 7 Florian Mickler 2011-04-21 08:56:55 UTC
Thanks for the update. Please do. 

In the meantime, I will close this report.