[pulseaudio-discuss] [PATCH RFCv3 30/51] alsa: Make rtpoll_run() runtime measurement compile-time code, default off

[David Henningsson]

On 2014-11-05 00:26, Peter Meerwald wrote:
> safe two pa_rtclock_now() calls in ALSA thread function
>
> Signed-off-by: Peter Meerwald <pmeerw at pmeerw.net>
> ---
>   src/modules/alsa/alsa-sink.c   | 9 ++++++---
>   src/modules/alsa/alsa-source.c | 9 ++++++---
>   2 files changed, 12 insertions(+), 6 deletions(-)
>
> diff --git a/src/modules/alsa/alsa-sink.c b/src/modules/alsa/alsa-sink.c
> index 43b15c3..31853c9 100644
> --- a/src/modules/alsa/alsa-sink.c
> +++ b/src/modules/alsa/alsa-sink.c
> @@ -1696,9 +1696,10 @@ static void thread_func(void *userdata) {
>
>       for (;;) {
>           int ret;
> -        pa_usec_t rtpoll_sleep = 0, real_sleep;
> +        pa_usec_t rtpoll_sleep = 0;
>
>   #ifdef DEBUG_TIMING
> +        pa_usec_t real_sleep;
>           pa_log_debug("Loop");
>   #endif
>
> @@ -1790,7 +1791,9 @@ static void thread_func(void *userdata) {
>
>           if (rtpoll_sleep > 0) {
>               pa_rtpoll_set_timer_relative(u->rtpoll, rtpoll_sleep);
> +#ifdef DEBUG_TIMING
>               real_sleep = pa_rtclock_now();
> +#endif
>           }
>           else
>               pa_rtpoll_set_timer_disabled(u->rtpoll);
> @@ -1800,16 +1803,16 @@ static void thread_func(void *userdata) {
>               goto fail;
>
>           if (rtpoll_sleep > 0) {
> -            real_sleep = pa_rtclock_now() - real_sleep;
>   #ifdef DEBUG_TIMING
> +            real_sleep = pa_rtclock_now() - real_sleep;
>               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_usec)
>                   pa_log_info("Scheduling delay of %0.2f ms > %0.2f ms, you might want to investigate this to improve latency...",
>                       (double) (real_sleep - rtpoll_sleep) / PA_USEC_PER_MSEC,
>                       (double) (u->tsched_watermark_usec) / PA_USEC_PER_MSEC);
> +#endif

For this one, would it be possible to keep it on, given a debug level of 
info or debug? When debugging xruns it is quite helpful if we know it's 
the scheduler rather than the snd_pcm_ syscalls that cause issues. So 
I'd like these to still show up in the debug log.

If checking the time takes a lot of time, we could still skip the calls 
to pa_rtclock_now() if the debug level is warn or err, which I believe 
is the upstream default.

>           }
>
>           if (u->sink->flags & PA_SINK_DEFERRED_VOLUME)
> diff --git a/src/modules/alsa/alsa-source.c b/src/modules/alsa/alsa-source.c
> index 9d4043d..482bae7 100644
> --- a/src/modules/alsa/alsa-source.c
> +++ b/src/modules/alsa/alsa-source.c
> @@ -1443,9 +1443,10 @@ static void thread_func(void *userdata) {
>
>       for (;;) {
>           int ret;
> -        pa_usec_t rtpoll_sleep = 0, real_sleep;
> +        pa_usec_t rtpoll_sleep = 0;
>
>   #ifdef DEBUG_TIMING
> +        pa_usec_t real_sleep;
>           pa_log_debug("Loop");
>   #endif
>
> @@ -1509,7 +1510,9 @@ static void thread_func(void *userdata) {
>
>           if (rtpoll_sleep > 0) {
>               pa_rtpoll_set_timer_relative(u->rtpoll, rtpoll_sleep);
> +#ifdef DEBUG_TIMING
>               real_sleep = pa_rtclock_now();
> +#endif
>           }
>           else
>               pa_rtpoll_set_timer_disabled(u->rtpoll);
> @@ -1519,16 +1522,16 @@ static void thread_func(void *userdata) {
>               goto fail;
>
>           if (rtpoll_sleep > 0) {
> -            real_sleep = pa_rtclock_now() - real_sleep;
>   #ifdef DEBUG_TIMING
> +            real_sleep = pa_rtclock_now() - real_sleep;
>               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_usec)
>                   pa_log_info("Scheduling delay of %0.2f ms > %0.2f ms, you might want to investigate this to improve latency...",
>                       (double) (real_sleep - rtpoll_sleep) / PA_USEC_PER_MSEC,
>                       (double) (u->tsched_watermark_usec) / PA_USEC_PER_MSEC);
> +#endif
>           }
>
>           if (u->source->flags & PA_SOURCE_DEFERRED_VOLUME)
>

-- 
David Henningsson, Canonical Ltd.
https://launchpad.net/~diwic