[pulseaudio-discuss] [PATCH v6 25/25] loopback: Add log_interval parameter

[Georg Chini]

Add a log_interval parameter to control the amount of logging. Default is
no logging. Like the adjust_time parameter, values below 100 are considered
seconds while larger values are ms. If the log interval is too small, logging
will occur on every iteration.

---
 src/modules/module-loopback.c | 59 +++++++++++++++++++++++++++++++++----------
 1 file changed, 46 insertions(+), 13 deletions(-)

diff --git a/src/modules/module-loopback.c b/src/modules/module-loopback.c
index f4e2c2f..e67e9a8 100644
--- a/src/modules/module-loopback.c
+++ b/src/modules/module-loopback.c
@@ -49,6 +49,7 @@ PA_MODULE_USAGE(
         "latency_msec=<latency in ms> "
         "adjust_threshold_usec=<threshold for latency adjustment in usec> "
         "low_device_latency=<boolean, use half of the normal device latency> "
+        "log_interval=<how often to log, values < 100 are seconds, else ms> "
         "format=<sample format> "
         "rate=<sample rate> "
         "channels=<number of channels> "
@@ -97,12 +98,14 @@ struct userdata {
     uint32_t iteration_counter;
     uint32_t underrun_counter;
     uint32_t adjust_counter;
+    uint32_t log_counter;
 
     /* Values from command line configuration */
     pa_usec_t latency;
     uint32_t adjust_threshold;
     pa_usec_t adjust_time;
     bool low_device_latency;
+    uint32_t log_interval;
 
     /* Latency boundaries and current values */
     pa_usec_t min_source_latency;
@@ -157,6 +160,7 @@ static const char* const valid_modargs[] = {
     "latency_msec",
     "adjust_threshold_usec",
     "low_device_latency",
+    "log_interval",
     "format",
     "rate",
     "channels",
@@ -373,18 +377,25 @@ static void adjust_rates(struct userdata *u) {
     /* Calculate new rate */
     new_rate = rate_controller(u, base_rate, old_rate, (int)(filtered_latency - final_latency), latency_difference);
 
-    pa_log_debug("Loopback status %s to %s:\n    Source latency: %0.2f ms\n    Buffer: %0.2f ms\n    Sink latency: %0.2f ms\n    End-to-end latency: %0.2f ms\n"
-                 "    Deviation from target latency at optimum rate: %0.2f usec\n    Average prediction error: ± %0.2f usec\n    Optimum rate: %0.2f Hz\n    Deviation from base rate: %i Hz",
-                u->source_output->source->name,
-                u->sink_input->sink->name,
-                (double) u->latency_snapshot.source_latency / PA_USEC_PER_MSEC,
-                (double) current_buffer_latency / PA_USEC_PER_MSEC,
-                (double) u->latency_snapshot.sink_latency / PA_USEC_PER_MSEC,
-                (double) current_latency / PA_USEC_PER_MSEC,
-                (double) latency_at_optimum_rate - final_latency,
-                (double) u->latency_error,
-                u->drift_compensation_rate + base_rate,
-                (int32_t)(new_rate - base_rate));
+    /* Log every log_interval iterations if the log_interval parameter is set */
+    if (u->log_interval != 0) {
+        u->log_counter--;
+        if (u->log_counter == 0) {
+            pa_log_debug("Loopback status %s to %s:\n    Source latency: %0.2f ms\n    Buffer: %0.2f ms\n    Sink latency: %0.2f ms\n    End-to-end latency: %0.2f ms\n"
+                         "    Deviation from target latency at optimum rate: %0.2f usec\n    Average prediction error: ± %0.2f usec\n    Optimum rate: %0.2f Hz\n    Deviation from base rate: %i Hz",
+                        u->source_output->source->name,
+                        u->sink_input->sink->name,
+                        (double) u->latency_snapshot.source_latency / PA_USEC_PER_MSEC,
+                        (double) current_buffer_latency / PA_USEC_PER_MSEC,
+                        (double) u->latency_snapshot.sink_latency / PA_USEC_PER_MSEC,
+                        (double) current_latency / PA_USEC_PER_MSEC,
+                        (double) latency_at_optimum_rate - final_latency,
+                        (double) u->latency_error,
+                        u->drift_compensation_rate + base_rate,
+                        (int32_t)(new_rate - base_rate));
+            u->log_counter = u->log_interval;
+        }
+    }
 
     /* Save current latency difference at new rate for next cycle and reset flags */
     u->last_latency_difference = current_source_sink_latency + current_buffer_latency * old_rate / new_rate - final_latency;
@@ -660,6 +671,7 @@ static void source_output_detach_cb(pa_source_output *o) {
     u->underrun_counter = 0;
     u->extra_latency = 0;
     u->latency_error = 0;
+    u->log_counter = u->log_interval;
 }
 
 /* Called from main thread */
@@ -964,6 +976,7 @@ static void sink_input_detach_cb(pa_sink_input *i) {
     u->underrun_counter = 0;
     u->extra_latency = 0;
     u->latency_error = 0;
+    u->log_counter = u->log_interval;
 }
 
 /* Called from output thread context */
@@ -1128,7 +1141,7 @@ int pa__init(pa_module *m) {
     pa_source *source = NULL;
     pa_source_output_new_data source_output_data;
     bool source_dont_move;
-    uint32_t latency_msec, adjust_threshold;
+    uint32_t latency_msec, adjust_threshold, log_interval;
     pa_sample_spec ss;
     pa_channel_map map;
     bool format_set = false;
@@ -1257,6 +1270,26 @@ int pa__init(pa_module *m) {
     u->real_adjust_time_sum = 0;
     u->adjust_counter = 0;
 
+    /* Get log interval, default is 0, which means no logging */
+    log_interval = 0;
+    if (pa_modargs_get_value_u32(ma, "log_interval", &log_interval) < 0) {
+        pa_log_info("Invalid log interval specification");
+        goto fail;
+    }
+    if (log_interval != 0 && u->adjust_time != 0) {
+        /* Convert to ms */
+        if (log_interval < 100)
+            log_interval = log_interval * PA_MSEC_PER_SEC;
+        /* Esimate number of iterations */
+        log_interval = (int)((double)log_interval * PA_USEC_PER_MSEC / u->adjust_time + 0.5);
+        /* if log interval is too small, log every iteration */
+        if (log_interval == 0)
+            log_interval = 1;
+    }
+    u->log_interval = log_interval;
+    u->log_counter = log_interval;
+
+
     pa_sink_input_new_data_init(&sink_input_data);
     sink_input_data.driver = __FILE__;
     sink_input_data.module = m;
-- 
2.8.1