Print total runtime in milliseconds at command end.

doc/xml/release.xml

@@ -22,6 +22,10 @@
 
                         <p>Use <code>time_t</code> instead of <code>__time_t</code> for better portability.</p>
                     </release-item>
+
+                    <release-item>
+                        <p>Print total runtime in milliseconds at command end.</p>
+                    </release-item>
                 </release-improvement-list>
 
                 <release-development-list>

src/command/command.c

@@ -1,15 +1,35 @@
 /***********************************************************************************************************************************
 Common Command Routines
 ***********************************************************************************************************************************/
+#include <inttypes.h>
 #include <string.h>
 
 #include "common/assert.h"
 #include "common/debug.h"
 #include "common/log.h"
 #include "common/memContext.h"
+#include "common/time.h"
 #include "config/config.h"
 #include "version.h"
 
+/***********************************************************************************************************************************
+Track time command started
+***********************************************************************************************************************************/
+static TimeMSec timeBegin;
+
+/***********************************************************************************************************************************
+Capture time at the very start of main so total time is more accurate
+***********************************************************************************************************************************/
+void
+cmdInit()
+{
+    FUNCTION_DEBUG_VOID(logLevelTrace);
+
+    timeBegin = timeMSec();
+
+    FUNCTION_DEBUG_RESULT_VOID();
+}
+
 /***********************************************************************************************************************************
 Begin the command
 ***********************************************************************************************************************************/
@@ -163,7 +183,12 @@ cmdEnd(int code, const String *errorMessage)
             String *info = strNewFmt("%s command end: ", cfgCommandName(cfgCommand()));
 
             if (code == 0)
+            {
                 strCat(info, "completed successfully");
+
+                if (cfgOptionValid(cfgOptLogTimestamp) && cfgOptionBool(cfgOptLogTimestamp))
+                    strCatFmt(info, " (%" PRIu64 "ms)", timeMSec() - timeBegin);
+            }
             else
                 strCat(info, strPtr(errorMessage));
 
@@ -172,5 +197,8 @@ cmdEnd(int code, const String *errorMessage)
         MEM_CONTEXT_TEMP_END();
     }
 
+    // Reset timeBegin in case there is another command following this one
+    timeBegin = timeMSec();
+
     FUNCTION_DEBUG_RESULT_VOID();
 }

src/command/command.h

@@ -9,6 +9,8 @@ Common Command Routines
 /***********************************************************************************************************************************
 Functions
 ***********************************************************************************************************************************/
+void cmdInit();
+
 void cmdBegin(bool logOption);
 void cmdEnd(int code, const String *errorMessage);
 

src/main.c

@@ -28,6 +28,9 @@ main(int argListSize, const char *argList[])
         FUNCTION_DEBUG_PARAM(CHARPY, argList);
     FUNCTION_DEBUG_END();
 
+    // Initialize command with the start time
+    cmdInit();
+
     volatile bool result = 0;
     volatile bool error = false;
 

test/src/module/command/commandTest.c

@@ -18,6 +18,8 @@ testRun()
     // *****************************************************************************************************************************
     if (testBegin("cmdBegin() and cmdEnd()"))
     {
+        cmdInit();
+
         // -------------------------------------------------------------------------------------------------------------------------
         cfgInit();
         cfgCommandSet(cfgCmdArchiveGet);
@@ -95,13 +97,26 @@ testRun()
         TEST_RESULT_VOID(cmdEnd(0, NULL), "command end no logging");
         logInit(logLevelInfo, logLevelOff, logLevelOff, false);
 
+        // -------------------------------------------------------------------------------------------------------------------------
+        TEST_RESULT_VOID(cmdEnd(25, strNew("aborted with exception [025]")), "command end with error");
+        testLogResult("P00   INFO: archive-get command end: aborted with exception [025]");
+
         // -------------------------------------------------------------------------------------------------------------------------
         TEST_RESULT_VOID(cmdEnd(0, NULL), "command end with success");
         testLogResult("P00   INFO: archive-get command end: completed successfully");
 
+        // Make sure time output is covered but don't do expect testing since the output is variable
         // -------------------------------------------------------------------------------------------------------------------------
-        TEST_RESULT_VOID(cmdEnd(25, strNew("aborted with exception [025]")), "command end with error");
+        cfgOptionValidSet(cfgOptLogTimestamp, true);
-        testLogResult("P00   INFO: archive-get command end: aborted with exception [025]");
+        cfgOptionSet(cfgOptLogTimestamp, cfgSourceParam, varNewBool(false));
+
+        TEST_RESULT_VOID(cmdEnd(0, NULL), "command end with success");
+        testLogResult("P00   INFO: archive-get command end: completed successfully");
+
+        cfgOptionSet(cfgOptLogTimestamp, cfgSourceParam, varNewBool(true));
+
+        TEST_RESULT_VOID(cmdEnd(0, NULL), "command end with success");
+        testLogResultRegExp("P00   INFO\\: archive-get command end: completed successfully \\([0-9]+ms\\)");
     }
 
     FUNCTION_HARNESS_RESULT_VOID();