[Libevent-users] Strange timeout scheduling in 1.4

[Leonid Evdokimov <leon@xxxxxxxxxxxx>]

Hello all,

I assumed, that timeout is never(!) scheduled a-bit-earlier than
requested and today I see, that either my assumption is wrong, or I
became a bit insane while writing the code.

I attached simple test for the assertion. For example, I've got
following strange results:

$ ./event-timeout
Diff: -1333 us (-1333956 ns) during 4424-th fired event.

$ ./event-timeout
Diff: -567 us (-568056 ns) during 8676-th fired event.

I run 2.6.38-10-generic x86_64 with libevent 1.4.13-stable-1 from
Ubuntu 11.04 (natty) and epoll backend on Intel(R) Core(TM) i7-2620M
CPU @ 2.70GHz CPU.

I build the test-case like that:
$ gcc event-timeout.c -o event-timeout -levent

I get same result with -O2 compilation flag.

Am I missing some sort of race-condition in my code? Is it bug in
libevent or expected behavior?

--
WBRBW, Leonid Evdokimov
xmpp:leon@xxxxxxxxxxxx && http://darkk.net.ru
tel:+79816800702 && tel:+79050965222

#include <event.h>
#include <sys/time.h>
#include <time.h>
#include <stdio.h>
#include <string.h>

struct timeval delay = {0, 100*1000};
int64_t fired = 0;

struct foo {
    struct event ev_timeout;
    struct timeval  last_lo;
    struct timespec last_hi;
};

#define i9(hi) ((hi).tv_sec * 1000*1000*1000 + (hi).tv_nsec)
#define i6(lo) ((lo).tv_sec * 1000*1000 + (lo).tv_usec)

void rearm(struct foo* f)
{
    gettimeofday(&f->last_lo, 0);
    clock_gettime(CLOCK_MONOTONIC, &f->last_hi);

    timeout_add(&f->ev_timeout, &delay);   
}

void timeout_cb(int fd, short event, void* foo_)
{
    struct foo* f = foo_;
    struct timeval now_lo;
    struct timespec now_hi;

    clock_gettime(CLOCK_MONOTONIC, &now_hi);
    gettimeofday(&now_lo, 0);
    fired++;

    if ((fired % 25000) == 0)
        printf("Fired %ld events.\n", fired);

    int64_t inow_hi = i9(now_hi);
    int64_t inow_lo = i6(now_lo);

    int64_t ilast_hi = i9(f->last_hi);
    int64_t ilast_lo = i6(f->last_lo);

    int64_t realdelay_hi = inow_hi - ilast_hi;
    int64_t realdelay_lo = inow_lo - ilast_lo;

    int64_t idiff_hi = realdelay_hi - i6(delay)*1000;
    int64_t idiff_lo = realdelay_lo - i6(delay);

    const int dead_ms = 10000;
    if (idiff_lo < 0 || dead_ms < idiff_lo || idiff_hi < 0 || dead_ms*1000 < idiff_hi) {
        printf("Diff: %ld us (%ld ns) during %ld-th fired event.\n", idiff_lo, idiff_hi, fired);
        event_loopbreak();
    }
    rearm(f);
}

int main()
{
    const size_t count = 4 * 1024;
    struct foo f[count];
    size_t i;

    memset(f, 0, sizeof(f));
    event_init();
    for (i = 0; i < count; i++) {
        timeout_set(&f[i].ev_timeout, timeout_cb, f+i);
        rearm(f+i);
    }
    event_dispatch();
}