Bug 508999 - pulseaudio loops on an alsa-sink error msg
pulseaudio loops on an alsa-sink error msg
Status: CLOSED CURRENTRELEASE
Product: Fedora
Classification: Fedora
Component: pulseaudio (Show other bugs)
11
All Linux
low Severity high
: ---
: ---
Assigned To: Lennart Poettering
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2009-06-30 15:31 EDT by Guy Streeter
Modified: 2016-02-09 20:32 EST (History)
9 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2009-10-23 15:17:27 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
pulseaudio -vvv log showing the error (203.12 KB, text/plain)
2009-06-30 15:31 EDT, Guy Streeter
no flags Details

  None (edit)
Description Guy Streeter 2009-06-30 15:31:40 EDT
Created attachment 350011 [details]
pulseaudio -vvv log showing the error

After a few minutes of playing music through a gstreamer-based app, pulseaudio stops responding and loops on printing these 3 error messages:

D: protocol-native.c: Requesting rewind due to rewrite.
D: alsa-sink.c: Requested to rewind 65536 bytes.
D: alsa-sink.c: Mhmm, actually there is nothing to rewind.

I will attach -vvv output from a run.
Comment 1 Guy Streeter 2009-07-10 11:41:22 EDT
Any ideas on this? Anything else you need to know?
I can't listen to music on this machine because pulseaudio hangs frequently.
Comment 2 zachary charlop-powers 2009-08-12 18:43:31 EDT
I am getting this same error message loop. It also comes on after a few minutes using any of the music players and all music formats.

My sound info is here:
http://www.alsa-project.org/db/?f=519998a2a4456353e8fad0dedce14500bc7a12b7


also, silly question, but I had wanted to post my pulseaudio -vvv as well but where IS the output written I tried "pulseaudio -vvv > log" and also looked in /etc
Comment 3 Nathan Crubel 2009-08-13 00:28:41 EDT
I am getting the same.  pulseuadio gets high cpu and found these messages in messages.

Aug 12 23:15:57 nc3700amd pulseaudio[2075]: ratelimit.c: 2803 events suppressed
Aug 12 23:15:57 nc3700amd pulseaudio[2075]: alsa-sink.c: Increasing wakeup watermark to 50.00 ms
Aug 12 23:16:02 nc3700amd pulseaudio[2075]: ratelimit.c: 9098 events suppressed
Aug 12 23:16:03 nc3700amd pulseaudio[2075]: alsa-sink.c: Increasing wakeup watermark to 60.00 ms
Aug 12 23:16:03 nc3700amd pulseaudio[2075]: alsa-sink.c: Increasing wakeup watermark to 70.00 ms
Aug 12 23:16:07 nc3700amd pulseaudio[2075]: ratelimit.c: 7961 events suppressed
Aug 12 23:16:10 nc3700amd pulseaudio[2075]: alsa-sink.c: Increasing wakeup watermark to 80.00 ms
Aug 12 23:16:17 nc3700amd pulseaudio[2075]: ratelimit.c: 4230 events suppressed
Aug 12 23:16:17 nc3700amd pulseaudio[2075]: alsa-sink.c: Increasing wakeup watermark to 90.00 ms
Aug 12 23:16:22 nc3700amd pulseaudio[2075]: ratelimit.c: 8763 events suppressed
Aug 12 23:16:23 nc3700amd pulseaudio[2075]: alsa-sink.c: Increasing wakeup watermark to 100.00 ms
Aug 12 23:16:42 nc3700amd pulseaudio[2075]: ratelimit.c: 1872 events suppressed
Aug 12 23:16:47 nc3700amd pulseaudio[2075]: ratelimit.c: 9067 events suppressed
Aug 12 23:16:48 nc3700amd pulseaudio[2075]: alsa-sink.c: Increasing wakeup watermark to 110.00 ms
Aug 12 23:17:02 nc3700amd kernel: usb 1-3: reset high speed USB device using ehci_hcd and address 2
Aug 12 23:19:09 nc3700amd pulseaudio[2075]: ratelimit.c: 1567 events suppressed
Aug 12 23:19:09 nc3700amd pulseaudio[2075]: alsa-sink.c: Increasing wakeup watermark to 120.00 ms
Aug 12 23:19:14 nc3700amd pulseaudio[2075]: ratelimit.c: 8846 events suppressed
Aug 12 23:19:15 nc3700amd pulseaudio[2075]: alsa-sink.c: Increasing wakeup watermark to 130.00 ms
Aug 12 23:20:31 nc3700amd pulseaudio[2075]: ratelimit.c: 1789 events suppressed
Aug 12 23:20:31 nc3700amd pulseaudio[2075]: alsa-sink.c: Increasing wakeup watermark to 140.00 ms
Aug 12 23:20:36 nc3700amd pulseaudio[2075]: ratelimit.c: 6563 events suppressed
Aug 12 23:20:38 nc3700amd pulseaudio[2075]: alsa-sink.c: Increasing wakeup watermark to 150.00 ms
Aug 12 23:20:39 nc3700amd pulseaudio[2075]: alsa-sink.c: Increasing wakeup watermark to 160.00 ms
Aug 12 23:20:41 nc3700amd pulseaudio[2075]: ratelimit.c: 8223 events suppressed
Aug 12 23:20:45 nc3700amd pulseaudio[2075]: alsa-sink.c: Increasing wakeup watermark to 170.00 ms
Aug 12 23:20:46 nc3700amd pulseaudio[2075]: ratelimit.c: 7309 events suppressed
Aug 12 23:20:47 nc3700amd pulseaudio[2075]: cpulimit.c: Received request to terminate due to CPU overload.
Comment 4 Joachim Backes 2009-08-25 04:08:27 EDT
Can confirm similar behaviour during playing a DVD with totem (each time after about 1 min playing correctly) : suddenly the sound stops, getting high CPU load. After logging out an relogging in, the same behaviour.

uname -r
2.6.29.6-217.2.8.fc11.i586

rpm -qa '*pulse*'

pulseaudio-module-zeroconf-0.9.15-14.fc11.i586
xmms-pulse-0.9.4-7.fc11.i586
pulseaudio-module-gconf-0.9.15-14.fc11.i586
pulseaudio-module-bluetooth-0.9.15-14.fc11.i586
pulseaudio-0.9.15-14.fc11.i586
pulseaudio-module-jack-0.9.15-14.fc11.i586
xine-lib-pulseaudio-1.1.16.3-2.fc11.i586
pulseaudio-esound-compat-0.9.15-14.fc11.i586
alsa-plugins-pulseaudio-1.0.20-2.fc11.i586
pulseaudio-utils-0.9.15-14.fc11.i586
wine-pulseaudio-1.1.23-1.fc11.i586
pulseaudio-libs-glib2-0.9.15-14.fc11.i586
pulseaudio-libs-zeroconf-0.9.15-14.fc11.i586
pulseaudio-module-x11-0.9.15-14.fc11.i586
pulseaudio-libs-0.9.15-14.fc11.i586
akode-pulseaudio-2.0.2-5.fc9.i386


/var/log/messages:

Aug 25 09:56:22 eule pulseaudio[2281]: alsa-sink.c: Increasing wakeup watermark to 30.00 ms
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-sink.c: Increasing wakeup watermark to 40.00 ms
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-sink.c: Increasing wakeup watermark to 50.00 ms
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 4294957568 bytes (22369570 ms).
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA developers.
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c: snd_pcm_dump():
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c: Hardware PCM card 0 'NVidia nForce2' device 0 subdevice 0
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c: Its setup is:
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   stream       : PLAYBACK
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   access       : MMAP_INTERLEAVED
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   format       : S16_LE
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   subformat    : STD
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   channels     : 2
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   rate         : 48000
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   exact rate   : 48000 (48000/1)
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   msbits       : 16
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   buffer_size  : 16384
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   period_size  : 16384
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   period_time  : 341333
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   tstamp_mode  : ENABLE
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   period_step  : 1
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   avail_min    : 16384
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   period_event : 0
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   start_threshold  : -1
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   stop_threshold   : 1073741824
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   silence_threshold: 0
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   silence_size : 0
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   boundary     : 1073741824
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   appl_ptr     : 1935776
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   hw_ptr       : 1916960
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c: snd_pcm_delay() returned a value that is exceptionally large: 417632 bytes (2175 ms).
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA developers.
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c: snd_pcm_dump():
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c: Hardware PCM card 0 'NVidia nForce2' device 0 subdevice 0
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c: Its setup is:
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   stream       : PLAYBACK
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   access       : MMAP_INTERLEAVED
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   format       : S16_LE
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   subformat    : STD
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   channels     : 2
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   rate         : 48000
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   exact rate   : 48000 (48000/1)
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   msbits       : 16
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   buffer_size  : 16384
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   period_size  : 16384
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   period_time  : 341333
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   tstamp_mode  : ENABLE
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   period_step  : 1
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   avail_min    : 16384
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   period_event : 0
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   start_threshold  : -1
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   stop_threshold   : 1073741824
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   silence_threshold: 0
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   silence_size : 0
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   boundary     : 1073741824
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   appl_ptr     : 2022176
Aug 25 09:57:02 eule pulseaudio[2281]: alsa-util.c:   hw_ptr       : 1917768
Aug 25 09:57:07 eule pulseaudio[2281]: ratelimit.c: 749 events suppressed
Aug 25 09:57:12 eule pulseaudio[2281]: ratelimit.c: 701 events suppressed
Aug 25 09:57:14 eule pulseaudio[2281]: alsa-sink.c: Increasing wakeup watermark
Comment 5 Lennart Poettering 2009-08-25 21:22:48 EDT
Joachim, your issue is unrelated and a kernel bug that is tracked in bug 506075
Comment 6 Joachim Backes 2009-08-26 01:50:16 EDT
(In reply to comment #5)
> Joachim, your issue is unrelated and a kernel bug that is tracked in bug 506075  

Thank you for clarification.
Comment 7 Florent Le Coz 2009-08-31 18:14:21 EDT
I confirm, I have the exact same pulseaudio -vvv output, and the problem is the same (crackling after one or two minutes of listening music or watching a movie)

I tried some downgrade :

# rpm -qa | grep pulse
pulseaudio-utils-0.9.15-14.fc11.x86_64
pulseaudio-libs-glib2-0.9.15-14.fc11.x86_64
pulseaudio-0.9.15-11.fc11.x86_64
xine-lib-pulseaudio-1.1.16.3-2.fc11.x86_64
alsa-plugins-pulseaudio-1.0.18-3.fc11.x86_64
pulseaudio-libs-0.9.15-14.fc11.x86_64

but I still experience this bug
Comment 8 Adam Williamson 2009-10-20 15:21:10 EDT
To get full PA logs, run the following in a console:

pulseaudio -k
pulseaudio -vvvv

then reproduce the problem. That kills the running PA and starts a new one running in the console with high verbosity, so you get all the output there.

Can we please have alsa-info.sh --no-upload output from each reporter, so we know what hardware is involved here? Thanks.

Please also confirm whether you are still seeing the issue with latest F11 kernel / pulseaudio (kernel went up to 2.6.30, so it's worth checking). For extra optional bonus credit, it'd be great if you could see if it happens with F12 Beta, so we know whether it happens with the newer kernel / PA / ALSA in that release. Thanks!

-- 
Fedora Bugzappers volunteer triage team
https://fedoraproject.org/wiki/BugZappers
Comment 9 Guy Streeter 2009-10-23 13:05:50 EDT
I am not able to reproduce this on current F11 software.
Comment 10 Lennart Poettering 2009-10-23 15:17:27 EDT
OK, closing then. If anyone manages to reproduce this, please reopen.

Note You need to log in before you can comment on or make changes to this bug.