[pulseaudio-discuss] Best Case Latency

[Tanu Kaskinen]

On Thu, 2013-10-03 at 02:33 +1000, Patrick Shirkey wrote:
> On Thu, October 3, 2013 12:14 am, Tanu Kaskinen wrote:
> > On Tue, 2013-10-01 at 00:38 +1000, Patrick Shirkey wrote:
> >> On Sat, September 28, 2013 3:12 am, Patrick Shirkey wrote:
> >> >
> >> >> On Sat, September 28, 2013 12:53 am, Tanu Kaskinen wrote:
> >> >> I don't remember if the alsa compatibility layer forwards the
> >> >> stream under/overrun notifications to the alsa application - IIRC
> >> there
> >> >> were problems when those were reported and there were different
> >> >> problems
> >> >> when those were not reported, and I don't remember what the current
> >> >> code
> >> >> does.
> >> >>
> >>
> >> This seems like it would be a good place to verify.
> >
> > Looking at the pulse alsa plugin source, it seems that stream overflow
> > events (the recording direction) are not reported. Underflows (the
> > playback direction) are reported by default (configurable in asoundrc).
> > Overflows are pretty unlikely, since the maximum stream buffer length
> > appears to be configured to 4 MB.
> >
> 
> I see the following sprinkled in /var/log/messages
> 
> Sep 30 12:19:02 xxx pulseaudio[28845]: [pulseaudio] ratelimit.c: 1997
> events suppressed
> Sep 30 12:19:02 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> 
> <snip>
> 
> Sep 30 21:40:04 xxx pulseaudio[28845]: [jack-source] ratelimit.c: 41
> events suppressed
> Sep 30 21:40:04 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Sep 30 21:40:04 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Sep 30 21:40:04 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Sep 30 21:40:04 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Sep 30 21:40:04 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Sep 30 21:40:04 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Sep 30 21:40:04 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Sep 30 21:40:04 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Sep 30 21:40:04 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Sep 30 21:40:04 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Sep 30 21:40:04 xxx pulseaudio[28845]: [jack-source] asyncq.c: q overrun,
> queuing locally
> 
> <snip>
> 
> Oct  1 09:53:30 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Oct  1 10:01:20 xxx pulseaudio[28845]: [pulseaudio] ratelimit.c: 2291
> events suppressed
> Oct  1 10:01:20 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Oct  1 10:01:20 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Oct  1 10:01:20 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Oct  1 10:01:20 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Oct  1 10:01:20 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Oct  1 10:01:20 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Oct  1 10:01:20 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Oct  1 10:01:20 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Oct  1 10:01:20 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Oct  1 10:01:20 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Oct  1 10:01:20 xxx pulseaudio[28845]: [pulseaudio] asyncq.c: q overrun,
> queuing locally
> Oct  1 10:01:42 xxx pulseaudio[28845]: [pulseaudio] ratelimit.c: 2321
> events suppressed

That doesn't look healthy. The message is printed when
pa_asyncmsgq_post() is called and the message queue is full. The message
queue can store 256 messages before this starts to happen, so some queue
consumer is having serious trouble keeping up with the producer. It
would be nice to know which pa_asyncmsgq_post() call this is (you could
set a breakpoint on the line that prints "q overrun", and then get a
backtrace).

> >> Also does anyone know why the PA Stream Buffer is hovering around 10ms?
> >> That number doesn't appear to match the 64 frames/period that JACK is
> >> set
> >> to so it would be useful to verify that it is calculated correctly
> >> and/or
> >> if it can be lowered.
> >
> > You can see in the pulseaudio log, when a stream is created, what
> > memblockq parameters the client requests and what are the final
> > parameters.
> >
> > According to pcm_pulse.c, the requested stream buffer length (tlength in
> > the memblockq parameters) should be
> >
> >     io->buffer_size * pcm->frame_size;
> >
> > I don't know how io->buffer_size is calculated, but I'd expect that to
> > be based on the period number and size provided by you (number of
> > periods * period size).
> >
> > 2 (periods) * 64 (frames per period) * 4 (bytes per frame) / 48
> > (frames/millisecond) equals 10.67 milliseconds, so it looks like the
> > reported latency of 10 milliseconds for playback is what you'd expect.
> >
> 
> Thanks for that info. What is the 48? Is that 48000/1000 ?

Yes, it's the sample rate (I divided it by 1000, because milliseconds
are a more convenient unit here than seconds).

-- 
Tanu