DelayTest.testSchedulingMultipleDelaysLongerFirst fails intermittently

[blairmcg]

The range of delays expected by the new Delays tests is too strict on the long side - context switching and other machine activity could easily cause the actual Delay experienced to be significantly longer than that requested, although it should never be shorter (once rounding is taken into account, so it may be 1mS shorter).

An example failure can be seen in build 7.1.8.969

Error message:

Expected delay of 0:00:00ms, got 33.6ms

Stack trace:

DelayTest>>expectDelay:for:@34: `self assert: (delta > -1000 and: [delta < 3000])
        description: ('Expected delay of <1d>ms, got <2d>ms' expandMacrosWith: expectedDuration
                with: (elapsed // 100 / 10 asScaledDecimal: 1))`
...

The maximum positive delta will probably need to be lifted to 50mS for reasonable reliability, although even then it may fail occasionally.

[blairmcg]

Another case:

Error message:
Expected delay of 0:00:00ms, got 8.2ms
Error stack trace:
DelayTest>>expectDelay:for:@34: `self assert: (delta > -1000 and: [delta < 3000])
        description: ('Expected delay of <1d>ms, got <2d>ms' expandMacrosWith: expectedDuration
                with: (elapsed // 100 / 10 asScaledDecimal: 1))`

DelayTest(TestCase)>>fail:
DelayTest(TestCase)>>assert:description:
DelayTest>>expectDelay:for:
DelayTest>>testSimultaneousWaitAndSignal
DelayTest>>testSimultaneousWaitAndSignalWithOtherLongerDelay

A reasonable solution might be retries. The failures are rare, and so probably won't occur twice.

We should also fix the delay printing in the error description here, as the duration is printed in hh:mm:ss format, not milliseconds. humanReadablePrintString would do the trick.

[blairmcg]

Another case from a recent CI build

Error message:
Expected delay of 0:00:00ms, got 13.4ms
Error stack trace:
Core.Tests.DelayTest>>#expectDelay:for:@34: `self assert: (delta > -1000 and: [delta < 3000])
        description: ('Expected delay of <1d>ms, got <2d>ms' expandMacrosWith: expectedDuration
                with: (elapsed // 100 / 10 asScaledDecimal: 1))`

Core.Tests.DelayTest(TestCase)>>fail:
Core.Tests.DelayTest(TestCase)>>assert:description:
Core.Tests.DelayTest>>expectDelay:for:
Core.Tests.DelayTest>>testSignal
Core.Tests.DelayTest(TestCase)>>performTest
[] in Core.Tests.DelayTest(TestCase)>>runCase
BlockClosure>>ensure:
Core.Tests.DelayTest(TestCase)>>runCase
[] in TestResult>>runCase:
ExceptionHandlerSet(ExceptionHandlerAbstract)>>markAndTry
[] in ExceptionHandlerSet(ExceptionHandlerAbstract)>>try:
BlockClosure>>ensure:
ExceptionHandlerSet(ExceptionHandlerAbstract)>>try:
BlockClosure>>on:do:on:do:on:do:
TestResult>>runCase:
Core.Tests.DelayTest(TestCase)>>run:
[] in TestSuite>>run:
OrderedCollection>>do:
[] in TestSuite>>run:
BlockClosure>>ensure:
TestSuite>>run:
[] in XProgramming.SUnit.CommandLineTestRunner>>runSuite:knownSlowTests:
BlockClosure>>ensure:
XProgramming.SUnit.CommandLineTestRunner>>runSuite:knownSlowTests:
RefactoringSmalltalkSystem(SmalltalkSystem)>>runRegressionTests:logTo:verbose:
RefactoringSmalltalkSystem(SmalltalkSystem)>>runRegressionTests
[] in Core.UndefinedObject>>{unbound}doIt
GuiInputState(InputState)>>loopWhile:
GuiInputState(InputState)>>mainLoop
[] in GuiInputState(InputState)>>forkMain
ExceptionHandler(ExceptionHandlerAbstract)>>markAndTry
[] in ExceptionHandler(ExceptionHandlerAbstract)>>try:
BlockClosure>>ensure:
ExceptionHandler(ExceptionHandlerAbstract)>>try:
BlockClosure>>on:do:
[] in BlockClosure>>newProcess:

Different test case this time. It is possible that garbage collections are sometimes triggering after the startTime has been recorded and that would certainly cause the expected delay time to be significantly exceeded, as in the first case. I will try and make it less sensitive to this.

[blairmcg]

Should be fixed in master. If it occurs again, I'll reopen.