From 8310170c5c3ae23002ec6f1ec551cb2e3ac8b127 Mon Sep 17 00:00:00 2001 From: Joseph Hickey Date: Tue, 22 Oct 2019 23:23:39 -0400 Subject: [PATCH 1/4] Fix #272: use 4K stack for sem-speed-test tasks On VxWorks, no minimum stack size is implemented, and the implementation will create tasks with an extremely small stack if "0" is passed in. This causes the worker tasks to overrun the stack on Vxworks, triggering undefined/inconsistent behavior. --- src/tests/sem-speed-test/sem-speed-test.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/tests/sem-speed-test/sem-speed-test.c b/src/tests/sem-speed-test/sem-speed-test.c index 6d00ce42c..4e828af77 100644 --- a/src/tests/sem-speed-test/sem-speed-test.c +++ b/src/tests/sem-speed-test/sem-speed-test.c @@ -150,10 +150,10 @@ void SemSetup(void) /* ** Create the tasks */ - status = OS_TaskCreate( &task_1_id, "Task 1", task_1, NULL, 0, TASK_PRIORITY, 0); + status = OS_TaskCreate( &task_1_id, "Task 1", task_1, NULL, 4096, TASK_PRIORITY, 0); UtAssert_True(status == OS_SUCCESS, "Task 1 create Id=%u Rc=%d", (unsigned int)task_1_id, (int)status); - status = OS_TaskCreate( &task_2_id, "Task 2", task_2, NULL, 0, TASK_PRIORITY, 0); + status = OS_TaskCreate( &task_2_id, "Task 2", task_2, NULL, 4096, TASK_PRIORITY, 0); UtAssert_True(status == OS_SUCCESS, "Task 2 create Id=%u Rc=%d", (unsigned int)task_2_id, (int)status); /* A small delay just to allow the tasks From c75b38de66369b19bae3e4a464569bc99353ba46 Mon Sep 17 00:00:00 2001 From: Joseph Hickey Date: Tue, 22 Oct 2019 23:18:11 -0400 Subject: [PATCH 2/4] Fix #273: Correct format code in debug message Cast the address value so it may be printed as an integer. --- src/os/rtems/osfilesys.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/os/rtems/osfilesys.c b/src/os/rtems/osfilesys.c index f7d46996e..ce34bd0e7 100644 --- a/src/os/rtems/osfilesys.c +++ b/src/os/rtems/osfilesys.c @@ -174,7 +174,7 @@ int32 OS_FileSysStartVolume_Impl (uint32 filesys_id) impl->mount_fstype = RTEMS_FILESYSTEM_TYPE_RFS; OS_DEBUG("OSAL: RAM disk initialized: volume=%s device=%s address=0x%08lX\n", - local->volume_name, impl->blockdev_name, local->address); + local->volume_name, impl->blockdev_name, (unsigned long)local->address); return_code = OS_SUCCESS; break; From f1fcd8d42b946de5782da805e3e75c3695c48006 Mon Sep 17 00:00:00 2001 From: Joseph Hickey Date: Tue, 22 Oct 2019 22:52:52 -0400 Subject: [PATCH 3/4] 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); /* From 6357c2d0e3cd93d6f115ff6a232632d96818deda Mon Sep 17 00:00:00 2001 From: Joseph Hickey Date: Tue, 22 Oct 2019 23:20:06 -0400 Subject: [PATCH 4/4] Fix #274: Avoid possible deadlock of timer callback If the tick_time from the wait routine was perpetually greater than the interval time, eventually the wait_time became such that it was always below zero. Once this occurs, application callbacks would cease entirely. To avoid this, run the callback condition in a loop for periodic timers only (not for one-shot config). --- src/os/shared/osapi-timebase.c | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/src/os/shared/osapi-timebase.c b/src/os/shared/osapi-timebase.c index e6cd7cad3..50384b2aa 100644 --- a/src/os/shared/osapi-timebase.c +++ b/src/os/shared/osapi-timebase.c @@ -494,7 +494,7 @@ void OS_TimeBase_CallbackThread(uint32 timebase_id) timecb = &OS_timecb_table[curr_cb_local_id]; saved_wait_time = timecb->wait_time; timecb->wait_time -= tick_time; - if (timecb->wait_time <= 0) + while (timecb->wait_time <= 0) { timecb->wait_time += timecb->interval_time; @@ -519,6 +519,14 @@ void OS_TimeBase_CallbackThread(uint32 timebase_id) { (*timecb->callback_ptr)(curr_cb_public_id, timecb->callback_arg); } + + /* + * Do not repeat the loop unless interval_time is configured. + */ + if (timecb->interval_time <= 0) + { + break; + } } curr_cb_local_id = timecb->next_ref; }