From 3bb0b88bebb1c54280d5bfe02c64e5107b125fa5 Mon Sep 17 00:00:00 2001 From: David Henningsson Date: Mon, 22 Oct 2012 10:53:32 +0200 Subject: [PATCH] alsa-sink/source: Warn for scheduling delays 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 --- 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); -- 2.7.4