v1.0 assertions are faster than v1.2

[Roald87]

After upgrading from v1.0 to v1.2 I saw that a test suite which ran without issues before, now had a lot of cycle overruns. After some investigation I noticed that there is a parameter to set the maximum number of assertions. For v1.0 this was at 500 and for v1.2 it is at 1000. Even when I set the parameter the same for both versions, v1.0 had no issue with cycle overruns, but v1.2 did. Are assertions now slower than they used to be?

Furthermore I wasn't aware of this maximum assertion parameter. I had way more assertions than the maximum, because I was comparing some arrays with custom structs. What happens to assertions which exceed this maximum? They are not asserted? Maybe a good idea to raise an error when the number of assertions exceeds the maximum.

[sagatowski]

Hi!

Thanks for this issue.

1. When you say that you have a lot of cycle overruns, do you mean that the execution of your tests take longer?
2. Do you have the same problem with 1.1?
3. Is it possible for you to upload a project that shows this behaviour (and the difference) between 1.0 and 1.2? Just so we can reproduce the error.

I'm a little overloaded with work now + in the midst of moving abroad, so I'm happy if you (or anyone else) could investigate this further and sketch a PR if you find a good solution!

I honestly don't remember what happens, but wouldn't be surprised if it's silently lost. I'm pretty sure there is already a (closed?) issue about this.
You are welcome to look deeper into the issue! If you add any new messages to the output in the suggestion, don't forget to check that it's compatible with TcUnit-Runner!

And as always:
https://github.com/tcunit/TcUnit/blob/master/CONTRIBUTING.md

Thanks!

[sagatowski]

Can you try to set the parameter LogExtendedResults to FALSE and see if it makes a difference?

[sagatowski]

https://tcunit.org/frequently-asked-questions/?Display_FAQ=1002

[Roald87]

When you say that you have a lot of cycle overruns, do you mean that the execution of your tests take longer?

Yes it looked like that.

Do you have the same problem with 1.1?

Haven't tested it.

Is it possible for you to upload a project that shows this behaviour (and the difference) between 1.0 and 1.2? Just so we can reproduce the error.

Let me try something.

could investigate this further and sketch a PR if you find a good solution!

👍

I'm pretty sure there is already a (closed?) issue about this.

You mean #145?

Can you try to set the parameter LogExtendedResults to FALSE and see if it makes a difference?

It is set to FALSE

If you add any new messages to the output in the suggestion, don't forget to check that it's compatible with TcUnit-Runner!

This is a response to my "Maybe a good idea to raise an error when the number of assertions exceeds the maximum."?

Finally what about:

Furthermore I wasn't aware of this maximum assertion parameter. What happens to assertions which exceed this maximum?

[AndyP01]

I have made a few quick tests using the TE1010 RealTime Monitor.

Some background on the tests:

1. Run on local runtime of my laptop.
2. Tested with a current project that is still a work in progress. It only has 19 Test suites and 108 actual unit tests in total at this time.
3. Compiled and running with TC3.1.4024.12

However, the time taken to execute the tests on the first PLC cycle:

V1.0.0.0 : 5.3ms
V1.1.0.0 : 6.2ms (Same time for LogExtendedResults = TRUE or FALSE)
V1.2.0.0 : 6.2ms (Same time for LogExtendedResults = TRUE or FALSE)

So in my experience:

V1.0.0.0 does execute the tests quicker than V1.1.0.0 & V1.2.0.0.
There is no difference in execution time when using LogExtendedResults set to TRUE or FALSE with V1.1.0.0 or V1.2.0.0

How that difference in execution time scales when running on an actual controller with a full set of tests remains to be seen.

[Roald87]

@AndyP01 thanks for checking this! Not much slower, but still a bit.

I guess this was caused by the features added for the build server integration.

Maybe one idea to speed things up would be to implement AND_THEN and OR_ELSE. I saw some code sections which contained a lot of if statements.

[sagatowski]

@AndyP01 Thanks a lot for this investigation! Is the TE1010 a mature product? Do you recommend it?
@Roald87 Yes something is slowing everything down, and apparently this happened between 1.0 and 1.1. Unfortunately there were a lot of changes between 1.0 and 1.1. Would probably have to do a comparison commit for commit. A good start would be to have a test project to use for comparison.

Any particular place you think we should use AND_THEN and OR_ELSE? To be honest I haven't used those features that many times, and I know in many places it makes a lot of sense. I've only used them in places where I could potentially use a nullptr but where it could be avoided if using this AND_THEN or OR_ELSE.

[sagatowski]

Note that the parameter for maximum number of assertions is maximum number of assertions PER TEST SUITE, thus the name MaxNumberOfAssertsForEachTestSuite.

This parameter is used to setup the size of the following array

So if you have a mega-super-large test suite in where you have ~1000 tests, then it seems the PLC will just crash (out of array).

[AndyP01]

TE1010 has been released for a couple of years not. Current version is V1.2.1.0. It allows for some very low level diagnostics.

There is no 7-day trial license avaialble for this though, since it resides on the engineering sytem.

Alternatively, you could use the more basic 'Profiler' function block available in the Tc2_Utitlities library.

https://infosys.beckhoff.com/english.php?content=../content/1033/tcplclib_tc2_utilities/35053195.html&id=1344160655692967299

I will try to do some more tests when time allows.

[AndyP01]

AND_THEN or OR_ELSE can be used wherever multiple checks are made in an IF statement. In the case of AND_THEN, if the first item to check is FALSE then there is no point checking the rest because the result will be FALSE. In contrast to using AND, the other checks are not executed, so you have to be careful if a subsequent check is a method call for example. (Maybe something needs to happen on each check for example, and if it does not get executed this will not happen.)

Similar for OR_ELSE. If the first check is TRUE, then the following checks are not executed because the result will be TRUE.

A very quick look in the TestSuite POU reveals a few places you could apply this technique:

IF GVL_TcUnit.IgnoreCurrentTest OR GVL_TcUnit.CurrentTestIsFinished THEN
    RETURN;
END_IF

could become:

IF GVL_TcUnit.IgnoreCurrentTest OR_ELSE GVL_TcUnit.CurrentTestIsFinished THEN
    RETURN;
END_IF

and:

FOR Counter := 1 TO NumberOfTestsToAnalyse BY 1 DO
        AreAllTestsFinished := AreAllTestsFinished AND (Tests[Counter].IsFinished() OR Tests[Counter].IsSkipped());
END_FOR

could perhaps become:

FOR Counter := 1 TO NumberOfTestsToAnalyse BY 1 DO
        AreAllTestsFinished := AreAllTestsFinished AND (Tests[Counter].IsFinished() OR_ELSE Tests[Counter].IsSkipped());
END_FOR

At the very least, if you have 100 tests and none are skipped, then the loop above will eliminate 100 calls to IsSkipped after avery call to IsFinished.

It should be quicker, but how much quicker would need to be tested.

Once again, if time allows, I will try to have a look...

[Roald87]

IF GVL_TcUnit.IgnoreCurrentTest OR_ELSE GVL_TcUnit.CurrentTestIsFinished THEN

For these cases it would be good to swap the order of the two statements. At least I think it is more likely that a test is finished than that a test is ignored. But that might be my limited view, since I never used the ignore tests. Why is this option there anyway, commenting it out is faster right?

Would probably have to do a comparison commit for commit

Not necessarily. You can use binairy search to find where it became slow. So you step back n/2 commits, where n is the number of commits between 1.0 and 1.1. If it is still slow you know the 'slow' commit is in the commit range 0 ... n/2. Contrary when it became fast you know it is between commit n/2 ... n. Then you bisect the range again, let's say the code is still slow at commit n/2. Then you go back to commit n/2/2 = n/4 and apply the trick again until you hunt it down. 👍

In order to hunt down all the long IF statements it would probably be good to write some regex/grep script which runs over all files.