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
