Skip to content

Commit

Permalink
core: fix bogus "delay in execution" warnings
Browse files Browse the repository at this point in the history 
 - time ijiffies are adjusted by the time_keeper process
 - when the trigger time for a time job is set right
   before adjusting the ijiffies and the processing
   of the timer job is done right after the ijiffies
   adjustment, there's an artificial delay (the ijiffies
   adjutment) that triggers a bogus "delay in execution"
   warning
 - by taking into consideration the ijiffies adjutment
   we avoid printing the bogus "delay in execution" warning
  • Loading branch information
@ovidiusas
ovidiusas committed Apr 27, 2022
1 parent 1f08266 commit 2fc6bb0
Showing 1 changed file with 76 additions and 10 deletions.
86 changes: 76 additions & 10 deletions timer.c
View file
Expand Up @@ -62,7 +62,7 @@
/* define internal timer to 10 milliseconds */
#define ITIMER_TICK 10000

/* try to synchronize with system time every 5 seconds */
/* try to synchronize with system time every 5 second(s) */
#define TIMER_SYNC_TICKS 5000000

/* synchronize if drift is greater than internal timer tick */
Expand All @@ -77,6 +77,8 @@ static struct os_timer *utimer_list = NULL;
static unsigned int *jiffies=0;
static utime_t *ujiffies=0;
static utime_t *ijiffies=0;
static utime_t *ijiffies_drift=0;
static utime_t *ijiffies_drift_base=0;
static unsigned short timer_id=0;
static int timer_pipe[2];
static struct scaling_profile *s_profile=NULL;
Expand Down Expand Up @@ -111,8 +113,11 @@ int init_timer(void)
jiffies = shm_malloc(sizeof(unsigned int));
ujiffies = shm_malloc(sizeof(utime_t));
ijiffies = shm_malloc(sizeof(utime_t));
ijiffies_drift = shm_malloc(sizeof(utime_t));
ijiffies_drift_base = shm_malloc(sizeof(utime_t));

if (jiffies==0 || ujiffies==0 || ijiffies==0 ){
if (jiffies==0 || ujiffies==0 || ijiffies==0 ||
ijiffies_drift==0 || ijiffies_drift_base==0){
LM_CRIT("could not init jiffies\n");
return E_OUT_OF_MEM;
}
Expand All @@ -130,6 +135,8 @@ int init_timer(void)
*jiffies=0;
*ujiffies=0;
*ijiffies=0;
*ijiffies_drift=0;
*ijiffies_drift_base=0;

/* create the pipe for dispatching the timer jobs */
if ( pipe(timer_pipe)!=0 ) {
Expand Down Expand Up @@ -455,7 +462,7 @@ static void run_timer_process( void )
multiple = (( TIMER_TICK * 1000000 ) / UTIMER_TICK ) / 1000000;
}

LM_DBG("tv = %ld, %ld , m=%d\n",
LM_DBG(" tv = %ld, %ld, m=%d\n",
(long)o_tv.tv_sec,(long)o_tv.tv_usec,multiple);

drift = 0;
Expand Down Expand Up @@ -539,7 +546,7 @@ static void run_timer_process_jif(void)
multiple = ((TIMER_TICK*1000000)) / (UTIMER_TICK);
umultiple = (UTIMER_TICK) / (ITIMER_TICK);

LM_DBG("tv = %ld, %ld , m=%d, mu=%d\n",
LM_DBG("tv = %ld, %ld, m=%d, mu=%d\n",
(long)o_tv.tv_sec,(long)o_tv.tv_usec,multiple,umultiple);

gettimeofday(&last_ts, 0);
Expand Down Expand Up @@ -587,7 +594,9 @@ static void run_timer_process_jif(void)
}

if (drift > TIMER_MAX_DRIFT_TICKS) {
*(ijiffies_drift_base) = *(ijiffies);
*(ijiffies) += (drift / ITIMER_TICK) * ITIMER_TICK;
*(ijiffies_drift) = (drift / ITIMER_TICK) * ITIMER_TICK;

ucnt += drift / ITIMER_TICK;
*(ujiffies) += (ucnt / umultiple) * (UTIMER_TICK);
Expand Down Expand Up @@ -839,6 +848,7 @@ void handle_timer_job(void)
{
struct os_timer *t;
ssize_t l;
utime_t _ijiffies,_ijiffies_drift_base,_ijiffies_drift;

/* read one "os_timer" pointer from the pipe (non-blocking) */
l = read( timer_fd_out, &t, sizeof(t) );
Expand All @@ -849,20 +859,76 @@ void handle_timer_job(void)
return;
}


/*
Scheduling and handling of the timer task happens without drifting
==================================================================
[time_keeper proc] *ijiffies increments:
V ITIMER_TICK V ITIMER_TICK V
->|<----------------------------->|<------------------------------->|<--
+ITIMER_TICK +ITIMER_TICK +ITIMER_TICK
[timer proc] ^schedule timer job
t->trigger_time
[Timer handler proc] ^handling timer job
The timer task was scheduled before a drift adjustement
=======================================================
[time_keeper proc] *ijiffies increments:
V ITIMER_TICK V ITIMER_TICK V
->|<----------------------------->|<----------->|<----------------->|<--
+ITIMER_TICK +ITIMER_TICK +DRIFT +ITIMER_TICK
^*ijifies_drift_base
[timer proc] ^schedule timer job || ^schedule timer job
t->trigger_time
[Timer handler proc] ^handling timer job
*/

/* Cache the entry values for jiffies */
_ijiffies = *ijiffies;
_ijiffies_drift_base = *ijiffies_drift_base;
_ijiffies_drift = *ijiffies_drift;

/* run the handler */
if (t->flags&TIMER_FLAG_IS_UTIMER) {

if (t->trigger_time<(*ijiffies-ITIMER_TICK) )
LM_WARN("utimer job <%s> has a %lld us delay in execution\n",
t->label, *ijiffies-t->trigger_time);
if (t->trigger_time > _ijiffies_drift_base) {
/* We read from the queue before a drift was detected
*/
if (t->trigger_time<(_ijiffies-ITIMER_TICK) ) {
LM_WARN("utimer job <%s> has a %lld us delay in execution: trigger_time=%lld ijiffies=%lld ijiffies_drift_base=%lld ijiffies_drift=%lld\n",
t->label, _ijiffies-t->trigger_time, t->trigger_time, _ijiffies, _ijiffies_drift_base, _ijiffies_drift);
}
} else {
/* We read from the queue after or while a drift was detected
*/
if (t->trigger_time<(_ijiffies-_ijiffies_drift-ITIMER_TICK) ) {
LM_WARN("utimer job <%s> has a %lld us delay in execution: trigger_time=%lld ijiffies=%lld ijiffies_drift_base=%lld ijiffies_drift=%lld\n",
t->label, _ijiffies-t->trigger_time-_ijiffies_drift, t->trigger_time, _ijiffies, _ijiffies_drift_base, _ijiffies_drift);
}
}

t->u.utimer_f( t->time , t->t_param);
t->trigger_time = 0;

} else {

if (t->trigger_time<(*ijiffies-ITIMER_TICK) )
LM_WARN("timer job <%s> has a %lld us delay in execution\n",
t->label, *ijiffies-t->trigger_time);
if (t->trigger_time > _ijiffies_drift_base) {
/* We read from the queue before a drift was detected
*/
if (t->trigger_time<(_ijiffies-ITIMER_TICK) ) {
LM_WARN("timer job <%s> has a %lld us delay in execution trigger_time=%lld ijiffies=%lld ijiffies_drift_base=%lld ijiffies_drift=%lld\n",
t->label, _ijiffies-t->trigger_time, t->trigger_time, _ijiffies, _ijiffies_drift_base, _ijiffies_drift);
}
} else {
/* We read from the queue after or while a drift was detected
*/
if (t->trigger_time<(_ijiffies-_ijiffies_drift-ITIMER_TICK) ) {
LM_WARN("timer job <%s> has a %lld us delay in execution trigger_time=%lld ijiffies=%lld ijiffies_drift_base=%lld ijiffies_drift=%lld\n",
t->label, _ijiffies-t->trigger_time-_ijiffies_drift, t->trigger_time, _ijiffies, _ijiffies_drift_base, _ijiffies_drift);
}
}

t->u.timer_f( (unsigned int)t->time , t->t_param);
t->trigger_time = 0;

Expand Down

0 comments on commit 2fc6bb0

Please sign in to comment.