search

tcunit / TcUnit

An unit testing framework for Beckhoff's TwinCAT 3
Other
258 stars 72 forks source link

Duration doesn't seem to be correctly calculated #211

Closed sagatowski closed 9 months ago

sagatowski commented 1 year ago

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 commented 1 year ago

@stefanbesler Can you look into this?

PTKu commented 1 year ago

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

sagatowski commented 1 year ago

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

sagatowski commented 1 year ago

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 commented 1 year ago

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: image

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

sagatowski commented 1 year ago

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:

I tested it running with both RUNand RUN_IN_SEQUENCEand 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 commented 10 months ago

This is now fixed.