OSAL Timer UT failing intermittently

[zanzaben]

Describe the bug
On my virtual machine running Ubuntu 20.04, OSAL_timer_UT fails roughly 50% of the times I run it. Specifically the OS_TimerSet test.

To Reproduce
Run Make test

Expected behavior
It should pass 100% of the time.

Code snips
Here is the printout

BEGIN] 05 OS_TimerSet
[ PASS] 05.001 ut_ostimer_timerio_test.c:525 - #1 Invalid-id-arg
[ INFO] 05.002 ut_ostimer_timerio_test.c:532 - #2 Internal-error
[ INFO] ut_ostimer_timerio_test.c:553:
OS_TimerSet() - #3 Interval-too-short (clk_accuracy=10000)

[ PASS] 05.003 ut_ostimer_timerio_test.c:560 - #3 Interval-too-short
[ INFO] ut_ostimer_timerio_test.c:591:
OS_TimerSet() - #1 Nominal condition (clk_accuracy=10000)

[ FAIL] 05.004 ut_ostimer_timerio_test.c:600 - #4 Nominal
[ END] 05 OS_TimerSet TOTAL::4 PASS::2 FAIL::1

System observed on:
Ubuntu 20.04

Reporter Info
ALex Campbell GSFC

[jphickey]

Likely that whatever this is will be the same as #942 (just hypothesizing) ... but please advise as much as you can about your specific VM config and I can attempt to reproduce on my side.

[jphickey]

FWIW, today I did open up my VirtualBox install (currently reporting itself as version 6.1.18) and made a new VM with a fresh Ubuntu 20.04 install. I selected "minimal" install, then did the usual apt-get updates and installed build prerequisites, then pulled down the latest bundle from github and built it.

In the end - I ran osal_timer_UT about a dozen times in a row, no failures at all.

So - I'm suspecting this has something to do with configuration. In particular I'd like to compare the settings for "System" in the VM settings GUI - i.e. amount of RAM and vCPUs assigned to the guest, acceleration options, etc.

Also - One issue I did run into - for some reason, by default, VirtualBox did not immediately enable caching on my virtual disk. Which meant that the disk was exceptionally slow. Even just getting the install done was taking way too long - so I forced-off, found the cache setting, enabled it, and restarted the install - which was MUCH faster second time around.

[skliper]

Note the "1Hz" processing on the system in question is extremely jittery, added a syslog right before the 1Hz elapsed check:

    CFE_ES_WriteToSysLog("%s: Good = %lu, Bad = %lu, elapsed sec = %lu.%06lu (%lu)\n", __func__,
                         (unsigned long)CFE_TIME_Global.ToneIntCounter, (unsigned long)CFE_TIME_Global.ToneIntErrorCounter,
                         (unsigned long)Elapsed.Seconds, (unsigned long)CFE_TIME_Sub2MicroSecs(Elapsed.Subseconds),
                         (unsigned long)Elapsed.Subseconds);

    /*
    ** Verify that tone occurred ~1 second after previous tone...
    */
    if (((Elapsed.Seconds == 1) && (Elapsed.Subseconds < CFE_TIME_Global.ToneOverLimit)) ||
        ((Elapsed.Seconds == 0) && (Elapsed.Subseconds > CFE_TIME_Global.ToneUnderLimit)))

and a sample result shows huge errors (> 500ms in one case)! Note on my docker errors are less than 2ms, the default limit is 20ms. I'm somewhat surprised there isn't at minimum a debug event generated for such poor performance, just a counter in tlm.

...
OS_BSP_Initialize():Maximum user msg queue depth = 10
CFE_PSP: Default Reset SubType = 1
CFE_PSP: Default CPU ID = 1
CFE_PSP: Default Spacecraft ID = 66
CFE_PSP: Default CPU Name: cpu1
OS_Posix_GetSchedulerParams():189:Policy 1: available, min-max: 1-99
OS_Posix_GetSchedulerParams():189:Policy 2: available, min-max: 1-99
OS_Posix_TaskAPI_Impl_Init():375:Selected policy 2 for RT tasks, root task = 99
OS_Posix_TaskAPI_Impl_Init():392:Could not setschedparam in main thread: Operation not permitted (1)
CFE_PSP: Instantiated software timebase 'cFS-Master' running at 10000 usec
CFE_PSP: Using POSIX monotonic clock as CFE timebase
CFE_PSP: Using MMAP simulated EEPROM implementation
CFE_PSP: Physical RAM access not implemented
CFE_PSP: I/O Port access not implemented
CFE_PSP: EEPROM Range (2) created: Start Address = 7F11AFECE000, Size = 00080000 Status = 0
CFE_PSP: Starting the cFE with a POWER ON reset.
CFE_PSP: Clearing out CFE CDS Shared memory segment.
CFE_PSP: Clearing out CFE Reset Shared memory segment.
CFE_PSP: Clearing out CFE User Reserved Shared memory segment.
1980-010-08:22:39.94410 CFE_ES_SetupResetVariables: POWER ON RESET due to Power Cycle (Power Cycle).
1980-010-08:22:39.94420 CFE_ES_Main: CFE_ES_Main in EARLY_INIT state
CFE_PSP: CFE_PSP_AttachExceptions Called
1980-010-08:22:39.94580 CFE_ES_Main: CFE_ES_Main entering CORE_STARTUP state
1980-010-08:22:39.94581 CFE_ES_CreateObjects: Starting Object Creation calls.
1980-010-08:22:39.94582 CFE_ES_CreateObjects: Calling CFE_ES_CDSEarlyInit
1980-010-08:22:39.94610 CFE_ES_CreateObjects: Calling CFE_EVS_EarlyInit
1980-010-08:22:39.94613 CFE_EVS_EarlyInit: Event Log cleared following power-on reset
1980-010-08:22:39.94614 CFE_ES_CreateObjects: Calling CFE_SB_EarlyInit
1980-010-08:22:39.94670 CFE_ES_CreateObjects: Calling CFE_TIME_EarlyInit
1980-012-14:03:20.00000 CFE_ES_CreateObjects: Calling CFE_TBL_EarlyInit
1980-012-14:03:20.00073 CFE_ES_CreateObjects: Calling CFE_FS_EarlyInit
EVS Port1 66/1/CFE_EVS 1: cFE EVS Initialized:  cFE DEVELOPMENT BUILD v6.8.0-rc1+dev844 (Codename: Bootes), Last Official Release: cfe v6.7.0
1980-012-14:03:20.15533 CFE_SB_AppInit: Registered 4 events for filtering
EVS Port1 66/1/CFE_SB 1: cFE SB Initialized:  cFE DEVELOPMENT BUILD v6.8.0-rc1+dev844 (Codename: Bootes), Last Official Release: cfe v6.7.0
EVS Port1 66/1/CFE_SB 14: No subscribers for MsgId 0x808,sender CFE_SB
EVS Port1 66/1/CFE_ES 1: cFE ES Initialized:  cFE DEVELOPMENT BUILD v6.8.0-rc1+dev844 (Codename: Bootes), Last Official Release: cfe v6.7.0
EVS Port1 66/1/CFE_SB 14: No subscribers for MsgId 0x808,sender CFE_ES
EVS Port1 66/1/CFE_ES 2: cFS Versions: cfe v6.8.0-rc1+dev844, osal v5.1.0-rc1+dev586, psp v1.5.0-rc1+dev118. cFE chksm 26583
EVS Port1 66/1/CFE_SB 14: No subscribers for MsgId 0x808,sender CFE_ES
EVS Port1 66/1/CFE_ES 91: Version Info: Mission SampleMission, version [unknown]
EVS Port1 66/1/CFE_SB 14: No subscribers for MsgId 0x808,sender CFE_ES
EVS Port1 66/1/CFE_ES 91: Version Info: Core Module core_api, version git:v7.0.0-rc1-356-g2fb070a-dirty
EVS Port1 66/1/CFE_ES 91: Version Info: Core Module es, version git:v7.0.0-rc1-356-g2fb070a-dirty
EVS Port1 66/1/CFE_ES 91: Version Info: Core Module evs, version git:v7.0.0-rc1-356-g2fb070a-dirty
EVS Port1 66/1/CFE_ES 91: Version Info: Core Module fs, version git:v7.0.0-rc1-356-g2fb070a-dirty
EVS Port1 66/1/CFE_ES 91: Version Info: Core Module sb, version git:v7.0.0-rc1-356-g2fb070a-dirty
EVS Port1 66/1/CFE_ES 91: Version Info: Core Module tbl, version git:v7.0.0-rc1-356-g2fb070a-dirty
EVS Port1 66/1/CFE_ES 91: Version Info: Core Module time, version git:v7.0.0-rc1-356-g2fb070a-dirty
EVS Port1 66/1/CFE_ES 91: Version Info: Core Module osal, version git:v6.0.0-rc1-322-g7f4ba96
EVS Port1 66/1/CFE_ES 91: Version Info: Core Module psp, version git:v1.5.0-rc1-118-g6d40816
EVS Port1 66/1/CFE_ES 91: Version Info: Core Module msg, version git:v7.0.0-rc1-356-g2fb070a-dirty
EVS Port1 66/1/CFE_ES 91: Version Info: Core Module sbr, version git:v7.0.0-rc1-356-g2fb070a-dirty
EVS Port1 66/1/CFE_ES 91: Version Info: Core Module resourceid, version git:v7.0.0-rc1-356-g2fb070a-dirty
EVS Port1 66/1/CFE_ES 92: Build 202108121234 by alex@alex-VirtualBox, config sample
EVS Port1 66/1/CFE_TIME 1: cFE TIME Initialized:  cFE DEVELOPMENT BUILD v6.8.0-rc1+dev844 (Codename: Bootes), Last Official Release: cfe v6.7.0
EVS Port1 66/1/CFE_TBL 1: cFE TBL Initialized:  cFE DEVELOPMENT BUILD v6.8.0-rc1+dev844 (Codename: Bootes), Last Official Release: cfe v6.7.0
1980-012-14:03:20.50907 CFE_ES_CreateObjects: Finished ES CreateObject table entries.
1980-012-14:03:20.50914 CFE_ES_Main: CFE_ES_Main entering CORE_READY state
1980-012-14:03:20.50927 CFE_ES_StartApplications: Opened ES App Startup file: /cf/cfe_es_startup.scr
1980-012-14:03:20.50983 CFE_ES_ParseFileEntry: Loading shared library: /cf/cfe_assert.so
1980-012-14:03:20.51038 [BEGIN] CFE FUNCTIONAL TEST
1980-012-14:03:20.51042 [BEGIN] 01 CFE-STARTUP
1980-012-14:03:20.51070 CFE_ES_ParseFileEntry: Loading shared library: /cf/sample_lib.so
SAMPLE Lib Initialized. Sample Lib DEVELOPMENT BUILD v1.2.0-rc1+dev34, Last Official Release: v1.1.0
1980-012-14:03:20.51176 CFE_ES_ParseFileEntry: Loading file: /cf/sample_app.so, APP: SAMPLE_APP
1980-012-14:03:20.51729 CFE_ES_ParseFileEntry: Loading file: /cf/ci_lab.so, APP: CI_LAB_APP
1980-012-14:03:20.51822 CFE_ES_ParseFileEntry: Loading file: /cf/to_lab.so, APP: TO_LAB_APP
1980-012-14:03:20.51893 CFE_ES_ParseFileEntry: Loading file: /cf/sch_lab.so, APP: SCH_LAB_APP
EVS Port1 66/1/SAMPLE_APP 1: SAMPLE App Initialized. Sample App DEVELOPMENT BUILD v1.2.0-rc1+dev62, Last Official Release: v1.1.0
1980-012-14:03:20.56833 CFE_EVS_Register: Filter limit truncated to 8
1980-012-14:03:20.56853 CI_LAB listening on UDP port: 1234
EVS Port1 66/1/CI_LAB_APP 3: CI Lab Initialized. CI Lab App DEVELOPMENT BUILD v2.4.0-rc1+dev39, Last Official Release: v2.3.0
1980-012-14:03:20.56894 CFE_EVS_Register: Filter limit truncated to 8
EVS Port1 66/1/TO_LAB_APP 1: TO Lab Initialized. TO Lab DEVELOPMENT BUILD v2.4.0-rc1+dev47, Last Official Release: v2.3.0, Awaiting enable command.
SCH Lab Initialized. SCH Lab DEVELOPMENT BUILD v2.4.0-rc1+dev32, Last Official Release: v2.3.0
1980-012-14:03:20.63374 CFE_ES_Main: CFE_ES_Main entering APPS_INIT state
1980-012-14:03:20.63377 CFE_ES_Main: CFE_ES_Main entering OPERATIONAL state
1980-012-14:03:20.84693 CFE_TIME_Tone1HzISR: Good = 0, Bad = 0, elapsed sec = 807760.793672 (3408797432)
1980-012-14:03:21.84717 CFE_TIME_Tone1HzISR: Good = 0, Bad = 1, elapsed sec = 1.000240 (1033798)
EVS Port1 66/1/CFE_TIME 21: Stop FLYWHEEL
1980-012-14:03:22.29983 CFE_TIME_Tone1HzISR: Good = 1, Bad = 1, elapsed sec = 1.299830 (1287762622)
1980-012-14:03:23.64138 CFE_TIME_Tone1HzISR: Good = 1, Bad = 2, elapsed sec = 1.341555 (1466969702)
EVS Port1 66/1/CFE_TIME 20: Start FLYWHEEL
1980-012-14:03:24.77923 CFE_TIME_Tone1HzISR: Good = 1, Bad = 3, elapsed sec = 1.137843 (592032895)
1980-012-14:03:25.97151 CFE_TIME_Tone1HzISR: Good = 1, Bad = 4, elapsed sec = 1.192288 (825872389)
1980-012-14:03:27.10913 CFE_TIME_Tone1HzISR: Good = 1, Bad = 5, elapsed sec = 1.137621 (591077695)
1980-012-14:03:28.30864 CFE_TIME_Tone1HzISR: Good = 1, Bad = 6, elapsed sec = 1.199500 (856848123)
1980-012-14:03:29.30866 CFE_TIME_Tone1HzISR: Good = 1, Bad = 7, elapsed sec = 1.000029 (127560)
EVS Port1 66/1/CFE_TIME 21: Stop FLYWHEEL
1980-012-14:03:30.05990 CFE_TIME_Tone1HzISR: Good = 2, Bad = 7, elapsed sec = 1.059906 (257297747)
1980-012-14:03:31.06019 CFE_TIME_Tone1HzISR: Good = 2, Bad = 8, elapsed sec = 1.000291 (1251553)
EVS Port1 66/1/CFE_TIME 21: Stop FLYWHEEL
EVS Port1 66/1/CFE_TIME 20: Start FLYWHEEL
1980-012-14:03:32.00090 CFE_TIME_Tone1HzISR: Good = 3, Bad = 8, elapsed sec = 1.000904 (3883080)
1980-012-14:03:32.99918 CFE_TIME_Tone1HzISR: Good = 4, Bad = 8, elapsed sec = 0.999187 (4291478494)
1980-012-14:03:33.99969 CFE_TIME_Tone1HzISR: Good = 5, Bad = 8, elapsed sec = 0.999693 (4293649600)
1980-012-14:03:35.12601 CFE_TIME_Tone1HzISR: Good = 6, Bad = 8, elapsed sec = 1.126012 (541217849)
1980-012-14:03:36.67064 CFE_TIME_Tone1HzISR: Good = 6, Bad = 9, elapsed sec = 1.544635 (2339193808)
EVS Port1 66/1/CFE_TIME 20: Start FLYWHEEL
1980-012-14:03:37.84026 CFE_TIME_Tone1HzISR: Good = 6, Bad = 10, elapsed sec = 1.169614 (728488301)
1980-012-14:03:38.84002 CFE_TIME_Tone1HzISR: Good = 6, Bad = 11, elapsed sec = 0.999756 (4293919324)
EVS Port1 66/1/CFE_TIME 21: Stop FLYWHEEL
1980-012-14:03:39.18070 CFE_TIME_Tone1HzISR: Good = 7, Bad = 11, elapsed sec = 1.180701 (776108751)
1980-012-14:03:40.37604 CFE_TIME_Tone1HzISR: Good = 7, Bad = 12, elapsed sec = 1.195344 (838997809)
EVS Port1 66/1/CFE_TIME 20: Start FLYWHEEL
1980-012-14:03:41.37082 CFE_TIME_Tone1HzISR: Good = 7, Bad = 13, elapsed sec = 0.994779 (4272545420)
EVS Port1 66/1/CFE_TIME 21: Stop FLYWHEEL
1980-012-14:03:42.27108 CFE_TIME_Tone1HzISR: Good = 8, Bad = 13, elapsed sec = 1.271086 (1164306363)
1980-012-14:03:43.44344 CFE_TIME_Tone1HzISR: Good = 8, Bad = 14, elapsed sec = 1.172359 (740277986)
EVS Port1 66/1/CFE_TIME 20: Start FLYWHEEL
1980-012-14:03:44.44022 CFE_TIME_Tone1HzISR: Good = 8, Bad = 15, elapsed sec = 0.996782 (4281149957)
EVS Port1 66/1/CFE_TIME 21: Stop FLYWHEEL
1980-012-14:03:45.00338 CFE_TIME_Tone1HzISR: Good = 9, Bad = 15, elapsed sec = 1.003380 (14520855)
1980-012-14:03:46.12480 CFE_TIME_Tone1HzISR: Good = 10, Bad = 15, elapsed sec = 1.124803 (536027380)
1980-012-14:03:47.30651 CFE_TIME_Tone1HzISR: Good = 10, Bad = 16, elapsed sec = 1.181712 (780449245)
EVS Port1 66/1/CFE_TIME 20: Start FLYWHEEL
1980-012-14:03:48.54567 CFE_TIME_Tone1HzISR: Good = 10, Bad = 17, elapsed sec = 1.239152 (1027153455)
1980-012-14:03:49.81645 CFE_TIME_Tone1HzISR: Good = 10, Bad = 18, elapsed sec = 1.270781 (1162996398)
1980-012-14:03:50.82571 CFE_TIME_Tone1HzISR: Good = 10, Bad = 19, elapsed sec = 1.009260 (39774404)
EVS Port1 66/1/CFE_TIME 21: Stop FLYWHEEL
1980-012-14:03:51.00049 CFE_TIME_Tone1HzISR: Good = 11, Bad = 19, elapsed sec = 1.000494 (2122143)
1980-012-14:03:52.00038 CFE_TIME_Tone1HzISR: Good = 12, Bad = 19, elapsed sec = 1.000389 (1671172)
1980-012-14:03:53.08964 CFE_TIME_Tone1HzISR: Good = 13, Bad = 19, elapsed sec = 1.089647 (385033510)
1980-012-14:03:54.35627 CFE_TIME_Tone1HzISR: Good = 13, Bad = 20, elapsed sec = 1.266624 (1145141790)
EVS Port1 66/1/CFE_TIME 20: Start FLYWHEEL
1980-012-14:03:55.39240 CFE_TIME_Tone1HzISR: Good = 13, Bad = 21, elapsed sec = 1.036125 (155156552)
1980-012-14:03:56.42037 CFE_TIME_Tone1HzISR: Good = 13, Bad = 22, elapsed sec = 1.027975 (120153858)
^C1980-012-14:03:56.87947 CFE_ES_RunExceptionScan: ExceptionID 0x1110000 in TaskID 0: Caught SIGINT
1980-012-14:03:56.87949 CFE_ES_RunExceptionScan: Processor Reset count not reached (0/2)
CFE_PSP: Exiting cFE with PROCESSOR Reset status.