EVFILT_TIMER does not behave as expected
EVFILT_TIMER does not behave as expected
- Subject: EVFILT_TIMER does not behave as expected
- From: Godfrey van der Linden <email@hidden>
- Date: Thu, 11 Mar 2010 18:05:37 +1100
G'day, All.
I've just spent a few days tracking down a bug in my kevent based event handling system and the timers just don't work as expected, that is ONESHOT USECOND timers always return immediately!
I set up my initial change list as
struct kevent timers[2];
int nch = 0;
EV_SET(&timers[nch], kLongTimerUS, EVFILT_TIMER, EV_ADD|EV_ONESHOT,
NOTE_USECONDS, 0, (void *) nch); nch++;
EV_SET(&timers[nch], kShortTimerUS, EVFILT_TIMER, EV_ADD|EV_ONESHOT,
NOTE_USECONDS, 0, (void *) nch); nch++;
Then I call
chList = timers;
for (;;) {
int nev = kevent(kq, chList, (int) nch, &evList, 1, NULL);
chList = NULL; nch = 0;
logKEvent(&evList);
}
Finally the results I get are
6us: timers[0] = { 1000000, EVFILT_TIMER, ADD|ONESHOT, 2, 0 }
32us: timers[1] = { 10000, EVFILT_TIMER, ADD|ONESHOT, 2, 0 }
46us: kev[0] = { 1000000, EVFILT_TIMER, ADD|ONESHOT, 0, 1 }
53us: kev[0] = { 10000, EVFILT_TIMER, ADD|ONESHOT, 0, 1 }
Where the first two lines log the creation of the change list, where the second two lines are kevents returned from my kevent call. The beginning of the line is the number of micro seconds from the start of the program, Notice I asked for two timeouts one of 1s another of 10ms. They both fire within 53us of the test running! That I didn't expect!
Below I have included the a minimum proof of the problem.
/*
gcc -std=c99 -Wall -Wextra -Werror -g -o kevent_bug kevent_bug.c
*/
#include <sys/cdefs.h>
#include <assert.h>
#include <errno.h>
#include <stdio.h>
#include <stdbool.h>
#include <strings.h>
#include <sys/time.h>
#include <sys/event.h>
#define kLongTimerUS (1000 * 1000)
#define kShortTimerUS ( 10 * 1000)
static struct timeval sStart;
static void
logKEvent(const struct kevent *kep, int ind, const char * const pfx);
int main(int argc __unused, char *argv[] __unused)
{
int kq = kqueue();
gettimeofday(&sStart, NULL);
struct kevent timers[2];
uintptr_t nch = 0;
EV_SET(&timers[nch], kLongTimerUS, EVFILT_TIMER, EV_ADD|EV_ONESHOT,
NOTE_USECONDS, 0, (void *) nch); nch++;
EV_SET(&timers[nch], kShortTimerUS, EVFILT_TIMER, EV_ADD|EV_ONESHOT,
NOTE_USECONDS, 0, (void *) nch); nch++;
for (unsigned i = 0; i < nch; i++)
logKEvent(&timers[i], i, "timers");
bool seenLong = false, seenShort = false;
const struct kevent *chList = timers;
do
{
struct kevent evList;
bzero(&evList, sizeof(evList));
int nev = kevent(kq, chList, (int) nch, &evList, 1, NULL);
nch = 0; chList = NULL; // Disable the change list
logKEvent(&evList, 0, "kev"); // Log the event
assert(nev == 1);
assert(evList.filter == EVFILT_TIMER);
uintptr_t udata = (uintptr_t) evList.udata;
if (udata == 0)
seenLong = true;
else if (udata == 1)
seenShort = true;
else
assert(false);
} while ( !seenLong || !seenShort );
}
static void logKEvent(const struct kevent *kep, int ind, const char * const pfx)
{
static const char *sFilterNames[] = {
"EVNULL", "EVFILT_READ", "EVFILT_WRITE", "EVFILT_AIO",
"EVFILT_VNODE", "EVFILT_PROC", "EVFILT_SIGNAL", "EVFILT_TIMER",
"EVFILT_MACHPORT", "EVFILT_FS", "EVFILT_USER", "EVFILT_SESSION"
};
// 1 2 3 4 5 6 7
// 12345678901234567890123456789012345678901234567890123456789012345678901234567
// ADD|DELETE|ENABLE|DISABLE|ONESHOT|CLEAR|RECEIPT|DISPATCH|BAD0x0100|BAD0x0200|
// 8 9 10 11
// 890123456789012345678901234567890123456789
// BAD0x0400|BAD0x0800|FLAG1|FLAG2|ERROR|EOF0
#define kMaxFlagCharacters 119
static const char *sFlagNames[] = {
"ADD", "DELETE", "ENABLE", "DISABLE",
"ONESHOT", "CLEAR", "RECEIPT", "DISPATCH",
"BAD0x0100", "BAD0x0200", "BAD0x0400", "BAD0x0800",
"FLAG1", "FLAG2", "ERROR", "EOF"
};
char flagBuffer[kMaxFlagCharacters], *cp = flagBuffer;
int cc;
#define kNumFilterNames (sizeof(sFilterNames)/sizeof(sFilterNames[0]))
#define kNumFlagNames (sizeof(sFlagNames) /sizeof(sFlagNames[0]))
#define kNumFlagChars (sizeof(flagBuffer) /sizeof(flagBuffer[0]))
cp[0] = '\0';
for (size_t i = 0; i < kNumFlagNames; i++)
{
cc = 0;
if ( kep->flags & (1 << i) )
cc = sprintf(cp, "%s|", sFlagNames[i]);
cp += cc;
}
cp[-1] = '\0'; // Overwrite trailing |
assert(cp < &flagBuffer[kNumFlagChars]);
unsigned filter = - kep->filter; assert(filter < kNumFilterNames);
struct timeval delta; gettimeofday(&delta, NULL);
timersub(&delta, &sStart, &delta);
fprintf(stderr, "%7ldus: %s[%d] = { %ld, %s, %s, %x, %ld }\n",
delta.tv_sec * 1000 * 1000 + delta.tv_usec,
pfx, ind, kep->ident, sFilterNames[filter], flagBuffer,
kep->fflags, kep->data);
}
_______________________________________________
Do not post admin requests to the list. They will be ignored.
Darwin-kernel mailing list (email@hidden)
Help/Unsubscribe/Update your Subscription:
This email sent to email@hidden