POSIX timer runs at twice the expected frequency

Question

In order to create a high accuracy timer, I have written a module that instantiates a POSIX timer using the timer_create() function. It uses CLOCK_REALTIME as its clock kind, SIGEV_SIGNAL as notification method and SIGRTMIN as the signal number. Its signal handler does nothing but a sem_post(). The timer is started using timer_settime(), with any number of milliseconds as the timer interval.

The user of the module can wait for a timer-tick; the wait functionality is essentially implemented by a sem_wait(). My single-threaded test application creates the timer and starts it with the desired interval of i milliseconds. Then it loops, waiting x times for the timer to trigger. It uses gettimeofday() to time all this.

The expectation is that the total time for the loop would be x*i milliseconds. In stead, it only takes exactly 0.5*x*i milliseconds. I have tried several combinations of x and i, with the total execution time of the test ranging from a few seconds to tens of seconds. The result is consistently that the timer runs at twice the expected/desired frequency.

This runs on CentOS 5.5 Linux 2.6.18-194.el5 #1 SMP Fri Apr 2 14:58:14 EDT 2010 x86_64 x86_64 x86_64 GNU/Linux with gcc 4.1.2

---

I have uploaded a stripped down version of the code which includes a script to compile the code and a test to reproduce the issue.

The code of the timer class itself is as follows:

/* PosixTimer: simple class for high-accuracy timer functionality */

/* Interface */
#include "PosixTimer.h"

/* Implementation */

#include <pthread.h>
#include <time.h>
#include <signal.h>
#include <semaphore.h>
#include <stdlib.h>
#include <string.h>
#include <stdio.h>

#define TIMER_SIGNAL SIGRTMIN
#define ALLOCATE_AND_CLEAR(pVar)  \
    pVar = malloc(sizeof(*pVar)); \
    memset(pVar, 0, sizeof(*pVar))
#define FREE_AND_NULL(pVar) \
    free(pVar); \
    pVar = NULL

struct PosixTimerImpl {
    timer_t           timerId;
    struct itimerspec timeOut;
    sem_t             semaphore;
};


static void
PosixTimer_sigHandler(
    int sig,
    siginfo_t *info,
    void *ptr)
{
    PosixTimer *self = (PosixTimer *)(info->si_value.sival_ptr);

    if (NULL != self) {
        sem_post(&self->semaphore);
    }
}

static void
PosixTimer_setTimeoutValue(
    PosixTimer *self,
    unsigned int msecInterval)
{
    if (NULL != self) {
        self->timeOut.it_value.tv_sec = msecInterval / 1000;
        self->timeOut.it_value.tv_nsec = (msecInterval % 1000) * 1000000;
        self->timeOut.it_interval.tv_sec = msecInterval / 1000;
        self->timeOut.it_interval.tv_nsec = (msecInterval % 1000) * 1000000;
    }
}

/* Public methods */

/**
 * Constructor for the PosixTimer class. Ticks happen every <interval> and are not queued
 */
PosixTimer *
PosixTimer_new(
    unsigned int msecInterval)
{
    PosixTimer *self = NULL;

    int clockId = CLOCK_REALTIME;
    struct sigevent evp;
    int status;

    /* Construction */

    ALLOCATE_AND_CLEAR(self);

    /* Initialization */

    PosixTimer_setTimeoutValue(self, msecInterval);

    evp.sigev_signo = TIMER_SIGNAL;
    evp.sigev_notify = SIGEV_SIGNAL;
    evp.sigev_value.sival_ptr = self;
    status = timer_create(clockId, &evp, &self->timerId);
    if (0 == status) {
        sem_init(&self->semaphore, 0, 0);
    } else {
        printf("Error creating timer, retVal = %d\n", status);
        FREE_AND_NULL(self);
    }
    return self;
}


/**
 * Destructor
 */
void
PosixTimer_delete(
    PosixTimer *self)
{
    int status;

    sem_post(&self->semaphore);
    status = sem_destroy(&self->semaphore);
    if (0 != status) {
        printf("sem_destroy failed\n");
    }
    status = timer_delete(self->timerId);
    if (0 != status) {
        printf("timer_delete failed\n");
    }
    FREE_AND_NULL(self);
}


/**
 * Kick off timer
 */
void
PosixTimer_start(
    PosixTimer *self)
{
#define FLAG_RELATIVE 0
    int status;
    struct sigaction sa;

    sigemptyset(&sa.sa_mask);
    sigaddset(&sa.sa_mask, TIMER_SIGNAL);
    sa.sa_flags = SA_SIGINFO;
    sa.sa_sigaction = PosixTimer_sigHandler;
    status = sigaction(TIMER_SIGNAL, &sa, NULL);
    if (0 != status) {
        printf("sigaction failed\n");
    } else {
        status = timer_settime(self->timerId, FLAG_RELATIVE,
                    &self->timeOut, NULL);
        if (0 != status) {
            printf("timer_settime failed\n");
        }
    }
}


/**
 * Wait for next timer tick
 */
void
PosixTimer_wait(
    PosixTimer *self)
{
    /* Just wait for the semaphore */
    sem_wait(&self->semaphore);
}

The test used to show the issue:

/* Simple test app to test PosixTimer */

#include "PosixTimer.h"
#include <sys/time.h>
#include <stdio.h>

int main(
    int argc,
    const char ** argv)
{

#define USEC_PER_MSEC (1000)
#define NSEC_PER_MSEC (1000000)
#define MSEC_PER_SEC  (1000)

    PosixTimer *timer1 = NULL;
    struct timeval before, after;
    double dElapsedMsecs;
    int elapsedMsecs;
    int iCount1;

    printf("Running PosixTimer tests\n");

#define DURATION_MSEC (10000)
#define INTERVAL_MSEC_TEST1 (5)
#define ACCURACY_MSEC_TEST1 (100)


    timer1 = PosixTimer_new(INTERVAL_MSEC_TEST1);
    iCount1 = DURATION_MSEC/INTERVAL_MSEC_TEST1;
    printf("Running test: %d milliseconds in %d cycles\n", DURATION_MSEC, iCount1);

    gettimeofday(&before, NULL);
    PosixTimer_start(timer1);
    while (0 < iCount1) {
        PosixTimer_wait(timer1);
        //printf(".");
        iCount1--;
    }
    gettimeofday(&after, NULL);
    //printf("\n");

    dElapsedMsecs = (after.tv_sec - before.tv_sec) * MSEC_PER_SEC;
    dElapsedMsecs += (after.tv_usec - before.tv_usec) / USEC_PER_MSEC;
    elapsedMsecs = dElapsedMsecs+0.5;

    if ((ACCURACY_MSEC_TEST1 > (elapsedMsecs - DURATION_MSEC)) &&
        (ACCURACY_MSEC_TEST1 > (DURATION_MSEC - elapsedMsecs))) {
        printf("success");
    } else {
        printf("failure");
    }
    printf(" (expected result in range (%d -- %d), got %d)\n", 
        DURATION_MSEC - ACCURACY_MSEC_TEST1,
        DURATION_MSEC + ACCURACY_MSEC_TEST1,
        elapsedMsecs);

    return 0;
}

The result is

-bash-3.2$ ./DesignBasedTest 
Running PosixTimer tests
Running test: 10000 milliseconds in 2000 cycles
failure (expected result in range (9900 -- 10100), got 5000)

Answer 1

The root cause of this problem was that sem_wait() was woken up twice: once because it was interrupted by the signal, and once because it really needed to wake up due to the semaphore being released by sem_post(). Checking for the return value of sem_wait() and errno = EINTR resolved the issue:

/**
 * Wait for next timer tick
 */
int
PosixTimer_wait(
    PosixTimer *self)
{
    int result;

    /* Just wait for the semaphore */
    do {
        result = (0 == sem_wait(&self->semaphore));
        if (!result) {
            result = errno;
        }
    } while (EINTR == result);
    return result;
}

Thanks to Basile Starynkevitch for suggesting the use of strace, which revealed the cause of the problem.