[pulseaudio-discuss] crackle and stutter

Tue Apr 12 09:52:00 PDT 2011

On Tue, Apr 12, 2011 at 12:24 PM, Brian J. Murrell
<brian at interlinx.bc.ca> wrote:
> On 11-04-12 12:00 PM, Sean McNamara wrote:
>> Hi,
>
> Hi,
>
>> Can you give an example of what application(s) in particular trigger
>> this?
>
> Skype for example, when somebody sends an IM, or logs on.  Skype pops up
> a notification and emits a sound event.  Or when I generate a keyboard
> sound event, like hitting tab a bunch of times at a bash prompt.  It
> displays:
>
> Display all 5014 possibilities? (y or n)
>
> For example, and each tab emits a sound event.  If I hit tab a good
> number of times I can see this in PA:
>
> D: core-scache.c: Playing sample "bell-window-system" on
> "alsa_output.pci-0000_00_10.1.analog-stereo"
> D: memblockq.c: memblockq requested: maxlength=17640, tlength=0, base=2,
> prebuf=1, minreq=1 maxrewind=0
> D: memblockq.c: memblockq sanitized: maxlength=17640, tlength=17640,
> base=2, prebuf=2, minreq=2 maxrewind=0
> D: module-stream-restore.c: Not restoring device for stream
> sink-input-by-media-role:event, because already set to
> 'alsa_output.pci-0000_00_10.1.analog-stereo'.
> D: module-intended-roles.c: Not setting device for stream
> bell-window-system, because already set.
> I: module-stream-restore.c: Restoring volume for sink input
> sink-input-by-media-role:event.
> I: module-stream-restore.c: Restoring mute state for sink input
> sink-input-by-media-role:event.
> D: module-suspend-on-idle.c: Sink
> alsa_output.pci-0000_00_10.1.analog-stereo becomes busy.
> I: resampler.c: Forcing resampler 'copy', because of fixed, identical
> sample rates.
> D: resampler.c: Channel matrix:
> D: resampler.c:        I00
> D: resampler.c:     +------
> D: resampler.c: O00 | 1.000
> D: resampler.c: O01 | 1.000
> I: remap_sse.c: Using SSE mono to stereo remapping
> I: resampler.c: Using resampler 'copy'
> I: resampler.c: Using s16le as working format.
> D: memblockq.c: memblockq requested: maxlength=33554432, tlength=0,
> base=4, prebuf=0, minreq=1 maxrewind=0
> D: memblockq.c: memblockq sanitized: maxlength=33554432,
> tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
> I: sink-input.c: Created input 6004 "bell-window-system" on
> alsa_output.pci-0000_00_10.1.analog-stereo with sample spec s16le 1ch
> 44100Hz and channel map mono
> I: sink-input.c:     media.name = "bell-window-system"
> I: sink-input.c:     event.id = "bell-window-system"
> I: sink-input.c:     media.role = "event"
> I: sink-input.c:     application.process.id = "3904"
> I: sink-input.c:     application.name = "gnome-terminal"
> I: sink-input.c:     event.description = "Bell event"
> I: sink-input.c:     media.filename =
> "/usr/share//sounds/ubuntu/stereo/bell.ogg"
> I: sink-input.c:     native-protocol.peer = "UNIX socket client"
> I: sink-input.c:     native-protocol.version = "16"
> I: sink-input.c:     window.x11.display = ":0.0"
> I: sink-input.c:     window.x11.screen = "0"
> I: sink-input.c:     application.process.user = "brian"
> I: sink-input.c:     application.process.host = "pc"
> I: sink-input.c:     application.process.binary = "metacity"
> I: sink-input.c:     application.language = "en_CA.UTF-8"
> I: sink-input.c:     application.process.machine_id =
> "c5af5645621daea8981bd8ac95e82500"
> I: sink-input.c:     application.process.session_id =
> "c5af5645621daea8981bd8ac95e82500-1301933908.840922-406521422"
> I: sink-input.c:     window.x11.xid = "48333716"
> I: sink-input.c:     window.name = "pc:/etc/shorewall6/gw-new"
> I: sink-input.c:     module-stream-restore.id =
> "sink-input-by-media-role:event"
> D: core-util.c: posix_madvise() worked fine!
> D: alsa-sink.c: Requested to rewind 352768 bytes.
> D: alsa-sink.c: Limited to 21016 bytes.
> D: alsa-sink.c: before: 5254
> D: alsa-sink.c: after: 5254
> D: alsa-sink.c: Rewound 21016 bytes.
> D: sink.c: Processing rewind...
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: sink-input.c: Have to rewind 21016 bytes on render memblockq.
> D: source.c: Processing rewind...
> D: alsa-sink.c: Latency set to 136.00ms
> D: alsa-sink.c: hwbuf_unused=328780
> D: alsa-sink.c: setting avail_min=83952
> D: alsa-sink.c: Requested to rewind 352768 bytes.
> D: alsa-sink.c: Limited to 23660 bytes.
> D: alsa-sink.c: before: 5915
> D: alsa-sink.c: after: 5915
> D: alsa-sink.c: Rewound 23660 bytes.
> I: sink-input.c: Freeing input 5988 "bell-window-system"
> D: sink.c: Processing rewind...
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: sink-input.c: Have to rewind 23660 bytes on render memblockq.
> D: source.c: Processing rewind...
>
>> Is it reproducible 100% of the time, or just sometimes?
>
> When it starts happening, it's quite reproducible.  My recollection
> however is that it takes some time for the PA server to get into this state.
>
>> How is
>> your CPU load when this is occurring?
>
> Negligible.
>
>> Some amount of rewinds are normal. Especially when the server first
>> starts up, or when the amount of latency demanded by an application is
>> very low while system load is high.
>
> Well, this PA server has been up since April 5 and the only applications
> actively using it are rhythmbox and a few apps which want to send
> notifications, like skype and pidgin.  I don't think any of that should
> necessarily be "low latency" demanding applications.
>
>> But excessive rewinds can be due
>> to a driver bug in ALSA (this would have to be specific to your
>> hardware since I can't reproduce the issue here on Maverick). I like
>> to compare it to an anti-lock break system: if it engages at the right
>> time, it's useful, but if it engages erroneously it can be dangerous.
>
> I seem to get these rewinds with every single notification sound that
> Skype sends.
>
>> Also (back to addressing Brian), it's always useful to post the output
>> of running alsa-info.sh with problems like this:
>> http://git.alsa-project.org/?p=alsa-driver.git;a=blob_plain;f=utils/alsa-info.sh
>
> http://brian.interlinx.bc.ca/alsa-info.txt.wI2YqOw8Nv

I can't tell from your PA logs which soundcard you are using to play
back notifications and rhythmbox sound?

 0 [NVidia         ]: HDA-Intel - HDA NVidia
                      HDA NVidia at 0xfe024000 irq 22

or

 1 [U0x46d0x8c5    ]: USB-Audio - USB Device 0x46d:0x8c5
                      USB Device 0x46d:0x8c5 at usb-0000:00:0b.1-3, high speed

I remember there being quite some Nvidia HDA problems lately. And this
smells fishy to me, from dmesg:

[   14.160524] hda_intel: Disable MSI for Nvidia chipset
...
[691084.544026] hda_codec: invalid CONNECT_LIST verb 12[2]:2100
[691120.324230] hda_codec: invalid CONNECT_LIST verb 12[2]:2100
[691203.712806] hda_codec: invalid CONNECT_LIST verb 12[2]:2100
[691277.537037] hda_codec: invalid CONNECT_LIST verb 12[2]:2100

Hmm. Can you correlate "PulseAudio is dropping out" with one of these
messages? 691277 seconds after startup would be 8 days and some
minutes after kernel init, so it seems recent?

If indeed these debug messages correlate to your problem, we can track
it through the kernel by finding the relevant printks.

>
>> I can't speak to the Ubuntu SRU process, but it's quite possible that
>> a stable update fixing this issue for Maverick will never arrive
>> (especially if nobody gets to the bottom of the issue). Your
>> alternatives are to try Natty (it's stabilizing well in Beta 2-ish
>> now), another more recent distro, or stay where you are but compile
>> PulseAudio from git (stable-queue branch is a good choice). The
>> problem might already be fixed upstream.
>
> Yeah, or there is
> https://launchpad.net/~ubuntu-audio-dev/+archive/ppa/+packages but I
> wanted to see if the problem is known and actually fixed there before I
> do that.  As an aside, I have to say, I find it frustrating that with
> *every* *single* Ubuntu release I have to use that repo to get decent
> sound.  :-(
>
>> As a last-ditch workaround you might try disabling time-based
>> scheduling, but troubleshooting further first would be preferred :)
>> With a bit more work, a fix could be forthcoming, and then we could
>> resolve the issue for everyone who has your particular (or shall I
>> say, peculiar?) sound chipset.
>
> Yeah.  I definitely like to contribute if I can.  I wonder where, if
> anywhere, I can find David's work on this.
>
> Cheers, and thanx much for the input!
>
> b.
>
>