[pulseaudio-discuss] Gap, silence and latency

[James Lee]

Hi,

I am working on a small project to integrate pulse into our current ALSA system 
to mix, re-sample and route audio.  I have a video player on the client side 
that takes multicast streams and plays them on "channels."  Each channel 
consists of one movie and a streamer on the server side streams the movie over 
and over again (so the player plays it over and over again).

I have one issue that I just cannot figure out and decided to ask for help 
here. I believe this is an issue that is pulse related because without pulse I 
do not see this.  There is a gap between when the movie ends and when it starts  
playing again.  It is about 2-3 second gap during which nothing is being 
streamed on the channel.  And every time this is encountered I see the 
following and audio gets out-of-sync (delayed) when the movie starts up again:

D: [alsa-sink] ratelimit.c: 329 events suppressed
D: [alsa-sink] alsa-sink.c: Wakeup from ALSA!
I: [alsa-sink] alsa-sink.c: Underrun!
I: [alsa-sink] alsa-sink.c: Increasing minimal latency to 26.00 ms
D: [alsa-sink] alsa-sink.c: Latency set to 26.00ms
D: [alsa-sink] alsa-sink.c: hwbuf_unused=126488
D: [alsa-sink] alsa-sink.c: setting avail_min=32416
D: [alsa-sink] alsa-sink.c: Latency set to 26.00ms
D: [alsa-sink] alsa-sink.c: hwbuf_unused=126488
D: [alsa-sink] alsa-sink.c: setting avail_min=32416
D: [alsa-sink] protocol-native.c: Underrun on 'ALSA Playback', 0 bytes in 
queue.
D: [alsa-sink] alsa-sink.c: Wakeup from ALSA!
I: [alsa-sink] alsa-sink.c: Underrun!
I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 15.99 ms
D: [alsa-sink] alsa-sink.c: Wakeup from ALSA!
D: [alsa-sink] alsa-sink.c: Wakeup from ALSA!
D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun.
D: [alsa-sink] alsa-sink.c: Requested to rewind 29204 bytes.
D: [alsa-sink] alsa-sink.c: Limited to 4328 bytes.
D: [alsa-sink] alsa-sink.c: before2: 1082
D: [alsa-sink] alsa-sink.c: after: 1082
D: [alsa-sink] alsa-sink.c: Rewound 4328 bytes.
D: [alsa-sink] sink.c: Processing rewind...
D: [alsa-sink] sink-input.c: Have to rewind 4328 bytes on render memblockq.
D: [alsa-sink] sink-input.c: Have to rewind 4328 bytes on render memblockq.
D: [alsa-sink] source.c: Processing rewind...

What is the expected behavior here?  Does pulse try to write silence when it 
runs into a complete underrun (0 bytes in queue)?  Even then, why would there 
be a delay in audio?  It almost looks like pulse is writing too much or at 
least more than it should during this gap?

Any help will be appreciated.  The below is info that you might find helpful.  
Thanks in advance!

I: [pulseaudio] main.c: Fresh high-resolution timers available! Bon appetit!
D: [pulseaudio] memblock.c: Using private memory pool with 1024 slots of size
64.0 KiB each, total size is 64.0 MiB, maximum usable slot size is 65496
I: [pulseaudio] cpu-arm.c: CPU flags: V6 V7 VFP EDSP NEON VFPV3 
D: [pulseaudio] cli-command.c: Checking for existence of
'/pulse/usr/local/lib/pulse-1.1/modules/module-detect.so': success
D: [pulseaudio] alsa-util.c: Trying hw:0,0 with SND_PCM_NO_AUTO_FORMAT ...
D: [pulseaudio] alsa-util.c: Managed to open hw:0,0
I: [pulseaudio] alsa-util.c: cannot disable ALSA period wakeups
D: [pulseaudio] alsa-util.c: Maximum hw buffer size is 743 ms
D: [pulseaudio] alsa-util.c: Set buffer size first (to 88200 samples), period
size second (to 88200 samples).
I: [pulseaudio] alsa-util.c: ALSA period wakeups were not disabled
I: [pulseaudio] alsa-sink.c: Successfully opened device hw:0,0.
I: [pulseaudio] alsa-sink.c: Successfully enabled mmap() mode.
I: [pulseaudio] alsa-sink.c: Successfully enabled timer-based scheduling mode.
I: [pulseaudio] sink.c: Created sink 0 "omap3smlca" with sample spec s16le 2ch
44100Hz and channel map front-left,front-right
I: [pulseaudio] sink.c:     alsa.resolution_bits = "16"
I: [pulseaudio] sink.c:     device.api = "alsa"
I: [pulseaudio] sink.c:     device.class = "sound"
I: [pulseaudio] sink.c:     alsa.class = "generic"
I: [pulseaudio] sink.c:     alsa.subclass = "generic-mix"
I: [pulseaudio] sink.c:     alsa.name = ""
I: [pulseaudio] sink.c:     alsa.id = "AIC3X tlv320aic34a-0"
I: [pulseaudio] sink.c:     alsa.subdevice = "0"
I: [pulseaudio] sink.c:     alsa.subdevice_name = "subdevice #0"
I: [pulseaudio] sink.c:     alsa.device = "0"
I: [pulseaudio] sink.c:     alsa.card = "0"
I: [pulseaudio] sink.c:     alsa.card_name = "omap3smlc_a"
I: [pulseaudio] sink.c:     alsa.long_card_name = "omap3smlc_a (tlv320aic34a)"
I: [pulseaudio] sink.c:     device.string = "hw:0,0"
I: [pulseaudio] sink.c:     device.buffering.buffer_size = "131072"
I: [pulseaudio] sink.c:     device.buffering.fragment_size = "2048"
I: [pulseaudio] sink.c:     device.access_mode = "mmap+timer"
I: [pulseaudio] sink.c:     device.description = "omap3smlc_a"
I: [pulseaudio] sink.c:     device.icon_name = "audio-card"
I: [pulseaudio] source.c: Created source 0 "omap3smlca.monitor" with sample
spec s16le 2ch 44100Hz and channel map front-left,front-right
I: [pulseaudio] source.c:     device.description = "Monitor of omap3smlc_a"
I: [pulseaudio] source.c:     device.class = "monitor"
I: [pulseaudio] source.c:     device.icon_name = "audio-input-microphone"
I: [pulseaudio] alsa-sink.c: Using 64.0 fragments of size 2048 bytes 
(11.61ms), buffer size is 131072 bytes (743.04ms)
I: [pulseaudio] alsa-sink.c: Time scheduling watermark is 20.00ms
D: [pulseaudio] alsa-sink.c: hwbuf_unused=0
D: [pulseaudio] alsa-sink.c: setting avail_min=31886
D: [pulseaudio] alsa-util.c: snd_pcm_dump():
D: [pulseaudio] alsa-util.c: Hardware PCM card 0 'omap3smlc_a' device 0 
subdevice 0
D: [pulseaudio] alsa-util.c: Its setup is:
D: [pulseaudio] alsa-util.c:   stream       : PLAYBACK
D: [pulseaudio] alsa-util.c:   access       : MMAP_INTERLEAVED
D: [pulseaudio] alsa-util.c:   format       : S16_LE
D: [pulseaudio] alsa-util.c:   subformat    : STD
D: [pulseaudio] alsa-util.c:   channels     : 2
D: [pulseaudio] alsa-util.c:   rate         : 44100
D: [pulseaudio] alsa-util.c:   exact rate   : 44100 (44100/1)
D: [pulseaudio] alsa-util.c:   msbits       : 16
D: [pulseaudio] alsa-util.c:   buffer_size  : 32768
D: [pulseaudio] alsa-util.c:   period_size  : 512
D: [pulseaudio] alsa-util.c:   period_time  : 11609
D: [pulseaudio] alsa-util.c:   tstamp_mode  : ENABLE
D: [pulseaudio] alsa-util.c:   period_step  : 1
D: [pulseaudio] alsa-util.c:   avail_min    : 31886
D: [pulseaudio] alsa-util.c:   period_event : 0
D: [pulseaudio] alsa-util.c:   start_threshold  : -1
D: [pulseaudio] alsa-util.c:   stop_threshold   : 1073741824
D: [pulseaudio] alsa-util.c:   silence_threshold: 0
D: [pulseaudio] alsa-util.c:   silence_size : 0
D: [pulseaudio] alsa-util.c:   boundary     : 1073741824
D: [pulseaudio] alsa-util.c:   appl_ptr     : 0
D: [pulseaudio] alsa-util.c:   hw_ptr       : 0
D: [alsa-sink] alsa-sink.c: Thread starting up
I: [alsa-sink] alsa-sink.c: Starting playback.
D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by 
half.
I: [pulseaudio] module.c: Loaded "module-alsa-sink" (index: #0; argument: 
"device=hw:0,0 sink_name=omap3smlca").
D: [pulseaudio] cli-command.c: Checking for existence of 
'/pulse/usr/local/lib/pulse-1.1/modules/module-esound-protocol-unix.so': 
success
I: [pulseaudio] module.c: Loaded "module-esound-protocol-unix" (index: #1; 
argument: "").
I: [pulseaudio] module.c: Loaded "module-native-protocol-unix" (index: #2; 
argument: "").
D: [pulseaudio] cli-command.c: Checking for existence of 
'/pulse/usr/local/lib/pulse-1.1/modules/module-dbus-protocol.so': failure
I: [pulseaudio] main.c: Daemon startup complete.
D: [alsa-sink] alsa-sink.c: Cutting sleep time for the initial iterations by 
half.