Hi,
I tracked down the timing problem even more and write another piece of testing code (see below). The code should just do something each 20ms. I discovered that using printf() in critical section is not a good idea as it introduces unwanted delay that is not calculated in the timeout. You can test it by setting DO_PRINTF to 1.
However, if no printf()'s are performed I still do not get a precise delay of 20ms +/- 1ms (even with realtime priority). See example output here:
---------------------------------------------------------------------- $ sudo nice -n-19 ./test-timer
delay[ 0]: 0.007194ms delay[ 1]: 21.125031ms --> thats too long :( delay[ 2]: 20.112892ms delay[ 3]: 20.113100ms delay[ 4]: 20.121551ms delay[ 5]: 22.959203ms --> thats too long :( delay[ 6]: 20.131611ms delay[ 7]: 20.145507ms delay[ 8]: 20.131889ms delay[ 9]: 20.145649ms delay[10]: 20.142365ms ----------------------------------------------------------------------
* How can I deal with the problem ? * Where does the unwanted delay come from ?
cheers, stefan
---------------------------- timer-test.c ---------------------------- #define _POSIX_C_SOURCE 199309L #define _BSD_SOURCE
#include <stdio.h> #include <stdlib.h> #include <time.h> #include <unistd.h> #include <sys/types.h> #include <sys/socket.h> #include <sys/un.h> #include <string.h> #include <errno.h> #include <pthread.h> #include <poll.h> #include <assert.h>
#define DELAYSTAMPS 30 #define DO_PRINTF 0
/* adapted from glibc sys/time.h timersub() macro */ #define priv_timespecsub(a, b, result) \ do { \ (result)->tv_sec = (a)->tv_sec - (b)->tv_sec; \ (result)->tv_nsec = (a)->tv_nsec - (b)->tv_nsec; \ if ((result)->tv_nsec < 0) { \ --(result)->tv_sec; \ (result)->tv_nsec += 1000000000; \ } \ } while (0)
#define priv_timespecadd(a, b, result) \ do { \ (result)->tv_sec = (a)->tv_sec + (b)->tv_sec; \ (result)->tv_nsec = (a)->tv_nsec + (b)->tv_nsec; \ if ((result)->tv_nsec >=1000000000L) { \ ++(result)->tv_sec; \ (result)->tv_nsec -= 1000000000L; \ } \ } while (0)
pthread_mutex_t timer_mutex = PTHREAD_MUTEX_INITIALIZER; pthread_cond_t timer_condition = PTHREAD_COND_INITIALIZER;
int main(void) { int t, len, ret; struct timespec start, now, period_time, delta, timeout; struct timespec prev, delta_prev; double delaystamps[DELAYSTAMPS]; int i;
// one period is 20ms period_time.tv_sec=0; period_time.tv_nsec = 20 * 1000000L;
start.tv_sec=0; start.tv_nsec=0;
clock_gettime(CLOCK_REALTIME, &start);
for (i=0; i<DELAYSTAMPS; i++) { memcpy(&prev, &start, sizeof(struct timespec)); clock_gettime(CLOCK_REALTIME, &start);
priv_timespecadd(&start, &period_time, &timeout); //printf("timeout at %li:%li\n", timeout.tv_sec, timeout.tv_nsec/1000000L);
priv_timespecsub(&start, &prev, &delta_prev);
#if (DO_PRINTF==1) printf("last action %fms ago\n", delta_prev.tv_sec*1000.0 + delta_prev.tv_nsec/1000000.0); #endif
delaystamps[i]=delta_prev.tv_sec*1000.0 + delta_prev.tv_nsec/1000000.0;
// -------------------------- BEGIN PROCESSING BLOCK --------------------------
// process data (requires some amount of time) usleep(10000);
// -------------------------- END PROCESSING BLOCK -------------------------- // sleep for the rest of the time until the period is over clock_gettime(CLOCK_REALTIME, &now); priv_timespecsub(&timeout, &now, &delta);
if ((now.tv_sec >= timeout.tv_sec) && (now.tv_nsec >= timeout.tv_nsec)) { //printf("we're late, don't sleep\n"); } else { #if (DO_PRINTF==1) printf("sleeping for %lims\n", delta.tv_sec*1000 + delta.tv_nsec/1000000L); #endif //nanosleep(&delta, NULL);
// wait for timeout using a fake pthread condition which is never signaled pthread_mutex_lock(&timer_mutex); pthread_cond_timedwait(&timer_condition, &timer_mutex, &timeout); pthread_mutex_unlock(&timer_mutex); }
}
// print delay timestamps for (i=0; i<DELAYSTAMPS; i++) { printf("delay[%2i]: %fms", i, delaystamps[i]); if (delaystamps[i] > 21) printf("\t--> thats too long :("); printf("\n"); }
return 0; }
----------------------------------------------------------------------