Measure overall, testsuite and test duration

TcUnit-Verifier/TcUnit-Verifier_DotNet/TcUnit-Verifier/FB_ExtendedTestInformation.cs

@@ -9,6 +9,7 @@ public FB_ExtendedTestInformation(IEnumerable<ErrorList.Error> errors, string te
         {
             Check_TestSuite_Statistics();
             AssertTestClassName();
+            AssertTestDuration();
             Test_BOOL_AssertFailed();
             Test_BOOL_AssertSuccess();
             Test_BYTE_TwoFailedAsserts();
@@ -36,6 +37,11 @@ private void AssertTestClassName()
             AssertMessageCount(className, 5, EnvDTE80.vsBuildErrorLevel.vsBuildErrorLevelLow);
         }
 
+        private void AssertTestDuration()
+        {
+            string duration = "Test duration=%f";
+            AssertMessageCount(duration, 260, EnvDTE80.vsBuildErrorLevel.vsBuildErrorLevelLow);
+        }
 
         private void Test_BOOL_AssertFailed()
         {

TcUnit-Verifier/TcUnit-Verifier_DotNet/TcUnit-Verifier/FB_TestNumberOfAssertionsCalculation.cs

@@ -16,27 +16,27 @@ public FB_TestNumberOfAssertionsCalculation(IEnumerable<ErrorList.Error> errors,
 
         private void TestMixed33SuccessulAnd9FailedAssertions()
         {
-            AssertContainsMessage("| Test status=FAIL, number of asserts=42", EnvDTE80.vsBuildErrorLevel.vsBuildErrorLevelLow);
+            AssertContainsMessage("| Test status=FAIL, number of asserts=42, duration=%f", EnvDTE80.vsBuildErrorLevel.vsBuildErrorLevelLow);
         }
 
         private void TestWith43SuccessfulAssertions()
         {
-            AssertContainsMessage("| Test status=PASS, number of asserts=43", EnvDTE80.vsBuildErrorLevel.vsBuildErrorLevelLow);
+            AssertContainsMessage("| Test status=PASS, number of asserts=43, duration=%f", EnvDTE80.vsBuildErrorLevel.vsBuildErrorLevelLow);
         }
 
         private void TestWith44FailedAssertions()
         {
-            AssertContainsMessage("| Test status=FAIL, number of asserts=44", EnvDTE80.vsBuildErrorLevel.vsBuildErrorLevelLow);
+            AssertContainsMessage("| Test status=FAIL, number of asserts=44, duration=%f", EnvDTE80.vsBuildErrorLevel.vsBuildErrorLevelLow);
         }
 
         private void TestWith45SuccessfulArrayAssertions()
         {
-            AssertContainsMessage("| Test status=PASS, number of asserts=45", EnvDTE80.vsBuildErrorLevel.vsBuildErrorLevelLow);
+            AssertContainsMessage("| Test status=PASS, number of asserts=45, duration=%f", EnvDTE80.vsBuildErrorLevel.vsBuildErrorLevelLow);
         }
 
         private void TestWith46FailedArrayAssertions()
         {
-            AssertContainsMessage("| Test status=FAIL, number of asserts=46", EnvDTE80.vsBuildErrorLevel.vsBuildErrorLevelLow);
+            AssertContainsMessage("| Test status=FAIL, number of asserts=46, duration=%f", EnvDTE80.vsBuildErrorLevel.vsBuildErrorLevelLow);
         }
 
     }

TcUnit-Verifier/TcUnit-Verifier_DotNet/TcUnit-Verifier/Program.cs

@@ -7,6 +7,7 @@
 using TCatSysManagerLib;
 using System.Threading;
 using EnvDTE80;
+using System.Text.RegularExpressions;
 
 namespace TcUnit.Verifier
 {
@@ -108,8 +109,12 @@ static void Main(string[] args)
             bool numberOfTestsLineFound = false;
             bool numberOfSuccesfulTestsLineFound = false;
             bool numberOfFailedTestsLineFound = false;
+            bool durationLineFound = false;
             bool testsFinishedRunningLastLineFound = false;
             int numberOfFailedTests = 0;
+            float duration;
+
+            const string durationStr = "| Duration:";
 
             log.Info("Waiting for TcUnit-Verifier_TwinCAT to finish running tests...");
 
@@ -139,6 +144,11 @@ static void Main(string[] args)
                         // Grab the number of failed tests so we can validate it during the assertion phase
                         numberOfFailedTests = int.Parse(error.Description.Split().Last());
                     }
+                    if (error.Description.Contains(durationStr))
+                    {
+                        int durationIndex = error.Description.IndexOf(durationStr);
+                        durationLineFound = float.TryParse(error.Description.Substring(durationIndex + durationStr.Length), out duration);
+                    }
                     if (error.Description.Contains("| ======================================"))
                         testsFinishedRunningLastLineFound = true;
                 }
@@ -148,7 +158,8 @@ static void Main(string[] args)
                     && numberOfTestSuitesLineFound 
                     && numberOfTestsLineFound 
                     && numberOfSuccesfulTestsLineFound
-                    && numberOfFailedTestsLineFound 
+                    && numberOfFailedTestsLineFound
+                    && durationLineFound
                     && testsFinishedRunningLastLineFound
                 )
                     break;

TcUnit-Verifier/TcUnit-Verifier_DotNet/TcUnit-Verifier/TestFunctionBlockAssert.cs

@@ -2,6 +2,7 @@
 using log4net;
 using System.Collections.Generic;
 using System.Linq;
+using System.Text.RegularExpressions;
 
 namespace TcUnit.Verifier
 {
@@ -46,12 +47,24 @@ protected string CreateFailedTestMessageNoAssertionMessage(string method, string
 
         private bool AreErrorItemsContainingTestMessage(string testMessage, vsBuildErrorLevel errorLevel)
         {
-            return _errors.Any(e => (e.Description.Contains(testMessage.ToUpper())) && e.ErrorLevel.Equals(errorLevel));
+            // no regex needed, do a fast check
+            if(!testMessage.Contains("%f"))
+                return _errors.Any(e => e.Description.Contains(testMessage.ToUpper()) && e.ErrorLevel.Equals(errorLevel));
+
+            // convert number placeholders (%f) to a regex that matches floating point values
+            testMessage = @".*?" + Regex.Escape(testMessage).Replace("%f", @"[+-]?(\d+([.]\d*)?([eE][+-]?\d+)?|[.]\d+([eE][+-]?\d+)?)") + @".*?";
+            return _errors.Any(e => Regex.Match(e.Description, testMessage, RegexOptions.IgnoreCase).Success && e.ErrorLevel.Equals(errorLevel));
         }
 
         private int CountErrorItemsContainingTestMessage(string testMessage, vsBuildErrorLevel errorLevel)
         {
-            return _errors.Count(s => (s.Description.Contains(testMessage.ToUpper())) && s.ErrorLevel.Equals(errorLevel));
+            // no regex needed, do a fast check
+            if (!testMessage.Contains("%f"))
+                return _errors.Count(e => e.Description.Contains(testMessage.ToUpper()) && e.ErrorLevel.Equals(errorLevel));
+
+            // convert number placeholders (%f) to a regex that matches floating point values
+            testMessage = @".*?" + Regex.Escape(testMessage).Replace("%f", @"[+-]?(\d+([.]\d*)?([eE][+-]?\d+)?|[.]\d+([eE][+-]?\d+)?)") + @".*?";
+            return _errors.Count(e => Regex.Match(e.Description, testMessage, RegexOptions.IgnoreCase).Success && e.ErrorLevel.Equals(errorLevel));
         }
 
         protected void AssertMessageCount(string message, int messageCount, vsBuildErrorLevel errorLevel)

TcUnit/TcUnit/DUTs/ST_TestCaseResult.TcDUT

@@ -10,6 +10,7 @@ STRUCT
     FailureMessage : Tc2_System.T_MaxString;
     FailureType : E_AssertionType;
     NumberOfAsserts : UINT;
+    Duration : LREAL; // in seconds
 END_STRUCT
 END_TYPE]]></Declaration>
   </DUT>

TcUnit/TcUnit/DUTs/ST_TestSuiteResult.TcDUT

@@ -7,6 +7,7 @@ STRUCT
     Identity : UINT(0..GVL_Param_TcUnit.MaxNumberOfTestSuites); // Should be 0..GVL_Param_TcUnit.MaxNumberOfTestSuites-1 but gives unknown compiler error
     NumberOfTests : UINT(0..GVL_Param_TcUnit.MaxNumberOfTestsForEachTestSuite);
     NumberOfFailedTests : UINT(0..GVL_Param_TcUnit.MaxNumberOfTestsForEachTestSuite);
+    Duration : LREAL; // in seconds
     TestCaseResults : ARRAY[1..GVL_Param_TcUnit.MaxNumberOfTestsForEachTestSuite] OF ST_TestCaseResult;
 END_STRUCT
 END_TYPE]]></Declaration>

TcUnit/TcUnit/DUTs/ST_TestSuiteResults.TcDUT

@@ -8,7 +8,8 @@ STRUCT
     NumberOfTestCases : UINT; // The total number of test cases (for all test suites)
     NumberOfSuccessfulTestCases : UINT; // The total number of test cases that had all ASSERTS successful
     NumberOfFailedTestCases : UINT; // The total number of test cases that had at least one ASSERT failed
-
+    Duration : LREAL; // Duration it took for all test suites to finish, in seconds
+
     (* Test results for each individiual test suite *)
     TestSuiteResults : ARRAY[1..GVL_Param_TcUnit.MaxNumberOfTestSuites] OF ST_TestSuiteResult;
 END_STRUCT

TcUnit/TcUnit/GVLs/GVL_TcUnit.TcGVL

@@ -14,6 +14,15 @@ VAR_GLOBAL
 
     (* Current name of test being called *)
     CurrentTestNameBeingCalled : Tc2_System.T_MaxString;
+
+    (* Used to get the current cpu cycle counter to calculate the duration of tests and test suits, respectively *)
+    GetCpuCounter : Tc2_System.GETCPUCOUNTER;
+
+    (* Stores the CPU cycle count with 100ns precision since the first entry into one of the Run methods (RUN, RUN_IN_SEQUENCE) *)
+    StartedAt : LWORD;
+
+    (* Duration it took for a complete run, in seconds *)
+    Duration : LREAL;    
 
     (* Whether or not the current test being called has finished running *)
     CurrentTestIsFinished : BOOL;
@@ -35,6 +44,11 @@ VAR_GLOBAL
 
     (* Buffered ADS message queue for output to the error list *)
     AdsMessageQueue : FB_AdsLogStringMessageFifoQueue;
+END_VAR
+VAR_GLOBAL CONSTANT
+  (* Multiply a value that is given in 100ns units by this value to
+     convert the value to seconds *)
+  HundredNanosecondToSecond : LREAL := 1.0 / 10000000.0;
 END_VAR]]></Declaration>
   </GVL>
 </TcPlcObject>

TcUnit/TcUnit/POUs/FB_AdsTestResultLogger.TcPOU

@@ -74,7 +74,11 @@ IF PrintingTestSuiteResultNumber <= GVL_TcUnit.NumberOfInitializedTestSuites AND
                                              STR2 := ', number of failed tests=');
         StringToPrint := Tc2_Standard.CONCAT(STR1 := StringToPrint,
                                              STR2 := UINT_TO_STRING(TcUnitTestResults.TestSuiteResults[PrintingTestSuiteResultNumber].NumberOfFailedTests));
-
+        StringToPrint := Tc2_Standard.CONCAT(STR1 := StringToPrint,
+                                             STR2 := ', duration=');
+        StringToPrint := Tc2_Standard.CONCAT(STR1 := StringToPrint,
+                                             STR2 := LREAL_TO_STRING(TcUnitTestResults.TestSuiteResults[PrintingTestSuiteResultNumber].Duration));
+
         GVL_TcUnit.AdsMessageQueue.WriteLog(MsgCtrlMask := Tc2_System.ADSLOG_MSGTYPE_HINT,
                                             MsgFmtStr := StringToPrint,
                                             StrArg := '');
@@ -96,7 +100,11 @@ IF PrintingTestSuiteResultNumber <= GVL_TcUnit.NumberOfInitializedTestSuites AND
             GVL_TcUnit.AdsMessageQueue.WriteLog(MsgCtrlMask := Tc2_System.ADSLOG_MSGTYPE_HINT,
                                                 MsgFmtStr := '| Test class name=%s',
                                                 StrArg := TcUnitTestResults.TestSuiteResults[PrintingTestSuiteResultNumber].TestCaseResults[TestsInTestSuiteCounter].TestClassName);
-
+            (* Print test duration *)
+            GVL_TcUnit.AdsMessageQueue.WriteLog(MsgCtrlMask := Tc2_System.ADSLOG_MSGTYPE_HINT,
+                                                MsgFmtStr := '| Test duration=%s',
+                                                StrArg := LREAL_TO_STRING(TcUnitTestResults.TestSuiteResults[PrintingTestSuiteResultNumber].TestCaseResults[TestsInTestSuiteCounter].Duration));
+
             (* Print test result/status (SUCCESS, FAILED, SKIPPED) + number of assertions made *)
             IF TcUnitTestResults.TestSuiteResults[PrintingTestSuiteResultNumber].TestCaseResults[TestsInTestSuiteCounter].TestIsFailed THEN
                 StringToPrint := Tc2_Standard.CONCAT(STR1 := '| Test status=', STR2 := TEST_STATUS_FAIL);
@@ -109,6 +117,9 @@ IF PrintingTestSuiteResultNumber <= GVL_TcUnit.NumberOfInitializedTestSuites AND
             StringToPrint := Tc2_Standard.CONCAT(STR1 := StringToPrint, STR2 := ', number of asserts=');
             StringToPrint := Tc2_Standard.CONCAT(STR1 := StringToPrint, STR2 :=
                                                  UINT_TO_STRING(TcUnitTestResults.TestSuiteResults[PrintingTestSuiteResultNumber].TestCaseResults[TestsInTestSuiteCounter].NumberOfAsserts));
+            StringToPrint := Tc2_Standard.CONCAT(STR1 := StringToPrint, STR2 := ', duration=');
+            StringToPrint := Tc2_Standard.CONCAT(STR1 := StringToPrint, STR2 :=
+                                                 LREAL_TO_STRING(TcUnitTestResults.TestSuiteResults[PrintingTestSuiteResultNumber].TestCaseResults[TestsInTestSuiteCounter].Duration));												 
             GVL_TcUnit.AdsMessageQueue.WriteLog(MsgCtrlMask := Tc2_System.ADSLOG_MSGTYPE_HINT,
                                                 MsgFmtStr := StringToPrint,
                                                 StrArg := '');
@@ -168,6 +179,9 @@ IF (GVL_TcUnit.NumberOfInitializedTestSuites = 0 OR PrintingTestSuiteResultNumbe
     GVL_TcUnit.AdsMessageQueue.WriteLog(MsgCtrlMask := Tc2_System.ADSLOG_MSGTYPE_ERROR,
                                         MsgFmtStr := '| Failed tests: %s',
                                         StrArg := UINT_TO_STRING(TcUnitTestResults.NumberOfFailedTestCases));
+    GVL_TcUnit.AdsMessageQueue.WriteLog(MsgCtrlMask := Tc2_System.ADSLOG_MSGTYPE_ERROR,
+                                        MsgFmtStr := '| Duration: %s',
+                                        StrArg := LREAL_TO_STRING(TcUnitTestResults.Duration));                                        
     GVL_TcUnit.AdsMessageQueue.WriteLog(MsgCtrlMask := Tc2_System.ADSLOG_MSGTYPE_ERROR,
                                         MsgFmtStr := '%s',
                                         StrArg := '| ======================================');

TcUnit/TcUnit/POUs/FB_TcUnitRunner.TcPOU

@@ -8,6 +8,7 @@ FUNCTION_BLOCK FB_TcUnitRunner
 VAR
     (* Indication of whether all test suites have reported that they are finished *)
     AllTestSuitesFinished : BOOL := FALSE;
+    AllTestSuitesFinishedTrigger : R_TRIG;
 
     (* Test result information *)
     TestResults : FB_TestResults;
@@ -49,7 +50,11 @@ VAR
     NumberOfTestSuitesFinished : UINT := 0;
 END_VAR]]></Declaration>
       <Implementation>
-        <ST><![CDATA[(* Run TcUnit test suites *)
+        <ST><![CDATA[IF GVL_TcUnit.StartedAt = 0 THEN
+    GVL_TcUnit.StartedAt := F_GetCpuCounterAs64bit(GVL_TcUnit.GetCpuCounter);
+END_IF
+
+(* Run TcUnit test suites *)
 IF NOT AllTestSuitesFinished THEN
     IF GVL_TcUnit.NumberOfInitializedTestSuites = 0 THEN
         AllTestSuitesFinished := TRUE;
@@ -61,19 +66,28 @@ IF NOT AllTestSuitesFinished THEN
                 GVL_TcUnit.CurrentTestSuiteBeingCalled := GVL_TcUnit.TestSuiteAddresses[Counter];
                 GVL_TcUnit.CurrentTestSuiteBeingCalled^.SetHasStartedRunning();
                 GVL_TcUnit.CurrentTestSuiteBeingCalled^();
+                GVL_TcUnit.CurrentTestSuiteBeingCalled^.UpdateDuration();
             END_IF
         END_FOR
         (* Check if some event triggered an abortion of running the tests, in that case abort it now.
            This can be accomplished by setting the result of the test suites run to finished. *)
         IF AbortRunningTestSuites THEN
             NumberOfTestSuitesFinished := GVL_TcUnit.NumberOfInitializedTestSuites;
         END_IF
+
         IF NumberOfTestSuitesFinished = GVL_TcUnit.NumberOfInitializedTestSuites THEN
             AllTestSuitesFinished := TRUE;
         END_IF
     END_IF
 END_IF
 
+(* Measure the duration it took to run all testsuites *)
+AllTestSuitesFinishedTrigger(CLK := AllTestSuitesFinished);
+IF AllTestSuitesFinishedTrigger.Q
+THEN
+    GVL_TcUnit.Duration := LWORD_TO_LREAL(F_GetCpuCounterAs64bit(GVL_TcUnit.GetCpuCounter) - GVL_TcUnit.StartedAt) * GVL_TcUnit.HundredNanosecondToSecond; // seconds
+END_IF
+
 (* Store test suite results continuously *)
 TestResults();
 
@@ -108,7 +122,11 @@ VAR_INST
      TimerBetweenExecutionOfTestSuites : Tc2_Standard.TOF;
 END_VAR]]></Declaration>
       <Implementation>
-        <ST><![CDATA[TimerBetweenExecutionOfTestSuites(PT := TimeBetweenTestSuitesExecution);
+        <ST><![CDATA[IF GVL_TcUnit.StartedAt = 0 THEN
+    GVL_TcUnit.StartedAt := F_GetCpuCounterAs64bit(GVL_TcUnit.GetCpuCounter);
+END_IF
+
+TimerBetweenExecutionOfTestSuites(PT := TimeBetweenTestSuitesExecution);
 (* Run TcUnit test suites *)
 IF NOT AllTestSuitesFinished THEN
     IF GVL_TcUnit.NumberOfInitializedTestSuites = 0 THEN
@@ -127,6 +145,7 @@ IF NOT AllTestSuitesFinished THEN
             GVL_TcUnit.CurrentTestSuiteBeingCalled := GVL_TcUnit.TestSuiteAddresses[CurrentlyRunningTestSuite];
             GVL_TcUnit.CurrentTestSuiteBeingCalled^.SetHasStartedRunning();
             GVL_TcUnit.CurrentTestSuiteBeingCalled^();
+            GVL_TcUnit.CurrentTestSuiteBeingCalled^.UpdateDuration();
         END_IF
         (* Check if some event triggered an abortion of running the tests, in that case abort it now.
            This can be accomplished by setting the result of the test suites run to finished. *)
@@ -139,6 +158,13 @@ IF NOT AllTestSuitesFinished THEN
     END_IF
 END_IF
 
+(* Measure the duration it took to run all testsuites *)
+AllTestSuitesFinishedTrigger(CLK := AllTestSuitesFinished);
+IF AllTestSuitesFinishedTrigger.Q
+THEN
+    GVL_TcUnit.Duration := LWORD_TO_LREAL(F_GetCpuCounterAs64bit(GVL_TcUnit.GetCpuCounter) - GVL_TcUnit.StartedAt) * GVL_TcUnit.HundredNanosecondToSecond; // seconds
+END_IF
+
 (* Store test suite results continuously *)
 TestResults();
 

TcUnit/TcUnit/POUs/FB_Test.TcPOU

@@ -20,6 +20,9 @@ VAR
     TestIsFailed : BOOL; // Indication of whether this test has at least one failed assert
     AssertionMessage : Tc2_System.T_MaxString; // Assertion message for the first assertion in this test
     AssertionType : E_AssertionType; // Assertion type for the first assertion in this test
+
+    StartedAt : LWORD; // Temporary variable to calculate the actual duration of the test, the value holds the cpu cycle counter when a test is started in 100ns precision
+    Duration : LREAL; // Duration of the test in seconds
 END_VAR]]></Declaration>
     <Implementation>
       <ST><![CDATA[]]></ST>
@@ -36,6 +39,12 @@ END_VAR]]></Declaration>
         <ST><![CDATA[GetAssertionType := AssertionType;]]></ST>
       </Implementation>
     </Method>
+    <Method Name="GetDuration" Id="{3e6c864c-e46e-4560-84e2-e90d42108999}">
+      <Declaration><![CDATA[METHOD INTERNAL GetDuration : LREAL]]></Declaration>
+      <Implementation>
+        <ST><![CDATA[GetDuration := Duration;]]></ST>
+      </Implementation>
+    </Method>
     <Method Name="GetName" Id="{94757f0e-9979-49d0-ad9f-e35c823175d4}">
       <Declaration><![CDATA[METHOD INTERNAL GetName : Tc2_System.T_MaxString;]]></Declaration>
       <Implementation>
@@ -104,9 +113,13 @@ END_IF]]></ST>
       </Implementation>
     </Method>
     <Method Name="SetFinished" Id="{e1245d1c-be22-4d60-bc91-fe0262827234}">
-      <Declaration><![CDATA[METHOD INTERNAL SetFinished : BOOL]]></Declaration>
+      <Declaration><![CDATA[METHOD INTERNAL SetFinished : BOOL
+VAR_INPUT
+    FinishedAt : LWORD; // CPU cycle counter with 100ns precision 
+END_VAR]]></Declaration>
       <Implementation>
-        <ST><![CDATA[TestIsFinished := TRUE;]]></ST>
+        <ST><![CDATA[TestIsFinished := TRUE;
+Duration := LWORD_TO_LREAL(FinishedAt - StartedAt) * GVL_TcUnit.HundredNanosecondToSecond; // seconds]]></ST>
       </Implementation>
     </Method>
     <Method Name="SetName" Id="{4c12f6eb-bbe4-4872-ac89-4411e2e81414}">
@@ -134,6 +147,18 @@ METHOD INTERNAL SetSkipped]]></Declaration>
         <ST><![CDATA[TestIsSkipped := TRUE;]]></ST>
       </Implementation>
     </Method>
+    <Method Name="SetStartedAtIfNotSet" Id="{35bcf245-cc42-44cc-8963-d5986e3acc7f}">
+      <Declaration><![CDATA[METHOD INTERNAL SetStartedAtIfNotSet
+VAR_INPUT
+    Timestamp : LWORD; // CPU cycle counter with 100ns precision 
+END_VAR
+]]></Declaration>
+      <Implementation>
+        <ST><![CDATA[IF StartedAt = 0 THEN
+    StartedAt := Timestamp;
+END_IF]]></ST>
+      </Implementation>
+    </Method>
     <Method Name="SetTestOrder" Id="{9154b373-5715-4bb9-b58b-0dd484b21841}">
       <Declaration><![CDATA[(* Sets in which order/sequence relative to the order tests should this test be executed/evaluated. *)
 METHOD INTERNAL SetTestOrder