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
This commit is contained in:
Pierre-Louis Bossart 2009-12-23 13:57:03 -06:00 committed by Lennart Poettering
parent a282eadb88
commit 0e47065fe5

View file

@ -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