diff options
author | Pierre-Louis Bossart <pierre-louis.bossart@intel.com> | 2009-12-23 13:57:03 -0600 |
---|---|---|
committer | Lennart Poettering <lennart@poettering.net> | 2010-01-05 21:27:25 +0100 |
commit | 0e47065fe5a410bcb7c367c23fc4d99b71fd82b2 (patch) | |
tree | db673f61f6579b58a57ebedadbb1c54ec540c666 /src | |
parent | a282eadb88f26cea183399dba267d619bbdcd6df (diff) |
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
Diffstat (limited to 'src')
-rw-r--r-- | src/pulsecore/rtpoll.c | 23 |
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 |