Signal Handler's Random Large Delay

[rrojas1979]

All,

I am setting up a 30 Hz POSIX clock to be used as an interval timer that generates SIGALRM. I am then setting a signal handler to be called on SIGALRM.

My signal handler function logs timestamps using gettimeofday() and at the end of my test run prints out the time stamps in addition to deltas so I can confirm the period of the signal handler.

The problem is that sometimes I am seeing deltas in the 700 ms range, which cause my tests to fail because quite obviously the signal handler isn't being called the expected amount of times for an X-second test run.

Before the tests are run, I am moving my process to the SCHED_FIFO scheduling policy and setting its priority to the highest number. My process also never yields the processor.

Following is the relevant code:

int posix_timer_test(const int test_period, const int timer_freq)
{
...
/* Set notification event: */
     event.sigev_notify = SIGEV_SIGNAL;           
     event.sigev_signo = SIGALRM;                 
     event.sigev_value.sival_ptr = &tid;
     event.sigev_notify_attributes = NULL;
     
     /* Set up signal handler: */
     sigemptyset(&sact.sa_mask);     
     sact.sa_flags = 0;
     sact.sa_handler = posix_test_sighandler;
     sigaction(SIGALRM, &sact, NULL);
     
     /* Set up POSIX timer: */
     ptimer.it_interval.tv_sec = 0;
     ptimer.it_interval.tv_nsec = ns_period;
     ptimer.it_value.tv_sec = INIT_DELAY;
     ptimer.it_value.tv_nsec = 0;
     
     timer_create(CLOCK_SRC, &event, &tid);
...
/* Get test start time: */
     if( gettimeofday(&test_start, NULL) < 0 )
     {
          return 0;
     }
     
     /* Start timer */
     timer_settime(tid, 0, &ptimer, NULL);
     
     /* Loop until test_cur.tv_sec - test_start.tv_sec = test_period */
     if( gettimeofday(&test_cur, NULL) < 0 )
     {
          timer_settime(tid, 0, &cancel, NULL);/* cancel itimer */
          return 0;
     }
     
     /* Loop for test_period + INIT_DELAY */
     while( (elapsed_time(&test_start, &test_cur) >> 10) < (test_period + INIT_DELAY) )
     {
          if( gettimeofday(&test_cur, NULL) < 0 )
          {
               timer_settime(tid, 0, &cancel, NULL);/* cancel itimer */
               return 0;
          }
     }
     
     /* Test complete cancel timer */
     timer_settime(tid, 0, &cancel, NULL);
...
}

And my signal handler:

void posix_test_sighandler(int sig)
{
     /* For this functional test, ensure that this function stops modifying timer_test_count */
     /* to compensate for any latency incurred by timer_test() in canceling the timer.       */
     if( timer_test_count < timer_test_exp_count )
     {
          //ptimer_overrun[timer_test_count] = timer_getoverrun(tid);
          gettimeofday(&t_stamp[timer_test_count++], NULL);
     }
}

Any help would be appreciated as to why I am seeing random deltas of 700 ms between two signal handler calls.

Thanks.

[wje_lf]

It would be helpful if you had a complete, compilable, runnable program which demonstrates your problem. That way we could play with it if we wished, and even if we didn't, it would allow us to do a more thorough job of looking for a problem.

For example, what's this business with timer_test_count and with t_stamp[]? Are you aware that you could be in the middle of accessing those two items in your main program while your signal handler is changing them? Is this of interest to you?

[rrojas1979]

Thanks for your reply.

If you look at the while loop under the comment "/* Loop for test_period + INIT_DELAY */", you will see that there are no race conditions for those global variables during the execution loop.

As far as a whole compilable program, the best I could give you is the full test function + signal handler code since I am running this via a unit test harness.

#include <stdio.h>      /* Standard I/O                        */
#include <string.h>     /* String functions.                   */
#include <termios.h>    /* POSIX terminal control definitions. */
#include <unistd.h>     /* UNIX standard function definitions. */
#include <sys/select.h> /* POSIX select functions and types.   */
#include <sys/time.h>   /* BSD Unix time functions.            */
#include <time.h>       /* POSIX time functions.               */
#include <signal.h>     /* Signals.                            */
#include <sched.h>      /* Scheduling functions.               */
#include <errno.h>      /* Errors.                             */

int timer_test_count;             /**< Signal test count variable. Global for sig handler access.       */
int timer_test_exp_count;         /**< Signal test expected count value. Global for sig handler access. */
timer_t tid;                      /**< POSIX timer ID.                                                  */

struct timeval t_stamp[108000];   /* DEBUG */
int ptimer_overrun[108000];       /* DEBUG */

int posix_timer_test(const int test_period, const int timer_freq)
{
     const int CLOCK_SRC = CLOCK_REALTIME;  /**< POSIX clock source.    */
     const int CPS = timer_freq;        /**< Defining counts per second rate.                    */ 
     const int INIT_DELAY = 1;          /**< Defining the initial delay (secs) before first sig. */
     unsigned long ns_period;           /**< Timer period in nsecs.                              */
     struct sigevent event;             /**< Sig event struct.                                   */
     struct sigaction sact;             /**< Sig action struct.                                  */
     struct itimerspec ptimer;          /**< POSIX interval timer structure.                     */
     struct itimerspec cancel;          /**< POSIX interval timer struct used to disable timer.  */
     struct timeval test_start;         /**< Test start time.                                    */
     struct timeval test_cur;           /**< Current test time.                                  */
     FILE *tlog;                        /* DEBUG */
     int i;                             /* DEBUG */
     int last_valid = 0;                /* DEBUG */  
     int delta = 0;                     /* DEBUG */
     int max_delta = 0;                 /* DEBUG */
     int min_delta = 999;               /* DEBUG */
     unsigned long ms_per_flag;         /* DEBUG */
     int runtime;                       /* DEBUG */
     int range;                         /* DEBUG */
     
     /* Calculate the usec period value: */
     ns_period = (unsigned long)( ((float)1/(float)timer_freq) * (float)1000000000 ); 
     
     /* Set notification event: */
     event.sigev_notify = SIGEV_SIGNAL;           /* SIGEV_SIGNAL, SIGEV_NONE, or SIGEV_THREAD */
     event.sigev_signo = SIGALRM;                 /* Set signal to be generated as SIGALRM     */
     event.sigev_value.sival_ptr = &tid;
     event.sigev_notify_attributes = NULL;
     
     /* Set up signal handler: */
     sigemptyset(&sact.sa_mask);     
     sact.sa_flags = 0;
     sact.sa_handler = posix_test_sighandler;
     sigaction(SIGALRM, &sact, NULL);
     
     /* Set up POSIX timer: */
     ptimer.it_interval.tv_sec = 0;
     ptimer.it_interval.tv_nsec = ns_period;
     ptimer.it_value.tv_sec = INIT_DELAY;
     ptimer.it_value.tv_nsec = 0;
     
     timer_create(CLOCK_SRC, &event, &tid);
     
     /* Initialize current test time struct: */
     test_cur.tv_sec = 0;
     test_cur.tv_usec = 0;
     
     /* Initialize the cancel timer struct: */
     cancel.it_value.tv_sec = 0;
     cancel.it_value.tv_nsec = 0;
     
     timer_test_count = 0;                          /* Set current timer test count  */
     timer_test_exp_count = (CPS * test_period);    /* Set expected timer test count */

     memset(t_stamp, 0, sizeof(t_stamp));           /* Clear the time stamp array.   */
     memset(ptimer_overrun, 0, sizeof(ptimer_overrun));
     
     /* Get test start time: */
     if( gettimeofday(&test_start, NULL) < 0 )
     {
          return 0;
     }
     
     /* Start timer */
     timer_settime(tid, 0, &ptimer, NULL);
     
     /* Loop until test_cur.tv_sec - test_start.tv_sec = test_period */
     if( gettimeofday(&test_cur, NULL) < 0 )
     {
          timer_settime(tid, 0, &cancel, NULL);/* cancel itimer */
          return 0;
     }
     
     /* Loop for test_period + INIT_DELAY */
     while( (elapsed_time(&test_start, &test_cur) >> 10) < (test_period + INIT_DELAY) )
     {
          if( gettimeofday(&test_cur, NULL) < 0 )
          {
               timer_settime(tid, 0, &cancel, NULL);/* cancel itimer */
               return 0;
          }
     }
     
     /* Test complete cancel timer */
     timer_settime(tid, 0, &cancel, NULL);
     
     /* DEBUG Log time stamps to file: */
     tlog = fopen("ptime.txt", "a");

     /* Set the millisecond period flag to be us_period + 30%: */
     ms_per_flag = (unsigned long)(((float)(ns_period)*1.3)/(float)1000000);
     
     for(i = 0; i < timer_test_exp_count; i++)
     {
          if( i > 0 )
    	  {
    	       delta = elapsed_time(&t_stamp[i-1], &t_stamp[i]);
    	       delta = delta & 0x3FF; /* mask off lower 10 bits for ms value. */
    	       if( (delta < min_delta) && (delta > 0) ) min_delta = delta;
    	       if( (delta > max_delta) && (delta != 1000) ) max_delta = delta;
    	  }
    	           
    	  fprintf(tlog, "%06d: %lu : %lu. delta =%d ms.", i, t_stamp[i].tv_sec, t_stamp[i].tv_usec, delta);
    	  if( (delta > ms_per_flag) && (delta != 1000) )
    	  {
               fprintf(tlog, " <<<<<FLAG>>>>>");
    	  }
    	  fprintf(tlog, "\n");
    	  
          if( (i > 0) && (t_stamp[i].tv_sec == 0 && t_stamp[i].tv_usec == 0) )
          {
               if(last_valid == 0) last_valid = i-1;
          }
     }
     
     if(last_valid == 0) last_valid = i-1;
     
     fprintf(tlog, "test_period = %d sec. exp = %d, actual = %d\n", test_period, timer_test_exp_count, timer_test_count);
     runtime = elapsed_time(&test_start, &test_cur);
     fprintf(tlog, "test start  = %lu : %lu. tes end    = %lu : %lu. runtime = %d.%d sec\n", test_start.tv_sec, test_start.tv_usec, \
         		                                                              test_cur.tv_sec, test_cur.tv_usec, \
         		                                                              (runtime >> 10), \
         		                                                              (runtime & 0x3FF));
     range = elapsed_time(&t_stamp[0], &t_stamp[last_valid]);
     fprintf(tlog, "first valid = %lu : %lu. last valid = %lu : %lu. range = %d.%d sec\n", \
    		                                               t_stamp[0].tv_sec, t_stamp[0].tv_usec, \
    		                                               t_stamp[last_valid].tv_sec, t_stamp[last_valid].tv_usec, \
    		                                               (range >> 10), \
    		                                               (range & 0x3FF));
     fprintf(tlog, "min delta = %d ms, max delta = %d ms\n\n\n\n", min_delta, max_delta);
     
     fclose(tlog);
     
     /* END DEBUG */
     
     return timer_test_count;
}

void posix_test_sighandler(int sig)
{
     /* For this functional test, ensure that this function stops modifying timer_test_count */
     /* to compensate for any latency incurred by timer_test() in canceling the timer.       */
     if( timer_test_count < timer_test_exp_count )
     {
          ptimer_overrun[timer_test_count] = timer_getoverrun(tid);
          gettimeofday(&t_stamp[timer_test_count++], NULL);
     }
}

unsigned long elapsed_time(const struct timeval* const start, const struct timeval* const cur)
{
     const unsigned long MAX_ELAPSED_SECS = 4194303;   /**< Max elapsed seconds measurable. */
     unsigned long msecs = 0;                          /**< Calculated elapsed msecs.       */
     unsigned long secs = 0;                           /**< Calculated elapsed secs.        */
     unsigned long counts = ETIME_ERR;                 /**< Encoded count value to return.  */
	
     /* If current seconds are less than start secconds, auto-error */
     if( start->tv_sec > cur->tv_sec )
     {
          return counts;
     }
     
     /* If seconds are equal, check to see that current usecs are GT start usecs */
     if( (start->tv_sec == cur->tv_sec) && (start->tv_usec > cur->tv_usec) )
     {
          return counts;
     }
     
     /* Check to see if seconds goes over our limit: */
     secs = cur->tv_sec - start->tv_sec;
     if( secs > MAX_ELAPSED_SECS )
     {
          return counts;
     }
     
     /* Calculate milliseconds: */
     
     /* With this case we can ascertain a +1 second rollover. */
     /* Since by this point in the code, our error checks have guaranteed that */
     /* cur is definitely later in time than start, a case where cur usecs are */
     /* less than start usecs indicates just enough usecs added to start where */
     /* a new second is entered, but not enough to constitute a whole second   */
     /* of elapsed time. Therefore, we must subtract 1 second from our secs    */
     /* calculation above since it was calculated with no regard to the value  */
     /* of the usec pairs.                                                     */
     if( start->tv_usec > cur->tv_usec )
     {
          msecs = ((1000000 - start->tv_usec) + cur->tv_usec)/1000;
          secs--;
     }
     else
     {
          msecs = (cur->tv_usec - start->tv_usec)/1000;
     }
     
     /* Calculate count word:                                                                 */
     /* Shift secs left 10 bits (multiply by 1024) to position into most significant 22 bits  */
     /* and then "drop" msecs count into least significant 10 bits. Voila!                    */
     counts = 0;
     counts = (secs << 10) + msecs;
	
     return counts; 
}

[wje_lf]

Since the program isn't compilable, I'm not inclined to play with it. That would mean that I would have to complete the job of turning it into a free-standing program, and that would be your job. :)

But I looked at the code, and nothing obvious jumps out at me.

If you're dumping data based on the array only after the timing portion of the test is complete, and you know that some of the intervals are in the 700ms range, then maybe you could modify the test so that if the interval is anywhere near huge (say, greater than 100 ms), dump the actual struct timeval values for that interval. Then do the arithmetic by hand to see whether you did it correctly in the program.

The reason I'm suggesting this is that some of your code for handling time and interval values seems a little more complex than it needs to be. Bugs can ensue in such a situation.

I wish I could have helped more, but I'm in the U.S., and I'll be glued to the election returns for the rest of the day. But (since the free-standing program was not available) I did the best I could, and I hope this helps some!