timings: improve timings by returning latency/time pair

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))