timings: improve timings by returning latency/time pairimprove-timing

When we ask for the latency, also return the time when the latency calculation
was made so that we can use both values to have more accurate timing results.

7 files changed, 72 insertions, 37 deletions

diff --git a/src/modules/alsa/alsa-sink.c b/src/modules/alsa/alsa-sink.c
index 1108a7974..1980bec8f 100644
--- a/src/modules/alsa/alsa-sink.c
+++ b/src/modules/alsa/alsa-sink.c
@@ -842,7 +842,7 @@ static void update_smoother(struct userdata *u) {
     u->smoother_interval = PA_MIN (u->smoother_interval * 2, SMOOTHER_MAX_INTERVAL);
 }
 
-static pa_usec_t sink_get_latency(struct userdata *u) {
+static void sink_get_latency(struct userdata *u, pa_usec_t *latency, pa_usec_t *now) {
     pa_usec_t r;
     int64_t delay;
     pa_usec_t now1, now2;
@@ -859,7 +859,8 @@ static pa_usec_t sink_get_latency(struct userdata *u) {
     if (u->memchunk.memblock)
         r += pa_bytes_to_usec(u->memchunk.length, &u->sink->sample_spec);
 
-    return r;
+    *latency = r;
+    *now = now1;
 }
 
 static int build_pollfd(struct userdata *u) {
@@ -1051,12 +1052,10 @@ static int sink_process_msg(pa_msgobject *o, int code, void *data, int64_t offse
     switch (code) {
 
         case PA_SINK_MESSAGE_GET_LATENCY: {
-            pa_usec_t r = 0;
+            pa_usec_t *r = (pa_usec_t *) data;
 
             if (u->pcm_handle)
-                r = sink_get_latency(u);
-
-            *((pa_usec_t*) data) = r;
+                sink_get_latency(u, &r[0], &r[1]);
 
             return 0;
         }
diff --git a/src/modules/alsa/alsa-source.c b/src/modules/alsa/alsa-source.c
index 5f1267517..bbe07bfbf 100644
--- a/src/modules/alsa/alsa-source.c
+++ b/src/modules/alsa/alsa-source.c
@@ -795,8 +795,8 @@ static void update_smoother(struct userdata *u) {
     u->smoother_interval = PA_MIN (u->smoother_interval * 2, SMOOTHER_MAX_INTERVAL);
 }
 
-static pa_usec_t source_get_latency(struct userdata *u) {
-   int64_t delay;
+static void source_get_latency(struct userdata *u, pa_usec_t *latency, pa_usec_t *now) {
+    int64_t delay;
     pa_usec_t now1, now2;
 
     pa_assert(u);
@@ -806,7 +806,8 @@ static pa_usec_t source_get_latency(struct userdata *u) {
 
     delay = (int64_t) now2 - (int64_t) pa_bytes_to_usec(u->read_count, &u->source->sample_spec);
 
-    return delay >= 0 ? (pa_usec_t) delay : 0;
+    *latency = delay >= 0 ? (pa_usec_t) delay : 0;
+    *now = now1;
 }
 
 static int build_pollfd(struct userdata *u) {
@@ -977,12 +978,10 @@ static int source_process_msg(pa_msgobject *o, int code, void *data, int64_t off
     switch (code) {
 
         case PA_SOURCE_MESSAGE_GET_LATENCY: {
-            pa_usec_t r = 0;
+            pa_usec_t *r = (pa_usec_t *) data;
 
             if (u->pcm_handle)
-                r = source_get_latency(u);
-
-            *((pa_usec_t*) data) = r;
+                source_get_latency(u, &r[0], &r[1]);
 
             return 0;
         }
diff --git a/src/modules/echo-cancel/module-echo-cancel.c b/src/modules/echo-cancel/module-echo-cancel.c
index b6c82a5b4..7e701172c 100644
--- a/src/modules/echo-cancel/module-echo-cancel.c
+++ b/src/modules/echo-cancel/module-echo-cancel.c
@@ -821,8 +821,7 @@ static void source_output_snapshot_within_thread(struct userdata *u, struct snap
     size_t delay, rlen, plen;
     pa_usec_t now, latency;
 
-    now = pa_rtclock_now();
-    latency = pa_source_get_latency_within_thread(u->source_output->source);
+    pa_source_get_latency_values_within_thread(u->source_output->source, &latency, &now);
     delay = pa_memblockq_get_length(u->source_output->thread_info.delay_memblockq);
 
     delay = (u->source_output->thread_info.resampler ? pa_resampler_request(u->source_output->thread_info.resampler, delay) : delay);
@@ -900,8 +899,7 @@ static int sink_input_process_msg_cb(pa_msgobject *obj, int code, void *data, in
 
             pa_sink_input_assert_io_context(u->sink_input);
 
-            now = pa_rtclock_now();
-            latency = pa_sink_get_latency_within_thread(u->sink_input->sink);
+            pa_sink_get_latency_values_within_thread(u->sink_input->sink, &latency, &now);
             delay = pa_memblockq_get_length(u->sink_input->thread_info.render_memblockq);
 
             delay = (u->sink_input->thread_info.resampler ? pa_resampler_request(u->sink_input->thread_info.resampler, delay) : delay);
diff --git a/src/pulsecore/sink.c b/src/pulsecore/sink.c
index b68ad3aa8..da1181998 100644
--- a/src/pulsecore/sink.c
+++ b/src/pulsecore/sink.c
@@ -34,6 +34,7 @@
 #include <pulse/timeval.h>
 #include <pulse/util.h>
 #include <pulse/i18n.h>
+#include <pulse/rtclock.h>
 
 #include <pulsecore/sink-input.h>
 #include <pulsecore/namereg.h>
@@ -1116,7 +1117,7 @@ void pa_sink_render_full(pa_sink *s, size_t length, pa_memchunk *result) {
 
 /* Called from main thread */
 pa_usec_t pa_sink_get_latency(pa_sink *s) {
-    pa_usec_t usec = 0;
+    pa_usec_t usec[2] = { 0, 0 };
 
     pa_sink_assert_ref(s);
     pa_assert_ctl_context();
@@ -1130,36 +1131,54 @@ pa_usec_t pa_sink_get_latency(pa_sink *s) {
     if (!(s->flags & PA_SINK_LATENCY))
         return 0;
 
-    pa_assert_se(pa_asyncmsgq_send(s->asyncmsgq, PA_MSGOBJECT(s), PA_SINK_MESSAGE_GET_LATENCY, &usec, 0, NULL) == 0);
+    pa_assert_se(pa_asyncmsgq_send(s->asyncmsgq, PA_MSGOBJECT(s), PA_SINK_MESSAGE_GET_LATENCY, usec, 0, NULL) == 0);
 
-    return usec;
+    return usec[0];
 }
 
 /* Called from IO thread */
-pa_usec_t pa_sink_get_latency_within_thread(pa_sink *s) {
-    pa_usec_t usec = 0;
+void pa_sink_get_latency_values_within_thread(pa_sink *s, pa_usec_t *latency, pa_usec_t *now) {
+    pa_usec_t usec[2] = { 0, 0 };
     pa_msgobject *o;
 
     pa_sink_assert_ref(s);
     pa_sink_assert_io_context(s);
     pa_assert(PA_SINK_IS_LINKED(s->thread_info.state));
+    pa_assert(latency);
+    pa_assert(now);
+
+    *latency = 0;
+    *now = 0;
 
     /* The returned value is supposed to be in the time domain of the sound card! */
 
     if (s->thread_info.state == PA_SINK_SUSPENDED)
-        return 0;
+        return;
 
     if (!(s->flags & PA_SINK_LATENCY))
-        return 0;
+        return;
 
     o = PA_MSGOBJECT(s);
 
     /* FIXME: We probably should make this a proper vtable callback instead of going through process_msg() */
 
-    if (o->process_msg(o, PA_SINK_MESSAGE_GET_LATENCY, &usec, 0, NULL) < 0)
-        return -1;
+    if (o->process_msg(o, PA_SINK_MESSAGE_GET_LATENCY, usec, 0, NULL) < 0)
+        return;
 
-    return usec;
+    *latency = usec[0];
+    if (usec[1] == 0)
+        *now = pa_rtclock_now();
+    else
+        *now = usec[1];
+}
+
+/* Called from IO thread */
+pa_usec_t pa_sink_get_latency_within_thread(pa_sink *s) {
+    pa_usec_t latency, now;
+
+    pa_sink_get_latency_values_within_thread(s, &latency, &now);
+
+    return latency;
 }
 
 static pa_cvolume* cvolume_remap_minimal_impact(
diff --git a/src/pulsecore/sink.h b/src/pulsecore/sink.h
index ba547fc32..fc5ac191b 100644
--- a/src/pulsecore/sink.h
+++ b/src/pulsecore/sink.h
@@ -356,6 +356,7 @@ void pa_sink_request_rewind(pa_sink*s, size_t nbytes);
 void pa_sink_invalidate_requested_latency(pa_sink *s, pa_bool_t dynamic);
 
 pa_usec_t pa_sink_get_latency_within_thread(pa_sink *s);
+void pa_sink_get_latency_values_within_thread(pa_sink *s, pa_usec_t *latency, pa_usec_t *now);
 
 pa_device_port *pa_device_port_new(const char *name, const char *description, size_t extra);
 void pa_device_port_free(pa_device_port *p);
diff --git a/src/pulsecore/source.c b/src/pulsecore/source.c
index 415c54bc3..1a960d791 100644
--- a/src/pulsecore/source.c
+++ b/src/pulsecore/source.c
@@ -32,6 +32,7 @@
 #include <pulse/xmalloc.h>
 #include <pulse/timeval.h>
 #include <pulse/util.h>
+#include <pulse/rtclock.h>
 
 #include <pulsecore/core-util.h>
 #include <pulsecore/source-output.h>
@@ -709,7 +710,7 @@ void pa_source_post_direct(pa_source*s, pa_source_output *o, const pa_memchunk *
 
 /* Called from main thread */
 pa_usec_t pa_source_get_latency(pa_source *s) {
-    pa_usec_t usec;
+    pa_usec_t usec[2] = { 0, 0 };
 
     pa_source_assert_ref(s);
     pa_assert_ctl_context();
@@ -721,36 +722,52 @@ pa_usec_t pa_source_get_latency(pa_source *s) {
     if (!(s->flags & PA_SOURCE_LATENCY))
         return 0;
 
-    pa_assert_se(pa_asyncmsgq_send(s->asyncmsgq, PA_MSGOBJECT(s), PA_SOURCE_MESSAGE_GET_LATENCY, &usec, 0, NULL) == 0);
+    pa_assert_se(pa_asyncmsgq_send(s->asyncmsgq, PA_MSGOBJECT(s), PA_SOURCE_MESSAGE_GET_LATENCY, usec, 0, NULL) == 0);
 
-    return usec;
+    return usec[0];
 }
 
 /* Called from IO thread */
-pa_usec_t pa_source_get_latency_within_thread(pa_source *s) {
-    pa_usec_t usec = 0;
+void pa_source_get_latency_values_within_thread(pa_source *s, pa_usec_t *latency, pa_usec_t *now) {
+    pa_usec_t usec[2] = { 0, 0 };
     pa_msgobject *o;
 
     pa_source_assert_ref(s);
     pa_source_assert_io_context(s);
     pa_assert(PA_SOURCE_IS_LINKED(s->thread_info.state));
 
+    *latency = 0;
+    *now = 0;
+
     /* The returned value is supposed to be in the time domain of the sound card! */
 
     if (s->thread_info.state == PA_SOURCE_SUSPENDED)
-        return 0;
+        return;
 
     if (!(s->flags & PA_SOURCE_LATENCY))
-        return 0;
+        return;
 
     o = PA_MSGOBJECT(s);
 
     /* We probably should make this a proper vtable callback instead of going through process_msg() */
 
-    if (o->process_msg(o, PA_SOURCE_MESSAGE_GET_LATENCY, &usec, 0, NULL) < 0)
-        return -1;
+    if (o->process_msg(o, PA_SOURCE_MESSAGE_GET_LATENCY, usec, 0, NULL) < 0)
+        return;
+
+    *latency = usec[0];
+    if (usec[1] == 0)
+        *now = pa_rtclock_now();
+    else
+        *now = usec[1];
+}
 
-    return usec;
+/* Called from IO thread */
+pa_usec_t pa_source_get_latency_within_thread(pa_source *s) {
+    pa_usec_t latency, now;
+
+    pa_source_get_latency_values_within_thread(s, &latency, &now);
+
+    return latency;
 }
 
 /* Called from main thread */
diff --git a/src/pulsecore/source.h b/src/pulsecore/source.h
index e3e56bc45..9ac44c1f5 100644
--- a/src/pulsecore/source.h
+++ b/src/pulsecore/source.h
@@ -306,6 +306,8 @@ void pa_source_set_fixed_latency_within_thread(pa_source *s, pa_usec_t latency);
 
 void pa_source_invalidate_requested_latency(pa_source *s, pa_bool_t dynamic);
 pa_usec_t pa_source_get_latency_within_thread(pa_source *s);
+void pa_source_get_latency_values_within_thread(pa_source *s, pa_usec_t *latency, pa_usec_t *now);
+
 
 #define pa_source_assert_io_context(s) \
     pa_assert(pa_thread_mq_get() || !PA_SOURCE_IS_LINKED((s)->state))