[pulseaudio-discuss] Best Case Latency

[Tanu Kaskinen]

On Fri, 2013-10-04 at 21:49 +1000, Patrick Shirkey wrote:
> On Thu, October 3, 2013 11:41 pm, Thomas Martitz wrote:
> > Am 03.10.2013 10:20, schrieb Patrick Shirkey:
> >> On Thu, October 3, 2013 5:14 pm, Tanu Kaskinen wrote:
> >>>
> >>> 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).
> >>>
> >> Sorry, if this is dense but how do I set a breakpoint on this line in PA
> >> while it is running?
> >
> > $ gdb --pid=$(pidof pulseaudio)
> >
> > If you're on debian you need to install debug symbols ($ sudo apt-get
> > install pulseaudio-dbg). For other distros I can't help. Compiling from
> > source in debug mode of course also works.
> >
> 
> Thanks. FYI, installing "pulseaudio-dbg" hosed my NVIDIA video driver
> which was a bit confusing.
> 
> Looking at /var/log/messages I spotted this when starting PA:
> 
> ----
> Oct  4 17:30:49 xxx pulseaudio[6571]: [pulseaudio] sink.c: Default and
> alternate sample rates are the same.
> Oct  4 17:30:49 xxx pulseaudio[6571]: [pulseaudio] module-jack-sink.c:
> JACK error >Cannot use real-time scheduling (RR/5)(1: Operation not
> permitted)<
> Oct  4 17:30:49 xxx pulseaudio[6571]: [pulseaudio] module-jack-sink.c:
> JACK error >JackClient::AcquireSelfRealTime error<
> Oct  4 17:30:49 xxx pulseaudio[6571]: [pulseaudio] source.c: Default and
> alternate sample rates are the same.
> Oct  4 17:30:49 xxx pulseaudio[6571]: [pulseaudio] module-jack-source.c:
> JACK error >Cannot use real-time scheduling (RR/5)(1: Operation not
> permitted)<
> Oct  4 17:30:49 xxx pulseaudio[6571]: [pulseaudio] module-jack-source.c:
> JACK error >JackClient::AcquireSelfRealTime error<
> ----
> 
> - Not sure why it is being printed twice.

Once for the sink and once for the source.

> I have enabled realtime in
> /etc/pulse/daemon.conf and jack is running in realtime mode so not sure
> why PA is unhappy. It could be a bug that is already fixed though.

It's not really PA that is unhappy. The "JACK error >foo<" messages come
from libjack. If you are able to run jackd with RT scheduling, under the
same user that you're running pulseaudio, I don't know what could be the
problem. Pulseaudio limits the realtime priority that it can use
(configured with the rlimit-rtprio option in daemon.conf), but if I
understand the log message correctly, libjack tries to use priority 5,
which shouldn't be a problem, because the default priority that
pulseaudio limits itself is 9.

> - I'm running pulseaudio 4.0 in debian  pulseaudio-dbg:amd64/unstable
> 4.0-6+b1
> 
> - Here's the backtrace based on the line number that Tanu provided. Not
> sure if I nailed it though.
> 
> (gdb) break asyncq.c:211
> Breakpoint 1 at 0x7f4d4572ff90: file pulsecore/asyncq.c, line 211.
> (gdb) continue
> Continuing.
> [Switching to Thread 0x7f4d39b2b700 (LWP 6686)]
> 
> Breakpoint 1, 0x00007f4d4572ff90 in pa_asyncq_post () from
> /usr/lib/libpulsecore-4.0.so
> (gdb) bt
> #0  0x00007f4d4572ff90 in pa_asyncq_post () from /usr/lib/libpulsecore-4.0.so
> #1  0x00007f4d4572ee7b in pa_asyncmsgq_post () at pulsecore/asyncmsgq.c:137
> #2  0x00007f4d3bf374f3 in source_output_push_cb () at
> pulsecore/protocol-native.c:1832
> #3  0x00007f4d4576d3b3 in pa_source_output_push () at
> pulsecore/source-output.c:822
> #4  0x00007f4d45773e5b in pa_source_post () at pulsecore/source.c:935
> #5  0x00007f4d39baf820 in source_process_msg () at
> modules/jack/module-jack-source.c:115
> #6  0x00007f4d4574d084 in asyncmsgq_read_work () from
> /usr/lib/libpulsecore-4.0.so
> #7  0x00007f4d4574c607 in pa_rtpoll_run () from /usr/lib/libpulsecore-4.0.so
> #8  0x00007f4d39baf953 in thread_func () at
> modules/jack/module-jack-source.c:201
> #9  0x00007f4d454f5d08 in ?? () from
> /usr/lib/x86_64-linux-gnu/pulseaudio/libpulsecommon-4.0.so
> #10 0x00007f4d449fae0e in start_thread () from
> /lib/x86_64-linux-gnu/libpthread.so.0
> #11 0x00007f4d4402593d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Ok, so this happens when the native protocol tries to send a block of
audio from the jack source thread to the main thread. My guess is that
the main thread is not getting enough CPU time to deal with all the
incoming audio (it's not RT scheduled).

This could very well cause growing latency. If the jack source pushes
audio blocks to the message queue faster than the main thread reads
those blocks, then that message queue becomes a significant (and
constantly growing?) audio buffer.

What to do? I don't know. Currently there's no upper limit for how long
the message queue can grow (so this is effectively also a memory leak
problem), and no way to query the queue length. Even if there was a
maximum length for the queue, what should be done if that maximum length
is exceeded? Perhaps the native protocol should kill the stream that is
not able to keep up with the source.

-- 
Tanu