Fix #2358, adds TIME module command to set CFE_TIME_Print() format #2370

CDKnightNASA · 2023-06-07T22:49:03Z

Checklist (Please check before submitting)

I reviewed the Contributing Guide.
I signed and emailed the appropriate Contributor License Agreement to [email protected] and copied [email protected].

Describe the contribution
Adds a CFE TIME command to configure how to print time information, mostly used by CFE_EVS to print to stdout, and CFE ES for writing to syslog.

Testing performed
Build and test using standard cFE coverage tests which have been updated to test different formats and error conditions.

Expected behavior changes
Enhances CFE_TIME_Print() function and allows for more concise and helpful timestamps.

System(s) tested on
Ubuntu 23 desktop VM.

Contributor Info - All information REQUIRED for consideration of pull request
[email protected]

modules/time/ut-coverage/time_UT.c

@@ -98,6 +98,8 @@
 static const UT_TaskPipeDispatchId_t UT_TPID_CFE_TIME_INVALID_MID = {.MsgId = CFE_SB_MSGID_RESERVED, .CommandCode = 0};
 static const UT_TaskPipeDispatchId_t UT_TPID_CFE_TIME_CMD_INVALID_CC = {
    .MsgId = CFE_SB_MSGID_WRAP_VALUE(CFE_TIME_CMD_MID), .CommandCode = 0x7F};
+static const UT_TaskPipeDispatchId_t UT_TPID_CFE_TIME_SET_PRINT_CC = {


modules/time/fsw/src/cfe_time_dispatch.c

@@ -240,6 +240,13 @@
                    }
                    break;

+                case CFE_TIME_SET_PRINT_CC:
+                    if (CFE_TIME_VerifyCmdLength(&SBBufPtr->Msg, sizeof(CFE_TIME_SetPrintCmd_t)))


modules/time/fsw/src/cfe_time_api.c

+            while(*FmtPtr != '\0' && OutChrs < CFE_TIME_PRINTED_STRING_SIZE)
+            {
+                /* if we have "%f", call strftime for string before and string after */
+                PctF = strstr(FmtBuf, "%f");
+                if (PctF)
+                {
+                    *PctF = '\0'; /* blot out "%f", for now */
+                }
+
+                TimeSz = strftime(PrintBuffer + OutChrs, CFE_TIME_PRINTED_STRING_SIZE - OutChrs, FmtPtr, &tm);
+
+                if (*FmtPtr && TimeSz == 0)
+                {
+                    /* strftime returns 0 if the buffer is too small */
+                    return CFE_TIME_FORMAT_TOO_LONG;
+                }
+
+                OutChrs += TimeSz;
+
+                /* we found/blotted %f above */
+                if (PctF)
+                {
+                    /* write %f value */
+                    if (OutChrs < CFE_TIME_PRINTED_STRING_SIZE - 5)
+                    {
+                        OutChrs += snprintf(PrintBuffer + OutChrs, CFE_TIME_PRINTED_STRING_SIZE - OutChrs, "%05d", mic);
+                    }
+                    else
+                    {
+                        return CFE_TIME_FORMAT_TOO_LONG;
+                    }
+
+                    /* go back through the loop with the remaining format */
+                    FmtPtr = PctF + 2;
+                }
+                else
+                {
+                    PrintBuffer[OutChrs] = '\0'; /* just in case, null-terminate the string */
+                    break; /* break while */
+                }
+            }


modules/time/fsw/src/cfe_time_api.c

+    switch (CFE_TIME_Global.PrintState)
+    {
+        case CFE_TIME_PrintState_DateTime:
+            gmtime_r(&sec, &tm);
+
+            strncpy(FmtPtr, CFE_TIME_Global.PrintFormat, CFE_TIME_FORMAT_SIZE);
+
+            while(*FmtPtr != '\0' && OutChrs < CFE_TIME_PRINTED_STRING_SIZE)
+            {
+                /* if we have "%f", call strftime for string before and string after */
+                PctF = strstr(FmtBuf, "%f");
+                if (PctF)
+                {
+                    *PctF = '\0'; /* blot out "%f", for now */
+                }
+
+                TimeSz = strftime(PrintBuffer + OutChrs, CFE_TIME_PRINTED_STRING_SIZE - OutChrs, FmtPtr, &tm);
+
+                if (*FmtPtr && TimeSz == 0)
+                {
+                    /* strftime returns 0 if the buffer is too small */
+                    return CFE_TIME_FORMAT_TOO_LONG;
+                }
+
+                OutChrs += TimeSz;
+
+                /* we found/blotted %f above */
+                if (PctF)
+                {
+                    /* write %f value */
+                    if (OutChrs < CFE_TIME_PRINTED_STRING_SIZE - 5)
+                    {
+                        OutChrs += snprintf(PrintBuffer + OutChrs, CFE_TIME_PRINTED_STRING_SIZE - OutChrs, "%05d", mic);
+                    }
+                    else
+                    {
+                        return CFE_TIME_FORMAT_TOO_LONG;
+                    }
+
+                    /* go back through the loop with the remaining format */
+                    FmtPtr = PctF + 2;
+                }
+                else
+                {
+                    PrintBuffer[OutChrs] = '\0'; /* just in case, null-terminate the string */
+                    break; /* break while */
+                }
+            }
+            break;
+        case CFE_TIME_PrintState_SecsSinceStart:
+            OutChrs += snprintf(PrintBuffer, CFE_TIME_PRINTED_STRING_SIZE, "%ld.%06d", (long int)sec, mic);
+            PrintBuffer[OutChrs] = '\0';
+            break;
+        default:
+            PrintBuffer[0] = '\0';
+            break;
+    }


CDKnightNASA · 2023-06-15T18:25:03Z

Two issues raised in the CCB:

"%%f" would not work properly (should be replaced with "%f" in the formatted string.)
strstr is fairly expensive, is there a more efficient way?
a) remove the "%f" logic and have a flag in CFE_TIME_Global to tack microseconds at the end.
b) do a one-time scan (at startup, at command) to set offset(s) for the %f(s)

chillfig · 2023-09-07T18:25:19Z

CCB 09/07/2023: Dan plans to run tests and this pr will be considered to be merged next week

dmknutsen · 2023-09-14T17:51:21Z

I was able to perform some initial testing and think we are on track to merge into Equuleus-rc2. I did run into a couple issues that I would like to resolve prior to merging:

We should make the default format backward compatible with the existing timestamp (there was a '-' removed between the Julian Day and Hour)
Because CFE_TIME_Print is called so often - I'd like to benchmark the new logic/while loop against a GR712 (which we are currently setting up in the cFS lab or CI/CD + bench-marking performance) to make sure there are not performance implications.
We will need to submit a separate PR to ensure that the example mission and platform config files are kept in sync (we added those toward the end of the Equuleus-rc1 dev cycle to demonstrate backward compatibility).
I'm seeing timestamp corruption prior to cFE_TIME initialization (after which they are fine). I'd like to understand if that is an actual bug or if it is related to how I merged the PR into my test environment.

chillfig · 2023-11-09T19:16:38Z

CCB: 11-9-2023: put on hold

dzbaker · 2023-11-30T19:18:27Z

CCB 30 November 2023: Going to run performance tests to make sure that changes don't result in a performance hit. Afterwards, backwards compatibility issues will be fixed.

dmknutsen · 2023-12-08T19:11:41Z

@CDKnightNASA - I set up a test to benchmark this against a GR712 running RTEMS 5. During the test, I called CFE_TIME_Print 10,000 times to see how long it takes with and without the patch. I ran the test three times to get an average.

Without patch:
EVS Port1 1980-012-14:03:27.26382 66/1/CFE_TEST_APP 5: [ MIR] 01.005 time_misc_test.c:66 - Elapsed time for Time Print test: 1013326 usec
EVS Port1 1980-012-14:03:27.25918 66/1/CFE_TEST_APP 5: [ MIR] 01.005 time_misc_test.c:66 - Elapsed time for Time Print test: 1013291 usec
EVS Port1 1980-012-14:03:27.27995 66/1/CFE_TEST_APP 5: [ MIR] 01.005 time_misc_test.c:66 - Elapsed time for Time Print test: 1013685 usec

With patch:
EVS Port1 1980-012 14:03:27.53286 66/1/CFE_TEST_APP 5: [ MIR] 01.005 time_misc_test.c:66 - Elapsed time for Time Print test: 1312445 usec
EVS Port1 1980-012 14:03:27.56680 66/1/CFE_TEST_APP 5: [ MIR] 01.005 time_misc_test.c:66 - Elapsed time for Time Print test: 1313442 usec
EVS Port1 1980-012 14:03:27.54457 66/1/CFE_TEST_APP 5: [ MIR] 01.005 time_misc_test.c:66 - Elapsed time for Time Print test: 1313067 usec

Against the GR712, the time to execute CFE_TIME_Print is 28% slower with the patch - which i do not believe is cause for concern. In this case, the enhanced functionality is most likely worth the performance trade. In practice the performance loss will be negligible as CFE_TIME_Print should never be called at a rate where this loss would be noticeable/impactful.

Lets plan to discuss/get concurrence at the next CCB.

CDKnightNASA · 2023-12-14T18:41:00Z

@CDKnightNASA - I set up a test to benchmark this against a GR712 running RTEMS 5. During the test, I called CFE_TIME_Print 10,000 times to see how long it takes with and without the patch. I ran the test three times to get an average.

Without patch: EVS Port1 1980-012-14:03:27.26382 66/1/CFE_TEST_APP 5: [ MIR] 01.005 time_misc_test.c:66 - Elapsed time for Time Print test: 1013326 usec EVS Port1 1980-012-14:03:27.25918 66/1/CFE_TEST_APP 5: [ MIR] 01.005 time_misc_test.c:66 - Elapsed time for Time Print test: 1013291 usec EVS Port1 1980-012-14:03:27.27995 66/1/CFE_TEST_APP 5: [ MIR] 01.005 time_misc_test.c:66 - Elapsed time for Time Print test: 1013685 usec

With patch: EVS Port1 1980-012 14:03:27.53286 66/1/CFE_TEST_APP 5: [ MIR] 01.005 time_misc_test.c:66 - Elapsed time for Time Print test: 1312445 usec EVS Port1 1980-012 14:03:27.56680 66/1/CFE_TEST_APP 5: [ MIR] 01.005 time_misc_test.c:66 - Elapsed time for Time Print test: 1313442 usec EVS Port1 1980-012 14:03:27.54457 66/1/CFE_TEST_APP 5: [ MIR] 01.005 time_misc_test.c:66 - Elapsed time for Time Print test: 1313067 usec

Against the GR712, the time to execute CFE_TIME_Print is 28% slower with the patch - which i do not believe is cause for concern. In this case, the enhanced functionality is most likely worth the performance trade. In practice the performance loss will be negligible as CFE_TIME_Print should never be called at a rate where this loss would be noticeable/impactful.

Lets plan to discuss/get concurrence at the next CCB.

As mentioned in the Teams chat, I think that the performance impact is significant enough to pull this PR. Missions can, instead, just modify the code so that they get the output format they prefer with less/zero impact. But I will await the CCB's decision and will implement suggested changes if the consensus is that the PR is worthwhile even with the performance impact.

dzbaker · 2024-01-04T19:23:38Z

CCB 4 January 2024: Determined that formatting can be applied at compile-time.

CDKnightNASA self-assigned this Jun 7, 2023

github-advanced-security bot found potential problems Jun 7, 2023

View reviewed changes

chillfig added the CCB:Ready Ready for discussion at the Configuration Control Board (CCB) label Jun 8, 2023

CDKnightNASA removed the CCB:Ready Ready for discussion at the Configuration Control Board (CCB) label Jun 8, 2023

CDKnightNASA force-pushed the fix-2358-evs_fmt branch from 5a7b8a8 to 55b71cf Compare June 8, 2023 18:29

Fix nasa#2358, adds TIME module command to set CFE_TIME_Print() format

10c81ea

CDKnightNASA force-pushed the fix-2358-evs_fmt branch from 55b71cf to 10c81ea Compare June 8, 2023 18:40

CDKnightNASA changed the title ~~fix#2358, adds TIME module command to set CFE_TIME_Print() format~~ Fix #2358, adds TIME module command to set CFE_TIME_Print() format Jun 8, 2023

CDKnightNASA marked this pull request as ready for review June 8, 2023 19:29

CDKnightNASA added the CCB:Ready Ready for discussion at the Configuration Control Board (CCB) label Jun 8, 2023

CDKnightNASA requested a review from jphickey June 15, 2023 18:21

CDKnightNASA added Equuleus-rc2 and removed CCB:Ready Ready for discussion at the Configuration Control Board (CCB) labels Jun 22, 2023

dzbaker closed this Jan 4, 2024

CDKnightNASA deleted the fix-2358-evs_fmt branch January 4, 2024 19:24

CDKnightNASA restored the fix-2358-evs_fmt branch January 4, 2024 19:24

CDKnightNASA mentioned this pull request Jan 4, 2024

Document how to change CFE_TIME_Print() timestamp format #2490

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix #2358, adds TIME module command to set CFE_TIME_Print() format #2370

Fix #2358, adds TIME module command to set CFE_TIME_Print() format #2370

CDKnightNASA commented Jun 7, 2023

CDKnightNASA commented Jun 15, 2023

chillfig commented Sep 7, 2023

dmknutsen commented Sep 14, 2023

chillfig commented Nov 9, 2023

dzbaker commented Nov 30, 2023

dmknutsen commented Dec 8, 2023

CDKnightNASA commented Dec 14, 2023

dzbaker commented Jan 4, 2024

Fix #2358, adds TIME module command to set CFE_TIME_Print() format #2370

Fix #2358, adds TIME module command to set CFE_TIME_Print() format #2370

Conversation

CDKnightNASA commented Jun 7, 2023

CDKnightNASA commented Jun 15, 2023

chillfig commented Sep 7, 2023

dmknutsen commented Sep 14, 2023

chillfig commented Nov 9, 2023

dzbaker commented Nov 30, 2023

dmknutsen commented Dec 8, 2023

CDKnightNASA commented Dec 14, 2023

dzbaker commented Jan 4, 2024