Duration doesn't seem to be correctly calculated

[sagatowski]

Describe the bug
The PR #159 doesn't seem to work correctly.

The duration doesn't seem to be correctly calculated. For example, in the below calculation, the duration of the whole test suite is SHORTER than the individual test. Running a complete test suite should always take longer than the individual tests.

Message		2023-05-01 11:06:16 203 ms | 'PlcTask' (350): | ID=12 number of tests=1, number of failed tests=0, duration=7.93e-5				
Message		2023-05-01 11:06:16 223 ms | 'PlcTask' (350): | Test name=GoFromRoughedToVented_Test1				
Message		2023-05-01 11:06:16 243 ms | 'PlcTask' (350): | Test class name=PRG_TEST.fbCryoPumpState_Test				
Message		2023-05-01 11:06:16 263 ms | 'PlcTask' (350): | Test duration=3.59549e-2	

To Reproduce
Take the latest version from the master-branch.

Expected behavior
The duration for the test suite should be longer than the duration for the individual tests.

Software versions
XAE 3.1.4024.44.
TcUnit library from branch.

[sagatowski]

@stefanbesler Can you look into this?

[PTKu]

Hmm... looks like a quantum fenomena is taking over here😃. Just kidding😊

[sagatowski]

@PTKu The test suites are getting close to a black hole! ⚫🌌

[sagatowski]

The implementation in #159 seems to be completely broken. I did a very simple program that has one single test, running for one second, according to this:

TEST('Test1Second');

fbTon(IN := TRUE);
IF fbTon.Q THEN
	AssertTrue(Condition := TRUE,
			   Message := '');
	TEST_FINISHED();
END_IF

Where fbTon is set to 1 second.

What I get is this (straight from the log):

Severity	Code	Description	Project	File	Line	Suppression State
Message		2023-05-01 18:05:31 355 ms | 'PlcTask' (350): | Test suite ID=0 'PRG_TEST.fbTests'				
Message		2023-05-01 18:05:31 375 ms | 'PlcTask' (350): | ID=0 number of tests=1, number of failed tests=0, duration=3.553e-4				
Message		2023-05-01 18:05:31 395 ms | 'PlcTask' (350): | Test name=Test1Second				
Message		2023-05-01 18:05:31 415 ms | 'PlcTask' (350): | Test class name=PRG_TEST.fbTests				
Message		2023-05-01 18:05:31 435 ms | 'PlcTask' (350): | Test status=PASS, number of asserts=1, duration=9.969568e-1				
Error		2023-05-01 18:05:31 455 ms | 'PlcTask' (350): | ==========TESTS FINISHED RUNNING==========				
Error		2023-05-01 18:05:31 475 ms | 'PlcTask' (350): | Test suites: 1				
Error		2023-05-01 18:05:31 495 ms | 'PlcTask' (350): | Tests: 1				
Error		2023-05-01 18:05:31 515 ms | 'PlcTask' (350): | Successful tests: 1				
Error		2023-05-01 18:05:31 535 ms | 'PlcTask' (350): | Failed tests: 0				
Error		2023-05-01 18:05:31 555 ms | 'PlcTask' (350): | Duration: 0.0				
Error		2023-05-01 18:05:31 575 ms | 'PlcTask' (350): | ======================================						

For the test itself the calculation seems good, but for the testsuite and all the tests combined (the final test result), the results are completely wrong.
Test suite returns 3.553e-4 while the whole test-execution returns 0.0!

@stefanbesler Could you look into this? If it's not corrected I will have to revert the pull request.

[sagatowski]

It get's even worse. The test time for individual tests is not calculated correctly either.
If I run two tests in parallell (normal behaviour, so just running using TcUnit.RUN() and not TcUnit.RUN_IN_SEQUENCE()), where one tests executes in 1 second, and the other one executes in two seconds (using two different timers), I get the following output:

It wrongfully calculates that both of the tests are running in two seconds!

[sagatowski]

Okey, I've been scratching my head the whole afternoon and did a quick-fix to solve both #210 and #211.
I tested it with a very simple program that has the following unit test layout:

• Test suite 1 (fbTests1)
• • Test 1 (Test10Seconds) - runs for 10 seconds
• • Test 2 (Test20Seconds) - runs for 20 seconds
• Test suite 2 (fbTests2)
• • Test 1 (Test15Seconds) - runs for 15 seconds

I tested it running with both RUN and RUN_IN_SEQUENCE and got the following results:
RUN() - Runs all test suites in parallell

Severity	Code	Description	Project	File	Line	Suppression State
Message		2023-05-01 20:36:58 893 ms | 'PlcTask' (350): | Test suite ID=0 'PRG_TEST.fbTests1'				
Message		2023-05-01 20:36:58 913 ms | 'PlcTask' (350): | ID=0 number of tests=2, number of failed tests=0, duration=19.9791316				
Message		2023-05-01 20:36:58 933 ms | 'PlcTask' (350): | Test name=Test10Seconds				
Message		2023-05-01 20:36:58 953 ms | 'PlcTask' (350): | Test class name=PRG_TEST.fbTests1				
Message		2023-05-01 20:36:58 973 ms | 'PlcTask' (350): | Test status=PASS, number of asserts=1, duration=9.9900302				
Message		2023-05-01 20:36:58 993 ms | 'PlcTask' (350): | Test name=Test20Seconds				
Message		2023-05-01 20:36:59 013 ms | 'PlcTask' (350): | Test class name=PRG_TEST.fbTests1				
Message		2023-05-01 20:36:59 033 ms | 'PlcTask' (350): | Test status=PASS, number of asserts=1, duration=19.9791247				
Message		2023-05-01 20:36:59 053 ms | 'PlcTask' (350): | Test suite ID=1 'PRG_TEST.fbTests2'				
Message		2023-05-01 20:36:59 073 ms | 'PlcTask' (350): | ID=1 number of tests=1, number of failed tests=0, duration=14.9846668				
Message		2023-05-01 20:36:59 093 ms | 'PlcTask' (350): | Test name=Test15Seconds				
Message		2023-05-01 20:36:59 113 ms | 'PlcTask' (350): | Test class name=PRG_TEST.fbTests2				
Message		2023-05-01 20:36:59 133 ms | 'PlcTask' (350): | Test status=PASS, number of asserts=1, duration=14.9846637				
Error		2023-05-01 20:36:59 153 ms | 'PlcTask' (350): | ==========TESTS FINISHED RUNNING==========				
Error		2023-05-01 20:36:59 173 ms | 'PlcTask' (350): | Test suites: 2				
Error		2023-05-01 20:36:59 193 ms | 'PlcTask' (350): | Tests: 3				
Error		2023-05-01 20:36:59 213 ms | 'PlcTask' (350): | Successful tests: 3				
Error		2023-05-01 20:36:59 233 ms | 'PlcTask' (350): | Failed tests: 0				
Error		2023-05-01 20:36:59 253 ms | 'PlcTask' (350): | Duration: 19.9896752				
Error		2023-05-01 20:36:59 273 ms | 'PlcTask' (350): | ======================================	

RUN_IN_SEQUENCE - Runs the test suites one after the other

Severity	Code	Description	Project	File	Line	Suppression State
Message		2023-05-01 20:38:00 575 ms | 'PlcTask' (350): | Test suite ID=0 'PRG_TEST.fbTests1'				
Message		2023-05-01 20:38:00 595 ms | 'PlcTask' (350): | ID=0 number of tests=2, number of failed tests=0, duration=19.9912857				
Message		2023-05-01 20:38:00 615 ms | 'PlcTask' (350): | Test name=Test10Seconds				
Message		2023-05-01 20:38:00 635 ms | 'PlcTask' (350): | Test class name=PRG_TEST.fbTests1				
Message		2023-05-01 20:38:00 655 ms | 'PlcTask' (350): | Test status=PASS, number of asserts=1, duration=9.9951145				
Message		2023-05-01 20:38:00 675 ms | 'PlcTask' (350): | Test name=Test20Seconds				
Message		2023-05-01 20:38:00 695 ms | 'PlcTask' (350): | Test class name=PRG_TEST.fbTests1				
Message		2023-05-01 20:38:00 715 ms | 'PlcTask' (350): | Test status=PASS, number of asserts=1, duration=19.9912784				
Message		2023-05-01 20:38:15 605 ms | 'PlcTask' (350): | Test suite ID=1 'PRG_TEST.fbTests2'				
Message		2023-05-01 20:38:15 625 ms | 'PlcTask' (350): | ID=1 number of tests=1, number of failed tests=0, duration=14.9924832				
Message		2023-05-01 20:38:15 645 ms | 'PlcTask' (350): | Test name=Test15Seconds				
Message		2023-05-01 20:38:15 665 ms | 'PlcTask' (350): | Test class name=PRG_TEST.fbTests2				
Message		2023-05-01 20:38:15 685 ms | 'PlcTask' (350): | Test status=PASS, number of asserts=1, duration=14.9924768				
Error		2023-05-01 20:38:15 705 ms | 'PlcTask' (350): | ==========TESTS FINISHED RUNNING==========				
Error		2023-05-01 20:38:15 725 ms | 'PlcTask' (350): | Test suites: 2				
Error		2023-05-01 20:38:15 745 ms | 'PlcTask' (350): | Tests: 3				
Error		2023-05-01 20:38:15 765 ms | 'PlcTask' (350): | Successful tests: 3				
Error		2023-05-01 20:38:15 785 ms | 'PlcTask' (350): | Failed tests: 0				
Error		2023-05-01 20:38:15 805 ms | 'PlcTask' (350): | Duration: 35.0139555				
Error		2023-05-01 20:38:15 825 ms | 'PlcTask' (350): | ======================================				

Left to be done:
I need to do more tests after I've gotten some sleep, and think about how we can incorporate these tests into TcUnit-Verifier to verify this automatically for us so I don't have to do it manually.
We also need to test it with the combination of TEST_ORDERED(), which on top of the above also makes it possible to run not only the test suites after the other, but also the TESTS after each other.

[sagatowski]

This is now fixed.