Improve 'debug.io' fdqueue.c debug logging

This commit is contained in:
Andrew Bettison 2013-11-19 15:37:18 +10:30
parent cb7b465888
commit 2c07f7888e

View File

@ -85,13 +85,15 @@ int is_scheduled(const struct sched_ent *alarm)
// on calling .poll.revents will be zero.
int _schedule(struct __sourceloc __whence, struct sched_ent *alarm)
{
time_ms_t now = gettime_ms();
if (config.debug.io)
DEBUGF("schedule(alarm=%s) called from %s() %s:%d",
alloca_alarm_name(alarm),
__whence.function,__whence.file,__whence.line);
DEBUGF("schedule(alarm=%s) alarm=%.3f deadline=%.3f",
alloca_alarm_name(alarm),
(double)(alarm->alarm - now) / 1000,
(double)(alarm->deadline - now) / 1000
);
if (!alarm->stats)
WARNF("schedule() called from %s() %s:%d without supplying an alarm name",
__whence.function,__whence.file,__whence.line);
WARN("schedule() called without supplying an alarm name");
struct sched_ent *node = next_alarm, *last = NULL;
@ -100,18 +102,16 @@ int _schedule(struct __sourceloc __whence, struct sched_ent *alarm)
if (!alarm->function)
return WHY("Can't schedule if you haven't set the function pointer");
time_ms_t now = gettime_ms();
if (alarm->deadline < alarm->alarm)
alarm->deadline = alarm->alarm;
if (now - alarm->deadline > 1000){
// 1000ms ago? thats silly, if you keep doing it noone else will get a turn.
WHYF("Alarm %s tried to schedule a deadline %"PRId64"ms ago, from %s() %s:%d",
WHYF("Alarm %s tried to schedule a deadline %"PRId64"ms ago",
alloca_alarm_name(alarm),
(now - alarm->deadline),
__whence.function,__whence.file,__whence.line);
(now - alarm->deadline)
);
}
// if the alarm has already expired, move straight to the deadline queue
@ -168,8 +168,7 @@ int _watch(struct __sourceloc __whence, struct sched_ent *alarm)
if (config.debug.io)
DEBUGF("watch(alarm=%s)", alloca_alarm_name(alarm));
if (!alarm->stats)
WARNF("watch() called from %s() %s:%d without supplying an alarm name",
__whence.function,__whence.file,__whence.line);
WARN("watch() called without supplying an alarm name");
if (!alarm->function)
return WHY("Can't watch if you haven't set the function pointer");
@ -177,10 +176,10 @@ int _watch(struct __sourceloc __whence, struct sched_ent *alarm)
if (alarm->_poll_index>=0 && fd_callbacks[alarm->_poll_index]==alarm){
// updating event flags
if (config.debug.io)
DEBUGF("Updating watch %s, #%d for %d", alloca_alarm_name(alarm), alarm->poll.fd, alarm->poll.events);
DEBUGF("Updating watch %s, #%d for %s", alloca_alarm_name(alarm), alarm->poll.fd, alloca_poll_events(alarm->poll.events));
}else{
if (config.debug.io)
DEBUGF("Adding watch %s, #%d for %d", alloca_alarm_name(alarm), alarm->poll.fd, alarm->poll.events);
DEBUGF("Adding watch %s, #%d for %s", alloca_alarm_name(alarm), alarm->poll.fd, alloca_poll_events(alarm->poll.events));
if (fdcount>=MAX_WATCHED_FDS)
return WHY("Too many file handles to watch");
fd_callbacks[fdcount]=alarm;
@ -213,7 +212,7 @@ int _unwatch(struct __sourceloc __whence, struct sched_ent *alarm)
fd_callbacks[fdcount]=NULL;
alarm->_poll_index=-1;
if (config.debug.io)
DEBUGF("%s stopped watching #%d for %d", alloca_alarm_name(alarm), alarm->poll.fd, alarm->poll.events);
DEBUGF("%s stopped watching #%d for %s", alloca_alarm_name(alarm), alarm->poll.fd, alloca_poll_events(alarm->poll.events));
return 0;
}
@ -225,8 +224,8 @@ static void call_alarm(struct sched_ent *alarm, int revents)
struct call_stats call_stats;
call_stats.totals = alarm->stats;
if (config.debug.io) DEBUGF("Calling alarm/callback %p ('%s')",
alarm, alloca_alarm_name(alarm));
if (config.debug.io)
DEBUGF("Calling alarm/callback %p %s", alarm, alloca_alarm_name(alarm));
if (call_stats.totals)
fd_func_enter(__HERE__, &call_stats);
@ -237,7 +236,8 @@ static void call_alarm(struct sched_ent *alarm, int revents)
if (call_stats.totals)
fd_func_exit(__HERE__, &call_stats);
if (config.debug.io) DEBUGF("Alarm %p returned",alarm);
if (config.debug.io)
DEBUGF("Alarm %p returned",alarm);
OUT();
}