Message: 3 Date: Sat, 14 Oct 2017 01:43:42 +0300 From: Tanu Kaskinen <[email protected]> To: General PulseAudio Discussion <[email protected]> Subject: Re: [pulseaudio-discuss] How to control latency with CLI? Message-ID: <[email protected]> Content-Type: text/plain; charset="UTF-8" On Fri, 2017-10-13 at 19:09 +1030, Steven Wawryk wrote:Today I noticed that there seems to be about 5minutes delay in module-remap-source on the workstation rather than in module-loopback on the embedded system.With the following CLI script items (selecting 1 of the 12 channels of digitised audio from the embedded system): ... load-module module-null-sink sink_name=rtp_in_sink1 sink_properties=device.description=RTP_in1 format=ulaw rate=8000 channels=12 channel_map=aux0,aux1,aux2,aux3,aux4,aux5,aux6,aux7,aux8,aux9,aux10,aux11 ... load-module module-rtp-recv sink=rtp_in_sink1 sap_address=224.0.0.81 latency_msec=10 ... load-module module-remap-source source_name=voip_source master=rtp_in_sink1.monitor source_properties=device.description=VoIPSource format=ulaw rate=8000 channels=1 master_channel_map=aux4 channel_map=front-left remix=no ... ... and observing with pavucontrol, when I tapped or spoke into the microphone, there was signal with no noticeable delay at rtp_in_sink1 and rtp_in_sink1.monitor, but the signal could not be seen on voip_source until about 5minutes later. I can't see any obvious reason in the module-remap-source source code. I will investigate further on Monday (including logs), but have I messed up the above CLI statements?I don't see anything wrong with the CLI commands. The latency in module-remap-source is weird. The module itself doesn't do any buffering. module-remap-source connects to the master source using a pa_source_output, and pa_source_output contains delay_memblockq, which is a buffer. Maybe the delay_memblockq is involved in the huge latency? The purpose (or at least one purpose) of delay_memblockq is to keep enough data buffered in monitor sources to deal with the possibility of data getting changed in the unplayed portion of the sink playback buffer. The sink in your case (or in any other case) doesn't have a playback buffer of 5 minutes, so if the delay_memblockq holds 5 minutes worth of data, there's some bug. Maybe adding some extra logging to pa_source_output_push() will shed some light on the matter.
I've *finally* managed to get PulseAudio running on the test workstation with extra logging in pa_source_output_push()!
I've attached a copy of pa_source_output_push() with the extra log statements to show where they are. Also, about 1second of gzipped output is attached (because otherwise there's a *lot* of output).
I don't fully understand what's going on, but here are a few things I noticed, which may be suspicious:
* There seems to be a number of source-outputs logging output, but I assume the relevant one for module-remap-source is the one with the PA_RESAMPLER_NO_REMIX ("flags=0x04") flag set because of the "remix=no" parameter I gave it.
* Whenever this source-output calls this function (outputting "rsmplr=30, flags=0x4" in the while loop), there seems to always be another immediately following call (outputting "limit=2304000bytes (1)" at the start of the function) with the *large* 2304000bytes limit that never executes the following "if" and "while" statement bodies. Hence it never calls o->push().
* At some point in the "Oct 25 05:31:07" second, the above behaviour switches from 1 to 2 immediately following calls with "limit=2304000bytes (1)" logged.
That's as far as I got today. In the absence of any feedback or guidance on this email, I'll investigate further tomorrow and hope I'm not too far off track.
/* Called from thread context */
void pa_source_output_push(pa_source_output *o, const pa_memchunk *chunk) {
bool need_volume_factor_source;
bool volume_is_norm;
size_t length;
size_t limit, mbs = 0;
pa_source_output_assert_ref(o);
pa_source_output_assert_io_context(o);
pa_assert(PA_SOURCE_OUTPUT_IS_LINKED(o->thread_info.state));
pa_assert(chunk);
pa_assert(pa_frame_aligned(chunk->length, &o->source->sample_spec));
if (!o->push || o->thread_info.state == PA_SOURCE_OUTPUT_CORKED)
return;
pa_assert(o->thread_info.state == PA_SOURCE_OUTPUT_RUNNING);
if (pa_memblockq_push(o->thread_info.delay_memblockq, chunk) < 0) {
pa_log_error("tst: Delay queue overflow!");
pa_log_debug("Delay queue overflow!");
pa_memblockq_seek(o->thread_info.delay_memblockq, (int64_t) chunk->length, PA_SEEK_RELATIVE, true);
}
limit = o->process_rewind ? 0 : o->source->thread_info.max_rewind;
pa_log_error("tst: limit=%ubytes (1)", (uint32_t)limit);
volume_is_norm = pa_cvolume_is_norm(&o->thread_info.soft_volume) && !o->thread_info.muted;
need_volume_factor_source = !pa_cvolume_is_norm(&o->volume_factor_source);
if (limit > 0 && o->source->monitor_of) {
pa_usec_t latency;
size_t n;
/* Hmm, check the latency for knowing how much of the buffered
* data is actually still unplayed and might hence still
* change. This is suboptimal. Ideally we'd have a call like
* pa_sink_get_changeable_size() or so that tells us how much
* of the queued data is actually still changeable. Hence
* FIXME! */
latency = pa_sink_get_latency_within_thread(o->source->monitor_of);
pa_log_error("tst: latency=%luusec", latency);
n = pa_usec_to_bytes(latency, &o->source->sample_spec);
pa_log_error("tst: latency=%ubytes", (uint32_t)n);
if (n < limit)
limit = n;
pa_log_error("tst: limit=%ubytes (2)", (uint32_t)limit);
}
/* Implement the delay queue */
while ((length = pa_memblockq_get_length(o->thread_info.delay_memblockq)) > limit) {
pa_memchunk qchunk;
bool nvfs = need_volume_factor_source;
length -= limit;
pa_log_error("tst: length=%ubytes", (uint32_t)length);
pa_assert_se(pa_memblockq_peek(o->thread_info.delay_memblockq, &qchunk) >= 0);
if (qchunk.length > length)
qchunk.length = length;
pa_log_error("tst: qchunk.length=%ubytes", (uint32_t)qchunk.length);
pa_assert(qchunk.length > 0);
/* It might be necessary to adjust the volume here */
if (!volume_is_norm) {
pa_memchunk_make_writable(&qchunk, 0);
if (o->thread_info.muted) {
pa_silence_memchunk(&qchunk, &o->source->sample_spec);
nvfs = false;
} else if (!o->thread_info.resampler && nvfs) {
pa_cvolume v;
/* If we don't need a resampler we can merge the
* post and the pre volume adjustment into one */
pa_sw_cvolume_multiply(&v, &o->thread_info.soft_volume, &o->volume_factor_source);
pa_volume_memchunk(&qchunk, &o->source->sample_spec, &v);
nvfs = false;
} else
pa_volume_memchunk(&qchunk, &o->source->sample_spec, &o->thread_info.soft_volume);
}
if (!o->thread_info.resampler) {
pa_log_error("tst: No resampler");
if (nvfs) {
pa_memchunk_make_writable(&qchunk, 0);
pa_volume_memchunk(&qchunk, &o->thread_info.sample_spec, &o->volume_factor_source);
}
o->push(o, &qchunk);
} else {
pa_log_error("tst: rsmplr=%d, flags=0x%x", (int32_t)o->thread_info.resampler->method, (uint32_t)o->thread_info.resampler->flags);
pa_memchunk rchunk;
if (mbs == 0)
mbs = pa_resampler_max_block_size(o->thread_info.resampler);
pa_log_error("tst: mbs=%ubytes", (uint32_t)mbs);
if (qchunk.length > mbs)
qchunk.length = mbs;
pa_resampler_run(o->thread_info.resampler, &qchunk, &rchunk);
if (rchunk.length > 0) {
pa_log_error("tst: rchunk.length=%ubytes", (uint32_t)rchunk.length);
if (nvfs) {
pa_memchunk_make_writable(&rchunk, 0);
pa_volume_memchunk(&rchunk, &o->thread_info.sample_spec, &o->volume_factor_source);
}
o->push(o, &rchunk);
}
if (rchunk.memblock)
pa_memblock_unref(rchunk.memblock);
}
pa_memblock_unref(qchunk.memblock);
pa_memblockq_drop(o->thread_info.delay_memblockq, qchunk.length);
}
}
palog.gz
Description: application/gzip
_______________________________________________ pulseaudio-discuss mailing list [email protected] https://lists.freedesktop.org/mailman/listinfo/pulseaudio-discuss
