Thanks for the help Tanu. It's very much appreciated.
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).It seems that you're logging to syslog. In case you didn't know, you can also run pulseaudio in a terminal and get the logs in the terminal, or if running pulseaudio as a background process is important, it's possible to set "log-target = newfile:/tmp/pulselog.txt" in /etc/pulse/daemon.conf, or to pass --log- target=newfile:/tmp/pulselog.txt on the command line. Of course, if you prefer to use syslog for some reason, I have no problem with that.
Given the difficult environment on the test workstation, I've stuck with syslog just because it's easy.
I've attached the modified pa_source_output_push() and highly pruned, gzipped output as before.
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.If you have pavucontrol running, it will create source outputs for both the null sink monitor and the remap source to be able to get the data for the volume meters. I think it would be good to log the source name and some identifier for the source output (either just the source output index, or some more readable data from the source output proplist).
The latest logging logs source-output creation and outputs the source-output index, module, source and destination_source names. Any other output is only done if source or destination_source names are "voip_source".
The notable events are as follows:* At 06:20:00 the source outputs for module-remap-source and module-rtp-send are created.
* At 06:21:08 the binary that uses the PulseAudio API to connect to the rtp_in_sink0.monitor an rtp_in_sink1.monitor sources starts, creating new source outputs associated with module-native-protocol-unix.
* At 06:22:01 pavucontrol starts, creating a whole lot of source outputs, including one for "voip_source", which is one of the source outputs that has a max_rewind of 2304000bytes.
* At 06:22:36 another computer attempts to connect with a VoIP call, which isn't accepted until 06::23:00. One additional source output for "voip_source" is created at 06:22:36 and has max_rewind of 2304000bytes. No notable event seems to happen at 06:23:00.
* All source outputs change max_rewind from zero to nonzero soon after creation, but the only source outputs that ever change max_rewind beyond that are thos associated with module-rtp-send.
* 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().The limit is the source's max rewind amount, and I see a bug related to that in module-remap-source (I wouldn't be surprised if it's in other filter sources too). The remap source max rewind is supposed to mirror the master source max rewind, but when the master source max rewind changes, the remap source max rewind isn't updated. The remap source should set the update_max_rewind source output callback, and use the callback to update its own max rewind to match the master source. If the max rewind isn't updated, as is now the case, it will stay at whatever value the master source had when the remap source got loaded. At that time there are likely no streams that are forcing lower latency, leading to a too high max rewind value when a low latency stream appears.
This seems to be confirmed by the fact that the only max_rewind changes (other than after creation) happen in the module-rtp-send module.
Given the platform configuration difficulties I have, can you think of a CLI-based work-around for this?
Steve
/* 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;
char output[256];
int idx = 0;
bool do_print = false;
size_t len = chunk->length;
static size_t max_rewinds[] = { 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 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);
idx += sprintf(output, "index=%u", o->index);
if (o->module) {
idx += sprintf(output + idx, ", mod=\"%s\"", o->module->name);
}
if (o->source) {
idx += sprintf(output + idx, ", src=\"%s\"", o->source->name);
if (strcmp(o->source->name, "voip_source") == 0) {
do_print = true;
}
}
if (o->destination_source) {
idx += sprintf(output + idx, ", dst_src=\"%s\"", o->destination_source->name);
if (strcmp(o->destination_source->name, "voip_source") == 0) {
do_print = true;
}
}
pa_log_error(" %s", output);
if (pa_memblockq_push(o->thread_info.delay_memblockq, chunk) < 0) {
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;
if (do_print) {
pa_log_error(" pushing %ubytes, limit %ubytes", (uint32_t)len, (uint32_t)limit);
}
if (limit != max_rewinds[o->index]) {
pa_log_error("max_rewind changed from %ubytes to %ubytes", (uint32_t)max_rewinds[o->index], (uint32_t)limit);
max_rewinds[o->index] = 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);
n = pa_usec_to_bytes(latency, &o->source->sample_spec);
if (n < limit)
limit = n;
}
/* 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_assert_se(pa_memblockq_peek(o->thread_info.delay_memblockq, &qchunk) >= 0);
if (qchunk.length > length)
qchunk.length = 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) {
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_memchunk rchunk;
if (mbs == 0)
mbs = pa_resampler_max_block_size(o->thread_info.resampler);
if (qchunk.length > mbs)
qchunk.length = mbs;
pa_resampler_run(o->thread_info.resampler, &qchunk, &rchunk);
if (rchunk.length > 0) {
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
