Subject: rtpoll: better support for DEBUG_TIMING logs

On all the platforms I tested, PulseAudio is frequently awaken and
doesn't sleep for the duration specified for the poll timeout.
Sometimes wake-ups occur within milliseconds of the poll call for no
good reason; this seems to be related to ALSA issues (see my posts on
the ALSA mailing list on null poll events).
This patch enables a better log of requested sleep times v. actual
sleep times. Enable DEBUG_TIMING to see actual messages. Please let me
know if you see odd behaviors like the one below
- Pierre

E: rtpoll.c: rtpoll_run
E: rtpoll.c: poll timeout: 188 ms
E: rtpoll.c: Process time 0 ms; sleep time 48 ms
E: rtpoll.c: rtpoll_run
E: rtpoll.c: rtpoll finish
E: rtpoll.c: rtpoll_run
E: rtpoll.c: poll timeout: 139 ms
E: rtpoll.c: Process time 0 ms; sleep time 49 ms
E: rtpoll.c: rtpoll_run
E: rtpoll.c: rtpoll finish
E: rtpoll.c: rtpoll_run
E: rtpoll.c: poll timeout: 189 ms
E: rtpoll.c: Process time 0 ms; sleep time 0 ms
E: rtpoll.c: rtpoll_run
E: rtpoll.c: rtpoll finish
E: rtpoll.c: rtpoll_run
E: rtpoll.c: poll timeout: 189 ms
E: rtpoll.c: Process time 0 ms; sleep time 49 ms

1 files changed, 20 insertions, 3 deletions

diff --git a/src/pulsecore/rtpoll.c b/src/pulsecore/rtpoll.c
index 666cbc98..e2f82626 100644
--- a/src/pulsecore/rtpoll.c
+++ b/src/pulsecore/rtpoll.c
@@ -47,6 +47,7 @@
 #include <pulsecore/core-util.h>
 #include <pulsecore/winsock.h>
 #include <pulsecore/ratelimit.h>
+#include <pulse/rtclock.h>
 
 #include "rtpoll.h"
 
@@ -217,6 +218,10 @@ int pa_rtpoll_run(pa_rtpoll *p, pa_bool_t wait_op) {
     pa_assert(p);
     pa_assert(!p->running);
 
+#ifdef DEBUG_TIMING
+    pa_log("rtpoll_run");
+#endif
+
     p->running = TRUE;
     p->timer_elapsed = FALSE;
 
@@ -230,13 +235,19 @@ int pa_rtpoll_run(pa_rtpoll *p, pa_bool_t wait_op) {
         if (!i->work_cb)
             continue;
 
-        if (p->quit)
+        if (p->quit) {
+#ifdef DEBUG_TIMING
+            pa_log("rtpoll finish");
+#endif
             goto finish;
+        }
 
         if ((k = i->work_cb(i)) != 0) {
             if (k < 0)
                 r = k;
-
+#ifdef DEBUG_TIMING
+            pa_log("rtpoll finish");
+#endif
             goto finish;
         }
     }
@@ -268,7 +279,9 @@ int pa_rtpoll_run(pa_rtpoll *p, pa_bool_t wait_op) {
 
             if (k < 0)
                 r = k;
-
+#ifdef DEBUG_TIMING
+            pa_log("rtpoll finish");
+#endif
             goto finish;
         }
     }
@@ -292,6 +305,10 @@ int pa_rtpoll_run(pa_rtpoll *p, pa_bool_t wait_op) {
         pa_usec_t now = pa_rtclock_now();
         p->awake = now - p->timestamp;
         p->timestamp = now;
+        if (!wait_op || p->quit || p->timer_enabled)
+            pa_log("poll timeout: %d ms ",(int) ((timeout.tv_sec*1000) + (timeout.tv_usec / 1000)));
+        else
+            pa_log("poll timeout is ZERO");
     }
 #endif