Bug 486068 - snd-intel8x0: signals POLLOUT when it shouldn't
Summary: snd-intel8x0: signals POLLOUT when it shouldn't
Keywords:
Status: CLOSED DUPLICATE of bug 472339
Alias: None
Product: Fedora
Classification: Fedora
Component: kernel
Version: rawhide
Hardware: x86_64
OS: Linux
low
urgent
Target Milestone: ---
Assignee: Kernel Maintainer List
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 478394 487225 (view as bug list)
Depends On:
Blocks: F11Target
TreeView+ depends on / blocked
 
Reported: 2009-02-18 04:29 UTC by John Ellson
Modified: 2009-08-23 16:38 UTC (History)
13 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2009-04-02 13:59:06 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
output from lspci (1.93 KB, text/plain)
2009-02-18 14:26 UTC, John Ellson
no flags Details
output from lsmod (3.14 KB, text/plain)
2009-02-18 14:27 UTC, John Ellson
no flags Details
output from dmesg (47.38 KB, text/plain)
2009-02-18 14:28 UTC, John Ellson
no flags Details
/var/log/messages after starting SecondLife (2.35 MB, text/plain)
2009-02-18 14:30 UTC, John Ellson
no flags Details
copy of /home/ellson/.xsession-errors (156.61 KB, text/plain)
2009-02-18 14:31 UTC, John Ellson
no flags Details
alsa, pulse, gstreamer, kernel rpms (4.24 KB, text/plain)
2009-02-18 14:32 UTC, John Ellson
no flags Details
diagram showing kernel module dependencies from active kernel (147.13 KB, image/png)
2009-02-21 19:10 UTC, John Ellson
no flags Details

Description John Ellson 2009-02-18 04:29:26 UTC
Description of problem:
Its crackly, its a resource hog, it fills up logs with crap, its useless!
I'm fed up with it!   This has been going on for months and it just gets worse!


Version-Release number of selected component (if applicable):
pulseaudio-0.9.15-0.test2.fc11.x86_64


How reproducible:
100% I wish it wasn't!!!

Steps to Reproduce:
1. start SecondLife, but don't even login!
2. tail -f /var/log/messages
3.
  
Actual results:
Feb 17 23:19:31 ontap pulseaudio[31470]: ratelimit.c: 245 events suppressed
Feb 17 23:19:37 ontap pulseaudio[31470]: ratelimit.c: 98 events suppressed
Feb 17 23:19:42 ontap pulseaudio[31470]: ratelimit.c: 126 events suppressed
Feb 17 23:19:47 ontap pulseaudio[31470]: ratelimit.c: 44 events suppressed
Feb 17 23:19:47 ontap pulseaudio[31470]: alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write! Most likely this is an ALSA driver bug. Please report this issue to the ALSA developers. We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail_update() returned 0.
Feb 17 23:19:52 ontap pulseaudio[31470]: ratelimit.c: 73 events suppressed
Feb 17 23:19:57 ontap pulseaudio[31470]: ratelimit.c: 40 events suppressed
Feb 17 23:20:02 ontap pulseaudio[31470]: ratelimit.c: 61 events suppressed
Feb 17 23:20:07 ontap pulseaudio[31470]: ratelimit.c: 235 events suppressed
Feb 17 23:20:14 ontap pulseaudio[31470]: ratelimit.c: 62 events suppressed
Feb 17 23:20:19 ontap pulseaudio[31470]: ratelimit.c: 91 events suppressed
Feb 17 23:20:24 ontap pulseaudio[31470]: ratelimit.c: 110 events suppressed
Feb 17 23:20:29 ontap pulseaudio[31470]: ratelimit.c: 137 events suppressed
Feb 17 23:20:34 ontap pulseaudio[31470]: ratelimit.c: 519 events suppressed
Feb 17 23:20:39 ontap pulseaudio[31470]: ratelimit.c: 132 events suppressed
Feb 17 23:20:44 ontap pulseaudio[31470]: ratelimit.c: 55 events suppressed
Feb 17 23:20:49 ontap pulseaudio[31470]: ratelimit.c: 34 events suppressed
Feb 17 23:20:54 ontap pulseaudio[31470]: ratelimit.c: 48 events suppressed
Feb 17 23:20:59 ontap pulseaudio[31470]: ratelimit.c: 96 events suppressed
Feb 17 23:21:04 ontap pulseaudio[31470]: ratelimit.c: 18 events suppressed
Feb 17 23:21:09 ontap pulseaudio[31470]: ratelimit.c: 244 events suppressed
Feb 17 23:21:15 ontap pulseaudio[31470]: ratelimit.c: 476 events suppressed
Feb 17 23:21:20 ontap pulseaudio[31470]: ratelimit.c: 54 events suppressed
Feb 17 23:21:25 ontap pulseaudio[31470]: ratelimit.c: 198 events suppressed
Feb 17 23:21:30 ontap pulseaudio[31470]: ratelimit.c: 137 events suppressed
Feb 17 23:21:35 ontap pulseaudio[31470]: ratelimit.c: 48 events suppressed
Feb 17 23:21:40 ontap pulseaudio[31470]: ratelimit.c: 19 events suppressed
Feb 17 23:21:45 ontap pulseaudio[31470]: ratelimit.c: 37 events suppressed
Feb 17 23:21:50 ontap pulseaudio[31470]: ratelimit.c: 32 events suppressed
Feb 17 23:21:55 ontap pulseaudio[31470]: ratelimit.c: 197 events suppressed
Feb 17 23:22:00 ontap pulseaudio[31470]: ratelimit.c: 52 events suppressed
Feb 17 23:22:06 ontap pulseaudio[31470]: ratelimit.c: 30 events suppressed
Feb 17 23:22:11 ontap pulseaudio[31470]: ratelimit.c: 86 events suppressed
Feb 17 23:22:16 ontap pulseaudio[31470]: ratelimit.c: 35 events suppressed
Feb 17 23:22:21 ontap pulseaudio[31470]: ratelimit.c: 100 events suppressed
Feb 17 23:22:26 ontap pulseaudio[31470]: ratelimit.c: 74 events suppressed
Feb 17 23:22:26 ontap pulseaudio[31470]: alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write! Most likely this is an ALSA driver bug. Please report this issue to the ALSA developers. We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail_update() returned 0.
Feb 17 23:22:31 ontap pulseaudio[31470]: ratelimit.c: 73 events suppressed
Feb 17 23:22:36 ontap pulseaudio[31470]: ratelimit.c: 39 events suppressed
Feb 17 23:22:36 ontap pulseaudio[31470]: alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write! Most likely this is an ALSA driver bug. Please report this issue to the ALSA developers. We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail_update() returned 0.
Feb 17 23:22:41 ontap pulseaudio[31470]: ratelimit.c: 125 events suppressed
Feb 17 23:22:47 ontap pulseaudio[31470]: ratelimit.c: 113 events suppressed
Feb 17 23:22:52 ontap pulseaudio[31470]: ratelimit.c: 177 events suppressed
Feb 17 23:22:58 ontap pulseaudio[31470]: ratelimit.c: 40 events suppressed
Feb 17 23:23:03 ontap pulseaudio[31470]: ratelimit.c: 89 events suppressed
Feb 17 23:23:08 ontap pulseaudio[31470]: ratelimit.c: 182 events suppressed
Feb 17 23:23:08 ontap pulseaudio[31470]: alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write! Most likely this is an ALSA driver bug. Please report this issue to the ALSA developers. We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail_update() returned 0.
Feb 17 23:23:08 ontap pulseaudio[31470]: alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write! Most likely this is an ALSA driver bug. Please report this issue to the ALSA developers. We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail_update() returned 0.
Feb 17 23:23:08 ontap pulseaudio[31470]: alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write! Most likely this is an ALSA driver bug. Please report this issue to the ALSA developers. We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail_update() returned 0.
Feb 17 23:23:13 ontap pulseaudio[31470]: ratelimit.c: 407 events suppressed
Feb 17 23:23:19 ontap pulseaudio[31470]: ratelimit.c: 160 events suppressed


Expected results:
Clean sound!
No log file noise!
Implementer testing this crap before dropping it on the rest of us!

Additional info:

Comment 1 Matthias Clasen 2009-02-18 07:48:35 UTC
Please tell us what alsa driver is causing this problem

Comment 2 John Ellson 2009-02-18 14:26:05 UTC
Its too complicated, I don't know what "driver" means in all this stuff.   I'll attach lspci, lsmod, dmesg, /var/log/messages, .xsession-errors, and a list of possibly-related rpms that I have installed.

These were captured after a yum update, a reboot (and rebuild of the NVidia proprietary graphics driver), login, and open SecondLife (without logging into SecondLife).


Sound was fine in this setup until recently, perhaps two weeks, max.

Comment 3 John Ellson 2009-02-18 14:26:52 UTC
Created attachment 332377 [details]
output from lspci

Comment 4 John Ellson 2009-02-18 14:27:30 UTC
Created attachment 332378 [details]
output from lsmod

Comment 5 John Ellson 2009-02-18 14:28:05 UTC
Created attachment 332379 [details]
output from dmesg

Comment 6 John Ellson 2009-02-18 14:30:41 UTC
Created attachment 332380 [details]
/var/log/messages after starting SecondLife

Comment 7 John Ellson 2009-02-18 14:31:31 UTC
Created attachment 332381 [details]
copy of /home/ellson/.xsession-errors

Comment 8 John Ellson 2009-02-18 14:32:44 UTC
Created attachment 332382 [details]
alsa, pulse, gstreamer, kernel rpms

Comment 9 antonio montagnani 2009-02-18 14:44:49 UTC
welcome on the band with intel sound modules. I think that you should also join:

471804  	Fedora  	pulseaudio  	NEW  	medium  	snd-intel8x0: Pulseaudio is dying and suffers from rare interruptions

446192  	Fedora  	kernel  	ASSIGNED  	low  	horrible skipping audio

462026  	Fedora  	alsa-lib  	NEW  	high  	music file play -> sound sparks.

462200  	Fedora  	pulseaudio  	ASSIGNED  	high  	Various issues causing PA to be killed by the CPU load limiter (was: snd_pcm_mmap_playback_avail returns immens values which cause PA to fail due to CPU overload)


and see your bug is a duplicate of any of them... :-)

Comment 10 John Ellson 2009-02-18 16:54:44 UTC
Re: Bug #471804  - seems to have been resolved Dec/08.  I think my sound worked then too.

----

Re: Bug #446192  - reports issues on fc9.

The also-info.sh script from the linked Bug #441087 might provide useful info.  My output is at:
   http://www.alsa-project.org/db/?f=1779e2137c625d20a275210780e7cc5f973300c8
I note that my pulseaudio server is not even running! 

Reports alsa driver version as: 1.0.18a

Suggests setting clock rates from modprobe.conf ... I'll try that this evening when I get home, although 441087 has been closed as fixed in kernel-2.6.27.12-170.2.5.fc10.i686 and I have kernel-2.6.29-0.124.rc5.fc11.x86_64

-----

Re: Bug #462200  - reports issues on fc10, but I'm only seeing them on a Rawhide box.  I have a similar, but not identical, fc10 x86_64 box thats playing sound ok.


----

Specifically, I don't see any other reports that seem to implicate ratelimit.c.  I believe this was a very recent addition?

Comment 11 John Ellson 2009-02-18 16:59:39 UTC
I missed Bug #462026

I see some of the sysmptoms of the later comments in that report, such as:

 Jan 24 08:44:18 localhost pulseaudio[3021]: module-alsa-sink.c: ALSA woke us up
to write new data to the device, but there was actually nothing to write! Most
likely this is an ALSA driver bug. Please report this issue to the PulseAudio
developers.


but not the symptoms reported in the original description.

Comment 12 antonio montagnani 2009-02-19 18:03:14 UTC
I installed a kernel-PAE-2.6.29.131, situation has improved but not still perfect, I have some "uncertainty" in music stream in radio .

Running a 686 kernel.

I agree with you that some bug in alsa driver for hda-intel systems must be present.

Comment 13 François Cami 2009-02-21 14:33:43 UTC
John,

Do any of the solutions outlined in the following document help ?
http://fedorasolved.org/Members/fenris02/pulseaudio-fixes-and-workarounds/
Please report what worked, and what did not, for you.

---
Fedora Bugzappers volunteer triage team
https://fedoraproject.org/wiki/BugZappers

Comment 14 John Ellson 2009-02-21 15:08:51 UTC
Re: Workaround document from Comment #13

Applicability:
  The notes are for Fedora 10, but my system is Rawhide, x86_64.  Trying anyway.

Requirements:
  Don't have a "gnome-sound-properties"  Perhaps this is now from Volume control applet -> preferences?   NVidia CK804 selected.   Unmuted.

Doing the work:
  1. "pulseaudio-module-jack alsa-plugins-jack jack-audio-connection-kit" already installed.

  2.  ***Do What???***   Is a regular user really expected to do 'su -c "usermod -aG pulse-rt,jackuser username"' before they can listen to sound? 

I was already in the "pulse-rt" group, but not in the "jackuser" group.  Added.

Now I need to logout and log back in ... to be continued

Comment 15 John Ellson 2009-02-21 15:41:58 UTC
Before logging out and rebooting I turned on PulseAudio from:
   System->Preferences->StartupApplicatons->PulseaudioSoundSystem
(Am I confused, or was this in System->preferences->Sessions until recently?)

-----------------
Playing NPR on RhythmBox sounds ok, although /var/messages shows:

    Feb 21 10:21:05 ontap pulseaudio[11070]: alsa-source.c: Increasing wakeup watermark to 34.00 ms
    Feb 21 10:23:31 ontap pulseaudio[11070]: alsa-sink.c: Increasing wakeup watermark to 73.50 ms
    Feb 21 10:23:41 ontap pulseaudio[11070]: ratelimit.c: 1 events suppressed
    Feb 21 10:23:44 ontap pulseaudio[11070]: alsa-source.c: Increasing wakeup watermark to 34.00 ms

Doesn't seem to repeat.

------------------------------

Opening SecondLife, without even logging in, shows the original problem is still present:

Feb 21 10:27:29 ontap pulseaudio[11070]: ratelimit.c: 160 events suppressed
Feb 21 10:27:34 ontap pulseaudio[11070]: ratelimit.c: 333 events suppressed
Feb 21 10:27:39 ontap pulseaudio[11070]: ratelimit.c: 5 events suppressed
Feb 21 10:27:54 ontap pulseaudio[11070]: ratelimit.c: 39 events suppressed
Feb 21 10:27:54 ontap pulseaudio[11070]: alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write! Most likely this is an ALSA driver bug. Please report this issue to the ALSA developers. We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail_update() returned 0.
Feb 21 10:27:54 ontap pulseaudio[11070]: alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write! Most likely this is an ALSA driver bug. Please report this issue to the ALSA developers. We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail_update() returned 0.


-----------------------------

Continuing with Work 2.

1. Did: "nano -w /etc/pulse/default.pa" and added "tched=0 as suggested.

2. Did 2.  All were already installed, but there was a new update to padevchooser.

3. No more: "System > Preferences > Hardware"

Trying: "System -> Preferences -> Sound -> Output"   
   ** "PulseAudio" is not listed as an available output device.

Re logging .....    to be continued

Comment 16 John Ellson 2009-02-21 15:55:20 UTC
Just relogged, not rebooted this time.

Ran "alsa-info.sh --no-upload".  It claims that PulsAudio is running, but not aRts or Jack.

SoundPreferences->Output still doesn't list "PulseAudio" as an output device.

Same problem with SecondLife.

------------

How to test:

   1.  $ id ellson
       uid=515(ellson) gid=524(ellson) groups=524(ellson),334(jackuser),494(pulse),493(pulse-rt),492(pulse-access)

   2.  $ pulseaudio -k
       I: caps.c: Limited capabilities successfully to CAP_SYS_NICE.
       I: caps.c: Dropping root privileges.
       I: caps.c: Limited capabilities successfully to CAP_SYS_NICE.

*****   /var/log/messages contains:

      Feb 21 10:49:09 ontap pulseaudio[13097]: core.h: Assertion 'pa_object_refcnt(pa_object_cast(o)) > 0' failed at ./pulsecore/core.h:158, function pa_core_assert_ref(). Aborting.

******

Attempting to repeat 2. produces:

       I: caps.c: Limited capabilities successfully to CAP_SYS_NICE.
       I: caps.c: Dropping root privileges.
       I: caps.c: Limited capabilities successfully to CAP_SYS_NICE.
       E: main.c: Failed to kill daemon: No such file or directory


Should I try to continue?

Comment 17 François Cami 2009-02-21 16:13:53 UTC
I'm especially interested in the "tched=0".
Does it fix the sound crackling ?

Comment 18 John Ellson 2009-02-21 16:34:11 UTC
I don't think intel hardware is implicated in my case.  My hardware is NVidia CK804, and "lsmod | grep snd_hda_intel" returns no match.

-----------------

I did:  rpm -e --allmatches alsa-plugins-pulseaudio  fluxbox-pulseaudio-1.1.1-1.fc10.x86_64 kde-settings-pulseaudio-4.2-3.20090218svn.fc11.noarch

I still get pulseaudio errors from SecondLife!

SecondLife log shows:

2009-02-21T16:29:23Z INFO: startInternetStream: Playing.....
*** Unable to locate valid config! Falling back to auto-detection...
*** Unable to locate PAC! Falling back to direct...
bus_callback:343: GST warning: Internal GStreamer error: clock problem.  Please file a bug at http://bugzilla.gnome.org/enter_bug.cgi?product=GStreamer.


/var/log/messages shows multiple:

Feb 21 11:29:50 ontap pulseaudio[15715]: alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write! Most likely this is an ALSA driver bug. Please report this issue to the ALSA developers. We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail_update() returned 0.


---------------

Re: Comment #17.

I'll let you know as soon as I can get any sound from SecondLife....

.... I seem to be regressing :-(

Comment 19 John Ellson 2009-02-21 17:13:17 UTC
Now getting no sounds from Rhythmbox, and only ambient and UI sounds from SecondLife, no music streams.  And even thse sounds die completely after 30sec or so, then restart for a while 30 sec later, then died again... no more restarts!

Reinstalled: alsa-plugins-pulseaudio.i386 alsa-plugins-pulseaudio.x86_64 fluxbox-pulseaudio-1.1.1-1.fc10.x86_64 kde-settings-pulseaudio-4.2-3.20090218svn.fc11.noarch

Still no sound from RhythmBox (except for three or so loud s=clicks at startup).

Rebooting...

Comment 20 John Ellson 2009-02-21 18:41:00 UTC
There is some sort of persistent state in $HOME/.pulse* that makes it hard to repeat tests consistently.

By removing these I was able to make these tests reproducable:

1.   without tched=0

      $ killall pulseaudio
      $ rm -rf .pulse*
      $ pulseaudio &

5 loud clicks as pulseaudio starts 

      I: caps.c: Dropping root privileges.
      I: caps.c: Limited capabilities successfully to CAP_SYS_NICE.
      N: alsa-sink.c: Increasing wakeup watermark to 36.75 ms

Rythmbox plays NPR stream without crackling.

Staring SecondLife, but no login, starts these messages:

    N: alsa-sink.c: Increasing wakeup watermark to 73.50 ms
    W: ratelimit.c: 231 events suppressed
    E: alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write! Most likely this is an ALSA driver bug. Please report this issue to the ALSA developers. We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail_update() returned 0.
    W: ratelimit.c: 50 events suppressed
    W: ratelimit.c: 245 events suppressed
    W: ratelimit.c: 6 events suppressed
    W: ratelimit.c: 25 events suppressed
    W: ratelimit.c: 49 events suppressed
    W: ratelimit.c: 10 events suppressed
    W: ratelimit.c: 30 events suppressed
    W: ratelimit.c: 28 events suppressed

and so on.

Secondlife plays music, but with crackling sounds.



2. with tched=0   (btw, this is now on line 53, not 48)

      $ killall pulseaudio
      $ rm -rf .pulse*
      $ pulseaudio &


5 loud clicks on startup.

Rythmbox sounds ok, but now producing messages like:

    W: ratelimit.c: 140 events suppressed
    E: alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write! Most likely this is an ALSA driver bug. Please report this issue to the ALSA developers. We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail_update() returned 0.


SecondLife:  

    Similar error messages.   Music is OK apart from an interruption or hesitation ever 30sec or so.    UI and ambient sounds still noisy and crackly.


So, I think tsched=0 changes something, but it doesn't fix the problems.

Comment 21 John Ellson 2009-02-21 19:08:52 UTC
Question:  Is there some kind of diagram someplace showing what connects to who?

Better yet, are there introspection tools that would extract this, so that I might be able to create a connection diagram with graphviz tools?   (Seeing as I'm a graphviz contributor.)   I can already do this for the sound modules (see attachment)

Comment 22 John Ellson 2009-02-21 19:10:04 UTC
Created attachment 332827 [details]
diagram showing kernel module dependencies from active kernel

Comment 23 Lennart Poettering 2009-02-25 02:49:23 UTC
This is a kernel driver issue. intel8x0 is broken on NVidia cards. (And actually not just there)

Reassigning to kernel.

Comment 24 Lennart Poettering 2009-03-03 01:25:09 UTC
*** Bug 487225 has been marked as a duplicate of this bug. ***

Comment 25 Lennart Poettering 2009-03-03 01:26:18 UTC
I took the liberty to make this block F10Blocker since this causes PA to burn a lot more CPU than necessary.

Comment 26 Lennart Poettering 2009-03-03 01:26:57 UTC
Sorry, F11Blocker of course.

Comment 27 Lennart Poettering 2009-03-03 01:33:55 UTC
*** Bug 478394 has been marked as a duplicate of this bug. ***

Comment 28 John Ellson 2009-03-10 20:58:24 UTC
Re: Comment #25

Although pulseaudio also consumes excessive CPU on F10, so it really should be a "blocker" there too, if it wasn't too late!

My workaround was to completely remove pulseaudio on F10.  Sound still worked. CPU usage dropped.

Not so easy to do on Rawhide.

Comment 29 Lennart Poettering 2009-04-02 13:59:06 UTC

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


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