[pulseaudio-discuss] PulseAudio unstable on Ubuntu Karmic 9.10

[Alexandre Savard]

We are developing a VOIP phone.

I upgraded my ubuntu 9.10 Karmic last thursday. Since, I can't get any
audio playback from pulseaudio or very crappy one. There is several
playback buffer underrun occuring. The Alsa plug-in still work well.
Before that upgrade, everything was working just fine. I have pulseaudio
and my application running on a Jaunty 9.10 and there is no problems.

Looking at the Latency Control
(http://pulseaudio.org/wiki/LatencyControl?version=17):

I first make sure that PA runs timer scheduling mode (tsched=1) for ALSA
devices.
Is this parameter is the /etc/pulse/daemon.conf "realtime-scheduling =
yes"

Uncommenting 
realtime-scheduling = yes
realtime-priority = 5
had no effect.

Using these pstream attributes provide me these debug messages in
pulseaudio:

attributes->maxlength = (uint32_t) -1;
attributes->tlength = 4096;
attributes->prebuf = (uint32_t) -1;      
attributes->minreq = (uint32_t) -1;
attributes->fragsize = (uint32_t) -1;

pa_stream_connect_playback( s , NULL , attributes,
PA_STREAM_ADJUST_LATENCY, &_volume, NULL)


I: sink-input.c:     media.name = "SFLphone out"
I: sink-input.c:     application.name = "SFLphone"
I: sink-input.c:     native-protocol.peer = "UNIX socket client"
I: sink-input.c:     native-protocol.version = "16"
I: sink-input.c:     media.role = "phone"
I: sink-input.c:     application.process.id = "10476"
I: sink-input.c:     application.process.user = "alexandresavard"
I: sink-input.c:     application.process.host =
"alexandresavard-desktop"
I: sink-input.c:     application.process.binary = "lt-sflphoned"
I: sink-input.c:     application.language = "C"
I: sink-input.c:     window.x11.display = ":0.0"
I: sink-input.c:     application.process.machine_id =
"760a77c32e810552e0ee9e6a4967c274"
I: sink-input.c:     application.process.session_id =
"760a77c32e810552e0ee9e6a4967c274-1256332458.764918-577634043"
I: sink-input.c:     module-stream-restore.id =
"sink-input-by-media-role:phone"
I: protocol-native.c: Requested tlength=46.44 ms, minreq=20.00 ms
D: protocol-native.c: Adjust latency mode enabled, configuring sink
latency to half of overall latency.
D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
D: memblockq.c: memblockq requested: maxlength=4194304, tlength=4940,
base=2, prebuf=3178, minreq=1764 maxrewind=0
D: memblockq.c: memblockq sanitized: maxlength=4194304, tlength=4940,
base=2, prebuf=3178, minreq=1764 maxrewind=0
I: protocol-native.c: Final latency 72.01 ms = 16.01 ms + 2*20.00 ms +
16.00 ms
D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
D: alsa-sink.c: Latency set to 16.00ms
D: alsa-sink.c: hwbuf_unused=62716
D: alsa-sink.c: setting avail_min=16033
D: alsa-sink.c: Requesting rewind due to latency change.
D: alsa-sink.c: Requested to rewind 65536 bytes.
D: alsa-sink.c: Limited to 63808 bytes.
D: alsa-sink.c: before: 15952
D: alsa-sink.c: after: 15952
D: alsa-sink.c: Rewound 63808 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 63808 bytes on render memblockq.
D: source.c: Processing rewind...
D: core-subscribe.c: Dropped redundant event due to change event.
D: reserve-wrap.c: Device lock status of reserve-monitor-wrapper at Audio0
changed: not busy
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Requested to rewind 65536 bytes.
D: alsa-sink.c: Limited to 1220 bytes.
D: alsa-sink.c: before: 305
D: alsa-sink.c: after: 305
D: alsa-sink.c: Rewound 1220 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 1220 bytes on render memblockq.
D: source.c: Processing rewind...
D: protocol-native.c: Underrun on 'SFLphone out', 0 bytes in queue.
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Requested to rewind 196 bytes.
D: alsa-sink.c: Limited to 196 bytes.
D: alsa-sink.c: before: 49
D: alsa-sink.c: after: 49
D: alsa-sink.c: Rewound 196 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 196 bytes on render memblockq.
D: source.c: Processing rewind...
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Requested to rewind 196 bytes.
D: alsa-sink.c: Limited to 196 bytes.
D: alsa-sink.c: before: 49
D: alsa-sink.c: after: 49
D: alsa-sink.c: Rewound 196 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 196 bytes on render memblockq.
D: source.c: Processing rewind...
D: protocol-native.c: Underrun on 'SFLphone out', 0 bytes in queue.
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Requested to rewind 328 bytes.
D: alsa-sink.c: Limited to 328 bytes.
D: alsa-sink.c: before: 82
D: alsa-sink.c: after: 82
D: alsa-sink.c: Rewound 328 bytes.
D: sink.c: Processing rewind...
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Requested to rewind 328 bytes.
D: alsa-sink.c: Limited to 328 bytes.
D: alsa-sink.c: before: 82
D: alsa-sink.c: after: 82
D: alsa-sink.c: Rewound 328 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 328 bytes on render memblockq.
D: source.c: Processing rewind...
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Requested to rewind 328 bytes.
D: alsa-sink.c: Limited to 328 bytes.
D: alsa-sink.c: before: 82
D: alsa-sink.c: after: 82
D: alsa-sink.c: Rewound 328 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 328 bytes on render memblockq.
D: source.c: Processing rewind...
D: protocol-native.c: Underrun on 'SFLphone out', 0 bytes in queue.
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Requested to rewind 80 bytes.
D: alsa-sink.c: Limited to 80 bytes.
D: alsa-sink.c: before: 20
D: alsa-sink.c: after: 20
D: alsa-sink.c: Rewound 80 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 80 bytes on render memblockq.
D: source.c: Processing rewind...
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Requested to rewind 80 bytes.
D: alsa-sink.c: Limited to 80 bytes.
D: alsa-sink.c: before: 20
D: alsa-sink.c: after: 20
D: alsa-sink.c: Rewound 80 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 80 bytes on render memblockq.
D: source.c: Processing rewind...
D: protocol-native.c: Underrun on 'SFLphone out', 0 bytes in queue.



Then I chaged parameters to:


attributes->maxlength = 88200;
attributes->tlength = 4096;
attributes->prebuf = 4096;      
attributes->minreq = 2048;
attributes->fragsize = 4096;

pa_stream_connect_playback( s , NULL , attributes,
PA_STREAM_ADJUST_LATENCY, &_volume, NULL)

I: sink-input.c:     media.name = "SFLphone out"
I: sink-input.c:     application.name = "SFLphone"
I: sink-input.c:     native-protocol.peer = "UNIX socket client"
I: sink-input.c:     native-protocol.version = "16"
I: sink-input.c:     media.role = "phone"
I: sink-input.c:     application.process.id = "8208"
I: sink-input.c:     application.process.user = "alexandresavard"
I: sink-input.c:     application.process.host =
"alexandresavard-desktop"
I: sink-input.c:     application.process.binary = "lt-sflphoned"
I: sink-input.c:     application.language = "C"
I: sink-input.c:     window.x11.display = ":0.0"
I: sink-input.c:     application.process.machine_id =
"760a77c32e810552e0ee9e6a4967c274"
I: sink-input.c:     application.process.session_id =
"760a77c32e810552e0ee9e6a4967c274-1256332458.764918-577634043"
I: sink-input.c:     module-stream-restore.id =
"sink-input-by-media-role:phone"
I: protocol-native.c: Requested tlength=46.44 ms, minreq=23.22 ms
D: protocol-native.c: Adjust latency mode enabled, configuring sink
latency to half of overall latency.
D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
D: memblockq.c: memblockq requested: maxlength=88200, tlength=4140,
base=2, prebuf=2094, minreq=2048 maxrewind=0
D: memblockq.c: memblockq sanitized: maxlength=88200, tlength=4140,
base=2, prebuf=2094, minreq=2048 maxrewind=0
I: protocol-native.c: Final latency 47.44 ms = 0.50 ms + 2*23.22 ms +
0.50 ms
D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
D: alsa-sink.c: Latency set to 0.50ms
D: alsa-sink.c: hwbuf_unused=65448
D: alsa-sink.c: setting avail_min=16374
D: alsa-sink.c: Requesting rewind due to latency change.
D: alsa-sink.c: Requested to rewind 65536 bytes.
D: alsa-sink.c: Limited to 65172 bytes.
D: alsa-sink.c: before: 16293
D: alsa-sink.c: after: 16293
D: alsa-sink.c: Rewound 65172 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 65172 bytes on render memblockq.
D: source.c: Processing rewind...
D: core-subscribe.c: Dropped redundant event due to change event.
D: reserve-wrap.c: Device lock status of reserve-monitor-wrapper at Audio0
changed: not busy
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Requested to rewind 65536 bytes.
D: alsa-sink.c: Limited to 44 bytes.
D: alsa-sink.c: before: 11
D: alsa-sink.c: after: 11
D: alsa-sink.c: Rewound 44 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 44 bytes on render memblockq.
D: source.c: Processing rewind...
I: alsa-sink.c: Underrun!
I: alsa-sink.c: Increasing minimal latency to 1.00 ms
D: alsa-sink.c: Latency set to 1.00ms
D: alsa-sink.c: hwbuf_unused=65360
D: alsa-sink.c: setting avail_min=16363
D: protocol-native.c: max_request changed, trying to update from 4140 to
4184.
D: protocol-native.c: Notifying client about increased tlength
D: alsa-sink.c: Latency set to 1.00ms
D: alsa-sink.c: hwbuf_unused=65360
D: alsa-sink.c: setting avail_min=16363
I: alsa-sink.c: Underrun!
I: alsa-sink.c: Increasing minimal latency to 2.00 ms
D: alsa-sink.c: Latency set to 2.00ms
D: alsa-sink.c: hwbuf_unused=65184
D: alsa-sink.c: setting avail_min=16341
D: protocol-native.c: max_request changed, trying to update from 4184 to
4272.
D: protocol-native.c: Notifying client about increased tlength
D: alsa-sink.c: Latency set to 2.00ms
D: alsa-sink.c: hwbuf_unused=65184
D: alsa-sink.c: setting avail_min=16341
I: alsa-sink.c: Underrun!
I: alsa-sink.c: Increasing minimal latency to 4.00 ms
D: alsa-sink.c: Latency set to 4.00ms
D: alsa-sink.c: hwbuf_unused=64832
D: alsa-sink.c: setting avail_min=16297
D: protocol-native.c: max_request changed, trying to update from 4272 to
4448.