Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

STF test times out when daylight savings time changes #106

Open
pshipton opened this issue Nov 4, 2019 · 7 comments
Open

STF test times out when daylight savings time changes #106

pshipton opened this issue Nov 4, 2019 · 7 comments

Comments

@pshipton
Copy link
Contributor

pshipton commented Nov 4, 2019

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
Copy link
Contributor Author

pshipton commented Nov 4, 2019

system_daaLoadTest_test_output.tar.gz

@pshipton
Copy link
Contributor Author

pshipton commented Nov 4, 2019

@Mesbah-Alam can you please take a look.

@pshipton
Copy link
Contributor Author

pshipton commented Nov 4, 2019

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

@pshipton
Copy link
Contributor Author

pshipton commented Nov 4, 2019 •
edited
Loading

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?

@pshipton pshipton mentioned this issue Nov 4, 2019
Closed
@pshipton pshipton changed the title DaaLoadTest completes but is still running STF test times out when daylight savings time changes Nov 4, 2019
@Mesbah-Alam
Copy link
Contributor

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
Copy link
Contributor Author

pshipton commented Nov 4, 2019

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
Copy link
Contributor

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

I will look into it.

Thanks for discovering the issue.

FYI @lumpfish

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@Mesbah-Alam @pshipton