[pulseaudio-discuss] [PATCH] alsa-sink/source: Warn for scheduling delays

[David Henningsson]

Sometimes the kernel does not schedule us in due time, thus causing
an underrun. Adding a detection and a debug message will be a helpful
step in determining the cause of an underrun.

Signed-off-by: David Henningsson <david.henningsson at canonical.com>
---

Will push this one to the 3.0 tree unless there are any objections?

 src/modules/alsa/alsa-sink.c   |   18 ++++++++++++++++--
 src/modules/alsa/alsa-source.c |   18 ++++++++++++++++--
 2 files changed, 32 insertions(+), 4 deletions(-)

diff --git a/src/modules/alsa/alsa-sink.c b/src/modules/alsa/alsa-sink.c
index 544399e..d3bf76d 100644
--- a/src/modules/alsa/alsa-sink.c
+++ b/src/modules/alsa/alsa-sink.c
@@ -1685,7 +1685,7 @@ static void thread_func(void *userdata) {
 
     for (;;) {
         int ret;
-        pa_usec_t rtpoll_sleep = 0;
+        pa_usec_t rtpoll_sleep = 0, real_sleep;
 
 #ifdef DEBUG_TIMING
         pa_log_debug("Loop");
@@ -1776,8 +1776,10 @@ static void thread_func(void *userdata) {
             }
         }
 
-        if (rtpoll_sleep > 0)
+        if (rtpoll_sleep > 0) {
             pa_rtpoll_set_timer_relative(u->rtpoll, rtpoll_sleep);
+            real_sleep = pa_rtclock_now();
+        }
         else
             pa_rtpoll_set_timer_disabled(u->rtpoll);
 
@@ -1785,6 +1787,18 @@ static void thread_func(void *userdata) {
         if ((ret = pa_rtpoll_run(u->rtpoll, TRUE)) < 0)
             goto fail;
 
+        if (rtpoll_sleep > 0) {
+            real_sleep = pa_rtclock_now() - real_sleep;
+#ifdef DEBUG_TIMING
+            pa_log_debug("Expected sleep: %0.2fms, real sleep: %0.2fms (diff %0.2f ms)",
+                (double) rtpoll_sleep / PA_USEC_PER_MSEC, (double) real_sleep / PA_USEC_PER_MSEC,
+                (double) ((int64_t) real_sleep - (int64_t) rtpoll_sleep) / PA_USEC_PER_MSEC);
+#endif
+            if (u->use_tsched && real_sleep > rtpoll_sleep + u->tsched_watermark)
+                pa_log_info("Scheduling delay of %0.2fms, you might want to investigate this to improve latency...",
+                    (double) (real_sleep - rtpoll_sleep) / PA_USEC_PER_MSEC);
+        }
+
         if (u->sink->flags & PA_SINK_DEFERRED_VOLUME)
             pa_sink_volume_change_apply(u->sink, NULL);
 
diff --git a/src/modules/alsa/alsa-source.c b/src/modules/alsa/alsa-source.c
index 94d4a09..d3a356a 100644
--- a/src/modules/alsa/alsa-source.c
+++ b/src/modules/alsa/alsa-source.c
@@ -1451,7 +1451,7 @@ static void thread_func(void *userdata) {
 
     for (;;) {
         int ret;
-        pa_usec_t rtpoll_sleep = 0;
+        pa_usec_t rtpoll_sleep = 0, real_sleep;
 
 #ifdef DEBUG_TIMING
         pa_log_debug("Loop");
@@ -1515,8 +1515,10 @@ static void thread_func(void *userdata) {
             }
         }
 
-        if (rtpoll_sleep > 0)
+        if (rtpoll_sleep > 0) {
             pa_rtpoll_set_timer_relative(u->rtpoll, rtpoll_sleep);
+            real_sleep = pa_rtclock_now();
+        }
         else
             pa_rtpoll_set_timer_disabled(u->rtpoll);
 
@@ -1524,6 +1526,18 @@ static void thread_func(void *userdata) {
         if ((ret = pa_rtpoll_run(u->rtpoll, TRUE)) < 0)
             goto fail;
 
+        if (rtpoll_sleep > 0) {
+            real_sleep = pa_rtclock_now() - real_sleep;
+#ifdef DEBUG_TIMING
+            pa_log_debug("Expected sleep: %0.2fms, real sleep: %0.2fms (diff %0.2f ms)",
+                (double) rtpoll_sleep / PA_USEC_PER_MSEC, (double) real_sleep / PA_USEC_PER_MSEC,
+                (double) ((int64_t) real_sleep - (int64_t) rtpoll_sleep) / PA_USEC_PER_MSEC);
+#endif
+            if (u->use_tsched && real_sleep > rtpoll_sleep + u->tsched_watermark)
+                pa_log_info("Scheduling delay of %0.2fms, you might want to investigate this to improve latency...",
+                    (double) (real_sleep - rtpoll_sleep) / PA_USEC_PER_MSEC);
+        }
+
         if (u->source->flags & PA_SOURCE_DEFERRED_VOLUME)
             pa_source_volume_change_apply(u->source, NULL);
 
-- 
1.7.9.5