STF test times out when daylight savings time changes

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_special.system_s390x_linux_Nightly/635 DaaLoadTest_all_special_27 variation: Mode612-OSRG JVM_OPTIONS: -Xcompressedrefs -Xcompressedrefs -Xgcpolicy:gencon -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation

1.DLT.stdout shows both threads completed testing.

02:00:25.476 - Completed 98.5%. Number of tests started=709 (+638)
02:00:34.346 - Thread completed. Suite=0 thread=1
02:00:44.459 - Completed 100.0%. Number of tests started=720 (+11)
02:00:47.471 - Thread completed. Suite=0 thread=0
02:00:47.533 - Load test completed
02:00:47.533 -   Ran     : 720
02:00:47.533 -   Passed  : 720
02:00:47.533 -   Failed  : 0
02:00:47.533 -   Result  : PASSED

However a timeout occurred.

STF 02:00:00.066 - **FAILED** Process DLT has timed out
STF 02:00:00.066 - Collecting dumps for: DLT

Looking at the javacore's collected, tests are still running. There is movement between the first javacore and the second.

3XMTHREADINFO      "load-0" J9VMThread:0x000000000011B300, omrthread_t:0x000003FF4000B418, java/lang/Thread:0x000000000C95F5C8, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x16, isDaemon:false)
3XMTHREADINFO1            (native thread ID:0x43E, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMTHREADINFO2            (native stack address range from:0x000003FFACC40000, to:0x000003FFACC80000, size:0x40000)
3XMCPUTIME               CPU usage total: 16.574560896 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=2591864 (0x278C78)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/math/BigInteger.implSquareToLen(BigInteger.java:2079(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.squareToLen(BigInteger.java:2012(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.square(BigInteger.java:1981(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.square(BigInteger.java:1964(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.pow(BigInteger.java:2407(Compiled Code))
4XESTACKTRACE                at java/math/BigDecimal.<init>(BigDecimal.java:934(Compiled Code))
4XESTACKTRACE                at java/math/BigDecimal.<init>(BigDecimal.java:875(Compiled Code))
4XESTACKTRACE                at net/openj9/test/decimals/TestBD2PD2BD.generateRandomBigDecimal(TestBD2PD2BD.java:582(Compiled Code))
4XESTACKTRACE                at net/openj9/test/decimals/TestBD2PD2BD.testBigInteger(TestBD2PD2BD.java:491(Compiled Code))
4XESTACKTRACE                at sun/reflect/GeneratedMethodAccessor745.invoke(Bytecode PC:36(Compiled Code))
4XESTACKTRACE                at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43(Compiled Code))
4XESTACKTRACE                at java/lang/reflect/Method.invoke(Method.java:498(Compiled Code))
4XESTACKTRACE                at org/junit/runners/model/FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50(Compiled Code))
4XESTACKTRACE                at org/junit/internal/runners/model/ReflectiveCallable.run(ReflectiveCallable.java:12(Compiled Code))
4XESTACKTRACE                at org/junit/runners/model/FrameworkMethod.invokeExplosively(FrameworkMethod.java:47(Compiled Code))
4XESTACKTRACE                at org/junit/internal/runners/statements/InvokeMethod.evaluate(InvokeMethod.java:17(Compiled Code))
4XESTACKTRACE                at org/junit/internal/runners/statements/RunBefores.evaluate(RunBefores.java:26(Compiled Code))
4XESTACKTRACE                at org/junit/internal/runners/statements/RunAfters.evaluate(RunAfters.java:27(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner.runLeaf(ParentRunner.java:325(Compiled Code))
4XESTACKTRACE                at org/junit/runners/BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78(Compiled Code))
4XESTACKTRACE                at org/junit/runners/BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner$3.run(ParentRunner.java:290(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner$1.schedule(ParentRunner.java:71(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner.runChildren(ParentRunner.java:288(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner.access$000(ParentRunner.java:58(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner$2.evaluate(ParentRunner.java:268(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner.run(ParentRunner.java:363(Compiled Code))
4XESTACKTRACE                at org/junit/runners/Suite.runChild(Suite.java:128(Compiled Code))
4XESTACKTRACE                at org/junit/runners/Suite.runChild(Suite.java:27(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner$3.run(ParentRunner.java:290(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner$1.schedule(ParentRunner.java:71(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner.runChildren(ParentRunner.java:288(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner.access$000(ParentRunner.java:58(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner$2.evaluate(ParentRunner.java:268(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner.run(ParentRunner.java:363(Compiled Code))
4XESTACKTRACE                at org/junit/runner/JUnitCore.run(JUnitCore.java:137(Compiled Code))
4XESTACKTRACE                at org/junit/runner/JUnitCore.run(JUnitCore.java:115(Compiled Code))
4XESTACKTRACE                at org/junit/runner/JUnitCore.run(JUnitCore.java:105(Compiled Code))
4XESTACKTRACE                at org/junit/runner/JUnitCore.runClasses(JUnitCore.java:62(Compiled Code))
4XESTACKTRACE                at org/junit/runner/JUnitCore.runClasses(JUnitCore.java:49(Compiled Code))
4XESTACKTRACE                at net/openj9/test/BasicTestRunner.runClass(BasicTestRunner.java:41(Compiled Code))
4XESTACKTRACE                at net/openj9/test/decimals/DecimalTestRunner.runTests(DecimalTestRunner.java:53(Compiled Code))
4XESTACKTRACE                at net/openj9/test/decimals/DecimalTestRunner.invokeTest(DecimalTestRunner.java:37(Compiled Code))
4XESTACKTRACE                at sun/reflect/GeneratedMethodAccessor1060.invoke(Bytecode PC:20(Compiled Code))
4XESTACKTRACE                at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43(Compiled Code))
4XESTACKTRACE                at java/lang/reflect/Method.invoke(Method.java:498(Compiled Code))
4XESTACKTRACE                at net/adoptopenjdk/loadTest/adaptors/ArbitraryJavaAdaptor.executeTest(ArbitraryJavaAdaptor.java:102(Compiled Code))
4XESTACKTRACE                at net/adoptopenjdk/loadTest/LoadTestRunner$2.run(LoadTestRunner.java:182)
4XESTACKTRACE                at java/util/concurrent/ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149(Compiled Code))
4XESTACKTRACE                at java/util/concurrent/ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
4XESTACKTRACE                at java/lang/Thread.run(Thread.java:819)

3XMTHREADINFO      "load-1" J9VMThread:0x00000000003A3500, omrthread_t:0x000003FF4000B910, java/lang/Thread:0x000000000C880278, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x17, isDaemon:false)
3XMTHREADINFO1            (native thread ID:0x43F, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMTHREADINFO2            (native stack address range from:0x000003FFAC7C0000, to:0x000003FFAC800000, size:0x40000)
3XMCPUTIME               CPU usage total: 14.251473317 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=20013608 (0x1316228)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at com/ibm/dataaccess/DecimalData.convertPackedDecimalToBigInteger(DecimalData.java:1274(Compiled Code))
4XESTACKTRACE                at net/openj9/test/decimals/TestDecimalData.testConvertBigIntegerNormals(TestDecimalData.java:4195(Compiled Code))
4XESTACKTRACE                at sun/reflect/GeneratedMethodAccessor762.invoke(Bytecode PC:36(Compiled Code))
4XESTACKTRACE                at sun/reflect/DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43(Compiled Code))
4XESTACKTRACE                at java/lang/reflect/Method.invoke(Method.java:498(Compiled Code))
4XESTACKTRACE                at org/junit/runners/model/FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50(Compiled Code))
4XESTACKTRACE                at org/junit/internal/runners/model/ReflectiveCallable.run(ReflectiveCallable.java:12(Compiled Code))
4XESTACKTRACE                at org/junit/runners/model/FrameworkMethod.invokeExplosively(FrameworkMethod.java:47(Compiled Code))
4XESTACKTRACE                at org/junit/internal/runners/statements/InvokeMethod.evaluate(InvokeMethod.java:17(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner.runLeaf(ParentRunner.java:325(Compiled Code))
4XESTACKTRACE                at org/junit/runners/BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78(Compiled Code))
4XESTACKTRACE                at org/junit/runners/BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner$3.run(ParentRunner.java:290(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner$1.schedule(ParentRunner.java:71(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner.runChildren(ParentRunner.java:288(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner.access$000(ParentRunner.java:58(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner$2.evaluate(ParentRunner.java:268(Compiled Code))
4XESTACKTRACE                at org/junit/internal/runners/statements/RunBefores.evaluate(RunBefores.java:26(Compiled Code))
4XESTACKTRACE                at org/junit/internal/runners/statements/RunAfters.evaluate(RunAfters.java:27(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner.run(ParentRunner.java:363(Compiled Code))
4XESTACKTRACE                at org/junit/runners/Suite.runChild(Suite.java:128(Compiled Code))
4XESTACKTRACE                at org/junit/runners/Suite.runChild(Suite.java:27(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner$3.run(ParentRunner.java:290(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner$1.schedule(ParentRunner.java:71(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner.runChildren(ParentRunner.java:288(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner.access$000(ParentRunner.java:58(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner$2.evaluate(ParentRunner.java:268(Compiled Code))
4XESTACKTRACE                at org/junit/runners/ParentRunner.run(ParentRunner.java:363(Compiled Code))
4XESTACKTRACE                at org/junit/runner/JUnitCore.run(JUnitCore.java:137(Compiled Code))
4XESTACKTRACE                at org/junit/runner/JUnitCore.run(JUnitCore.java:115(Compiled Code))
4XESTACKTRACE                at net/adoptopenjdk/loadTest/adaptors/JUnitAdaptor.executeTest(JUnitAdaptor.java:130(Compiled Code))
4XESTACKTRACE                at net/adoptopenjdk/loadTest/LoadTestRunner$2.run(LoadTestRunner.java:182(Compiled Code))
4XESTACKTRACE                at java/util/concurrent/ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149(Compiled Code))
4XESTACKTRACE                at java/util/concurrent/ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624(Compiled Code))
4XESTACKTRACE                at java/lang/Thread.run(Thread.java:819(Compiled Code))

[pshipton]

system_daaLoadTest_test_output.tar.gz

[pshipton]

@Mesbah-Alam can you please take a look.

[pshipton]

The tests timed out, collected some diagnostics, and then finished afterwards. It seems the timeout occurred about 15 seconds after the tests started.

[pshipton]

Another one here with a 4 min timeout https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_special.system_x86-64_linux_Nightly/640

and with a less than 3 min timeout https://ci.eclipse.org/openj9/job/Test_openjdk13_j9_sanity.system_x86-64_linux_Nightly/87

More: https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_sanity.system_x86-64_windows_Nightly/184 https://ci.eclipse.org/openj9/job/Test_openjdk13_j9_sanity.system_ppc64_aix_Nightly/6

I get it, I believe this was caused by the daylight savings time change that occurred. What is the code used to determine if a timeout occurs?

[Mesbah-Alam]

A human readable timeout value (e.g. 60m) is provided in the test , such as https://github.com/AdoptOpenJDK/openjdk-systemtest/blob/master/openjdk.test.jlm/src/test.jlm/net/adoptopenjdk/test/jlm/TestJlmRemoteMemoryAuth.java#L183

Then that value gets parsed by STF here: https://github.com/AdoptOpenJDK/stf/blob/master/stf.core/src/stf.core/net/adoptopenjdk/stf/util/TimeParser.java#L40

It is possible for stf to mis-calculate the time for tests that start before the daylight saving time change takes place and are long enough to continue on after the change happens.

[pshipton]

It is possible for stf to mis-calculate the time for tests that start before the daylight saving time change takes place and are long enough to continue on after the change happens.

Right. I'm wondering if the code can be improved so this problem can't occur. Otherwise this problem will occur every year until we get rid of daylight savings time changes. There are some java APIs which aren't affected by clock changes.

[Mesbah-Alam]

There are some java APIs which aren't affected by clock changes

I will look into it.

Thanks for discovering the issue.

FYI @lumpfish