From 1419f3910f22d482e3bdb4c9580b176e62c93a7f Mon Sep 17 00:00:00 2001 From: Joseph Hickey Date: Tue, 22 Oct 2019 22:52:52 -0400 Subject: [PATCH] Fix #271: Correct interval time computations In VxWorks, the sigwait routine was not handling the actual time of the first interval, which basically meant that the start_time was elapsed twice before the first callback was generated. This exposed a few other small but significant details regarding how the intervals were dealt with across all operating systems. For VxWorks and RTEMS, where the timer interval is rounded up to an integer number of ticks, compute the actual interval time and write a debug message in case it is different than the intended value. This makes it more obvious to the user that some application/bsp changes might be necessary to get accurate timing. For all operating systems, the "reset" flag needs to be sampled AFTER the sigwait returns, not before it. This flag gets set when the OS_TimeBaseSet() API is called. Removes an unused POSIX delay routine that was intended to support use of clock_nanosleep() in place of the timer signal. This mode was never usable because OS_TimerCreate always allocates a signal and fails if it cannot do so. This code caused problems/incompatibilities for the sigwait model which IS used, so it needed to be removed. --- src/os/posix/ostimer.c | 63 +++++++++------------------- src/os/rtems/ostimer.c | 49 ++++++++++++++++------ src/os/vxworks/ostimer.c | 69 +++++++++++++++++++++++++++++-- src/tests/timer-test/timer-test.c | 45 ++++++++++++++------ 4 files changed, 154 insertions(+), 72 deletions(-) diff --git a/src/os/posix/ostimer.c b/src/os/posix/ostimer.c index d3d5ae4e0..69dd8bfc7 100644 --- a/src/os/posix/ostimer.c +++ b/src/os/posix/ostimer.c @@ -135,7 +135,7 @@ void OS_TimeBaseUnlock_Impl(uint32 local_id) * Purpose: Local helper routine, not part of OSAL API. * *-----------------------------------------------------------------*/ -static uint32 OS_TimeBase_SoftWaitImpl(uint32 timer_id) +static uint32 OS_TimeBase_SigWaitImpl(uint32 timer_id) { int ret; OS_impl_timebase_internal_record_t *local; @@ -144,57 +144,34 @@ static uint32 OS_TimeBase_SoftWaitImpl(uint32 timer_id) local = &OS_impl_timebase_table[timer_id]; - if (local->reset_flag == 0) - { - interval_time = OS_timebase_table[timer_id].nominal_interval_time; - } - else + ret = sigwait(&local->sigset, &sig); + + if (ret != 0) { - interval_time = OS_timebase_table[timer_id].nominal_start_time; - local->reset_flag = 0; + /* + * the sigwait call failed. + * returning 0 will cause the process to repeat. + */ + interval_time = 0; } - - if (local->assigned_signal == 0) + else if (local->reset_flag == 0) { /* - * If no signal is in use and this function got called, - * just implement it using a software delay. This is the - * least accurate option, but it always works. + * Normal steady-state behavior. + * interval_time reflects the configured interval time. */ - if (interval_time == 0) - { - /* - * Protect against a zero interval time causing a "spin loop" - * In this case sleep for 10ms. - */ - interval_time = 10000; - } - local->softsleep.tv_nsec += 1000 * (interval_time % 1000000); - local->softsleep.tv_sec += interval_time / 1000000; - if (local->softsleep.tv_nsec > 1000000000) - { - local->softsleep.tv_nsec -= 1000000000; - ++local->softsleep.tv_sec; - } + interval_time = OS_timebase_table[timer_id].nominal_interval_time; } - - - do + else { /* - * Note that either of these calls can be interrupted by OTHER signals, - * so it needs to be repeated until it actually returns the proper code. + * Reset/First interval behavior. + * timer_set() was invoked since the previous interval occurred (if any). + * interval_time reflects the configured start time. */ - if (local->assigned_signal == 0) - { - ret = clock_nanosleep(OS_PREFERRED_CLOCK, TIMER_ABSTIME, &local->softsleep, NULL); - } - else - { - ret = sigwait(&local->sigset, &sig); - } + interval_time = OS_timebase_table[timer_id].nominal_start_time; + local->reset_flag = 0; } - while (ret != 0); return interval_time; } /* end OS_TimeBase_SoftWaitImpl */ @@ -453,7 +430,7 @@ int32 OS_TimeBaseCreate_Impl(uint32 timer_id) break; } - OS_timebase_table[timer_id].external_sync = OS_TimeBase_SoftWaitImpl; + OS_timebase_table[timer_id].external_sync = OS_TimeBase_SigWaitImpl; } while (0); diff --git a/src/os/rtems/ostimer.c b/src/os/rtems/ostimer.c index 05154944a..e966d29f0 100644 --- a/src/os/rtems/ostimer.c +++ b/src/os/rtems/ostimer.c @@ -63,6 +63,8 @@ typedef struct uint8 simulate_flag; uint8 reset_flag; rtems_interval interval_ticks; + uint32 configured_start_time; + uint32 configured_interval_time; } OS_impl_timebase_internal_record_t; /**************************************************************************************** @@ -150,10 +152,15 @@ static rtems_timer_service_routine OS_TimeBase_ISR(rtems_id rtems_timer_id, void static uint32 OS_TimeBase_WaitImpl(uint32 local_id) { OS_impl_timebase_internal_record_t *local; - uint32 interval_time; + uint32 tick_time; local = &OS_impl_timebase_table[local_id]; + /* + * Pend for the tick arrival + */ + rtems_semaphore_obtain(local->tick_sem, RTEMS_WAIT, RTEMS_NO_TIMEOUT); + /* * Determine how long this tick was. * Note that there are plenty of ways this become wrong if the timer @@ -163,21 +170,16 @@ static uint32 OS_TimeBase_WaitImpl(uint32 local_id) */ if (local->reset_flag == 0) { - interval_time = OS_timebase_table[local_id].nominal_interval_time; + tick_time = local->configured_interval_time; } else { - interval_time = OS_timebase_table[local_id].nominal_start_time; + tick_time = local->configured_start_time; local->reset_flag = 0; } - /* - * Pend for the tick arrival - */ - rtems_semaphore_obtain(local->tick_sem, RTEMS_WAIT, RTEMS_NO_TIMEOUT); - - return interval_time; + return tick_time; } /* end OS_TimeBase_WaitImpl */ @@ -469,13 +471,34 @@ int32 OS_TimeBaseSet_Impl(uint32 timer_id, int32 start_time, int32 interval_time } else { - if (local->interval_ticks > 0) + local->configured_start_time = (10000 * start_ticks) / OS_SharedGlobalVars.TicksPerSecond; + local->configured_interval_time = (10000 * local->interval_ticks) / OS_SharedGlobalVars.TicksPerSecond; + local->configured_start_time *= 100; + local->configured_interval_time *= 100; + + if (local->configured_start_time != start_time) { - start_ticks = local->interval_ticks; + OS_DEBUG("WARNING: timer %lu start_time requested=%luus, configured=%luus\n", + (unsigned long)timer_id, + (unsigned long)start_time, + (unsigned long)local->configured_start_time); + } + if (local->configured_interval_time != interval_time) + { + OS_DEBUG("WARNING: timer %lu interval_time requested=%luus, configured=%luus\n", + (unsigned long)timer_id, + (unsigned long)interval_time, + (unsigned long)local->configured_interval_time); } - OS_timebase_table[timer_id].accuracy_usec = (start_ticks * 100000) / OS_SharedGlobalVars.TicksPerSecond; - OS_timebase_table[timer_id].accuracy_usec *= 10; + if (local->interval_ticks > 0) + { + OS_timebase_table[timer_id].accuracy_usec = local->configured_interval_time; + } + else + { + OS_timebase_table[timer_id].accuracy_usec = local->configured_start_time; + } } } } diff --git a/src/os/vxworks/ostimer.c b/src/os/vxworks/ostimer.c index ee4b63ac8..9b786ca66 100644 --- a/src/os/vxworks/ostimer.c +++ b/src/os/vxworks/ostimer.c @@ -76,6 +76,9 @@ typedef struct TASK_ID handler_task; timer_t host_timerid; enum OS_TimerState timer_state; + uint32 configured_start_time; + uint32 configured_interval_time; + bool reset_flag; } OS_impl_timebase_internal_record_t; /**************************************************************************************** @@ -153,14 +156,14 @@ static uint32 OS_VxWorks_SigWait(uint32 local_id) OS_impl_timebase_internal_record_t *local; OS_common_record_t *global; uint32 active_id; - uint32 interval_time; + uint32 tick_time; int signo; int ret; local = &OS_impl_timebase_table[local_id]; global = &OS_global_timebase_table[local_id]; active_id = global->active_id; - interval_time = 0; + tick_time = 0; if (active_id != 0 && local->assigned_signal > 0) { @@ -190,11 +193,20 @@ static uint32 OS_VxWorks_SigWait(uint32 local_id) if (ret == OK && signo == local->assigned_signal && global->active_id == active_id) { - interval_time = OS_timebase_table[local_id].nominal_interval_time; + if (local->reset_flag) + { + /* first interval after reset, use start time */ + tick_time = local->configured_start_time; + local->reset_flag = false; + } + else + { + tick_time = local->configured_interval_time; + } } } - return interval_time; + return tick_time; } /* end OS_VxWorks_SigWait */ @@ -354,6 +366,7 @@ int32 OS_TimeBaseCreate_Impl(uint32 timer_id) local->handler_mutex = (SEM_ID)0; local->host_timerid = 0; local->timer_state = OS_TimerRegState_INIT; + local->reset_flag = false; /* * Set up the necessary OS constructs @@ -543,11 +556,59 @@ int32 OS_TimeBaseSet_Impl(uint32 timer_id, int32 start_time, int32 interval_time if (status == OK) { return_code = OS_SUCCESS; + + /* + * VxWorks will round the interval up to the next higher + * system tick interval. Sometimes this can make a substantial + * difference in the actual time, particularly as the error + * accumulates over time. + * + * timer_gettime() will reveal the actual interval programmed, + * after all rounding/adjustments, which can be used to determine + * the actual start_time/interval_time that will be realized. + * + * If this actual interval is different than the intended value, + * it may indicate the need for better tuning on the app/config/bsp + * side, and so a DEBUG message is generated. + */ + status = timer_gettime(local->host_timerid, &timeout); + if (status == OK) + { + local->configured_start_time = + (timeout.it_value.tv_sec * 1000000) + + (timeout.it_value.tv_nsec / 1000); + local->configured_interval_time = + (timeout.it_interval.tv_sec * 1000000) + + (timeout.it_interval.tv_nsec / 1000); + + if (local->configured_start_time != start_time) + { + OS_DEBUG("WARNING: timer %lu start_time requested=%luus, configured=%luus\n", + (unsigned long)timer_id, + (unsigned long)start_time, + (unsigned long)local->configured_start_time); + } + if (local->configured_interval_time != interval_time) + { + OS_DEBUG("WARNING: timer %lu interval_time requested=%luus, configured=%luus\n", + (unsigned long)timer_id, + (unsigned long)interval_time, + (unsigned long)local->configured_interval_time); + } + + } + } else { return_code = OS_TIMER_ERR_INVALID_ARGS; } + + } + + if (!local->reset_flag && return_code == OS_SUCCESS) + { + local->reset_flag = true; } return return_code; diff --git a/src/tests/timer-test/timer-test.c b/src/tests/timer-test/timer-test.c index 89a55dec8..f6cf3d683 100644 --- a/src/tests/timer-test/timer-test.c +++ b/src/tests/timer-test/timer-test.c @@ -92,7 +92,7 @@ void TimerTestTask(void) { int i = 0; - int32 TimerStatus; + int32 TimerStatus[NUMBER_OF_TIMERS]; uint32 TableId; uint32 TimerID[NUMBER_OF_TIMERS]; char TimerName[NUMBER_OF_TIMERS][20] = {"TIMER1","TIMER2","TIMER3","TIMER4"}; @@ -101,25 +101,38 @@ void TimerTestTask(void) for ( i = 0; i < NUMBER_OF_TIMERS; i++ ) { - TimerStatus = OS_TimerCreate(&TimerID[i], TimerName[i], &ClockAccuracy, &(test_func)); - UtAssert_True(TimerStatus == OS_SUCCESS, "Timer %d Created RC=%d ID=%d", i, (int)TimerStatus, (int)TimerID[i]); + TimerStatus[i] = OS_TimerCreate(&TimerID[i], TimerName[i], &ClockAccuracy, &(test_func)); + UtAssert_True(TimerStatus[i] == OS_SUCCESS, "Timer %d Created RC=%d ID=%d", i, (int)TimerStatus[i], (int)TimerID[i]); UtPrintf("Timer %d Accuracy = %d microseconds \n",i ,(int)ClockAccuracy); - TimerStatus = OS_TimerSet(TimerID[i], TimerStart[i], TimerInterval[i]); - UtAssert_True(TimerStatus == OS_SUCCESS, "Timer %d programmed RC=%d", i, (int)TimerStatus); - OS_ConvertToArrayIndex(TimerID[i], &TableId); - timer_idlookup[TableId] = i; } + /* Sample the clock now, before starting any timer */ + OS_GetLocalTime(&StartTime); + for ( i = 0; i < NUMBER_OF_TIMERS; i++ ) + { + /* + * to ensure that all timers are started as closely as possible, + * this just stores the result and does not assert/printf now + */ + TimerStatus[i] = OS_TimerSet(TimerID[i], TimerStart[i], TimerInterval[i]); + } + + /* + * Now the actual OS_TimerSet() return code can be checked. + */ + for ( i = 0; i < NUMBER_OF_TIMERS; i++ ) + { + UtAssert_True(TimerStatus[i] == OS_SUCCESS, "Timer %d programmed RC=%d", i, (int)TimerStatus[i]); + } /* ** Let the main thread sleep */ UtPrintf("Starting Delay loop.\n"); - OS_GetLocalTime(&StartTime); for (i = 0 ; i < 30; i++ ) { /* @@ -134,9 +147,13 @@ void TimerTestTask(void) for ( i = 0; i < NUMBER_OF_TIMERS; i++ ) { - TimerStatus = OS_TimerDelete(TimerID[i]); - UtAssert_True(TimerStatus == OS_SUCCESS, "Timer %d delete RC=%d. Count total = %d", - i, (int)TimerStatus, (int)timer_counter[i]); + TimerStatus[i] = OS_TimerDelete(TimerID[i]); + } + + for ( i = 0; i < NUMBER_OF_TIMERS; i++ ) + { + UtAssert_True(TimerStatus[i] == OS_SUCCESS, "Timer %d delete RC=%d. Count total = %d", + i, (int)TimerStatus[i], (int)timer_counter[i]); } OS_ApplicationShutdown(true); @@ -165,7 +182,11 @@ void TimerTestCheck(void) /* Make sure the ratio of the timers are OK */ for ( i = 0; i < NUMBER_OF_TIMERS; i++ ) { - expected = (microsecs - TimerStart[i]) / TimerInterval[i]; + /* + * Expect one tick after the start time (i.e. first tick) + * Plus one tick for every interval that occurred during the test + */ + expected = 1 + (microsecs - TimerStart[i]) / TimerInterval[i]; UtAssert_True(expected > 0, "Expected ticks = %u", (unsigned int)expected); /*