diff --git a/doc/xml/release.xml b/doc/xml/release.xml index 8d5243191..108b6130d 100644 --- a/doc/xml/release.xml +++ b/doc/xml/release.xml @@ -22,6 +22,10 @@

Use time_t instead of __time_t for better portability.

+ + +

Print total runtime in milliseconds at command end.

+
diff --git a/src/command/command.c b/src/command/command.c index 305eb7b8b..8faecc129 100644 --- a/src/command/command.c +++ b/src/command/command.c @@ -1,15 +1,35 @@ /*********************************************************************************************************************************** Common Command Routines ***********************************************************************************************************************************/ +#include #include #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(); } diff --git a/src/command/command.h b/src/command/command.h index 4680ca8ef..2c97da701 100644 --- a/src/command/command.h +++ b/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); diff --git a/src/main.c b/src/main.c index b014fbc4e..a3560844d 100644 --- a/src/main.c +++ b/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; diff --git a/test/src/module/command/commandTest.c b/test/src/module/command/commandTest.c index efbebb35e..170c1b115 100644 --- a/test/src/module/command/commandTest.c +++ b/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"); - testLogResult("P00 INFO: archive-get command end: aborted with exception [025]"); + cfgOptionValidSet(cfgOptLogTimestamp, true); + 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();