Bug 518732

Summary: random crashes when playing sound files
Product: [Fedora] Fedora Reporter: James Bridge <james>
Component: pulseaudioAssignee: Lennart Poettering <lpoetter>
Status: CLOSED DUPLICATE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: low    
Version: 11CC: lkundrak, lpoetter, wtogami
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2009-08-24 14:41:48 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description James Bridge 2009-08-21 23:21:45 UTC 
Description of problem:


Version-Release number of selected component (if applicable):0.9.15


How reproducible: variable


Steps to Reproduce:
1. play music file
  
Actual results: output crashes unpredictably - generally after 2 - 30 minutes.
Often get a message "pa_stream_writable_size() failed. Connection terminated"


Expected results: not to crash, obviously.




Additional info:
I have tried several different players and types of file and watched the CPU usage. Mplayer is most stable: likely to play for 30 min or more, with cpu usage around 1% and pa 2-4%. Totem and Rhythmbox both use more cpu and fail sooner, typically after 2-5 min. Totem is more successful with wav files than mp3 or oga. In all cases the crash causes pa's cpu use to soar up to 85% or more.

Loading a wav file into Sound Recorder and playing it back also crashed after a few minutes, in this case with the message "pa_stream_cork() failed".

The problem is definitely fairly new - appeared since upgrade to F11. 

I am running fully updated F11 on a 2.66 Celeron machine with integrated Intel ICH5 sound chip.
Comment 1 Lennart Poettering 2009-08-24 02:31:46 UTC 
Most likely this is just another duplicate of bug 506075 or bug 501769. Please check syslog if you find any output from PA related to snd_pcm_delay() or snd_pcm_avail() overflowing.
Comment 2 James Bridge 2009-08-24 10:51:01 UTC 
you are correct. Output from syslog is
Aug 24 11:42:21 dadscomputer pulseaudio[2082]: alsa-sink.c: Increasing wakeup watermark to 30.00 ms
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-sink.c: Increasing wakeup watermark to 40.00 ms
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-sink.c: Increasing wakeup watermark to 50.00 ms
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 18446744073709540224 bytes (384307168142 ms).
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA developers.
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c: snd_pcm_dump():
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c: Hardware PCM card 0 'Intel ICH5' device 0 subdevice 0
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c: Its setup is:
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   stream       : PLAYBACK
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   access       : MMAP_INTERLEAVED
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   format       : S16_LE
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   subformat    : STD
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   channels     : 2
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   rate         : 48000
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   exact rate   : 48000 (48000/1)
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   msbits       : 16
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   buffer_size  : 16384
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   period_size  : 16384
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   period_time  : 341333
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   tstamp_mode  : ENABLE
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   period_step  : 1
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   avail_min    : 16384
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   period_event : 0
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   start_threshold  : -1
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   stop_threshold   : 4611686018427387904
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   silence_threshold: 0
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   silence_size : 0
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   boundary     : 4611686018427387904
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   appl_ptr     : 13945634
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   hw_ptr       : 13926402
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c: snd_pcm_delay() returned a value that is exceptionally large: 402284 bytes (2095 ms).
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA developers.
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c: snd_pcm_dump():
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c: Hardware PCM card 0 'Intel ICH5' device 0 subdevice 0
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c: Its setup is:
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   stream       : PLAYBACK
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   access       : MMAP_INTERLEAVED
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   format       : S16_LE
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   subformat    : STD
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   channels     : 2
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   rate         : 48000
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   exact rate   : 48000 (48000/1)
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   msbits       : 16
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   buffer_size  : 16384
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   period_size  : 16384
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   period_time  : 341333
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   tstamp_mode  : ENABLE
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   period_step  : 1
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   avail_min    : 16384
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   period_event : 0
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   start_threshold  : -1
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   stop_threshold   : 4611686018427387904
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   silence_threshold: 0
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   silence_size : 0
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   boundary     : 4611686018427387904
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   appl_ptr     : 14032034
Aug 24 11:43:19 dadscomputer pulseaudio[2082]: alsa-util.c:   hw_ptr       : 13931463
Aug 24 11:43:24 dadscomputer pulseaudio[2082]: ratelimit.c: 252 events suppressed
Aug 24 11:43:29 dadscomputer pulseaudio[2082]: ratelimit.c: 133 events suppressed
Aug 24 11:43:34 dadscomputer pulseaudio[2082]: ratelimit.c: 96 events suppressed
Aug 24 11:43:35 dadscomputer pulseaudio[2082]: cpulimit.c: Received request to terminate due to CPU overload.
Comment 3 Lennart Poettering 2009-08-24 14:41:48 UTC 
sigh

*** This bug has been marked as a duplicate of bug 506075 ***