search

eclipse-openj9 / openj9

Eclipse OpenJ9: A Java Virtual Machine for OpenJDK that's optimized for small footprint, fast start-up, and high throughput. Builds on Eclipse OMR (https://github.com/eclipse/omr) and combines with the Extensions for OpenJDK for OpenJ9 repo.
Other
3.28k stars 721 forks source link

OutOfMemory: OutOfMemoryError: Java heap space #15943

Closed pshipton closed 2 years ago

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_x86-64_linux_Nightly_testList_1/353

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk8_j9_extended.functional_x86-64_linux_Nightly_testList_1/353/functional_test_output.tar.gz

Test handling of other arguments
Testing: -verbose:dynload,sizes,stack,debug
Test start time: 2022/09/21 22:54:08 Eastern Standard Time
JVMDUMP039I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError" at 2022/09/21 22:54:08 - please wait.
...
JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
    at java.lang.String.<init>(String.java:942)
    at TestSuite.evaluateVariables(TestSuite.java:253)
    at TestSuite.expandVariable(TestSuite.java:427)
    at TestSuite.evaluateVariables(TestSuite.java:249)
    at TestSuite.evaluateVariables(TestSuite.java:146)
    at Test.run(Test.java:159)
    at TestSuite.runTest(TestSuite.java:84)
    at TestIterator.addTest(TestIterator.java:84)
    at TestConfigParser$TestConfigDocumentHandler.xmlEndElement(TestConfigParser.java:309)
    at com.oti.j9.exclude.XMLParser._scan_element_close(XMLParser.java:370)
    at com.oti.j9.exclude.XMLParser._scan_element_or_instruction(XMLParser.java:391)
    at com.oti.j9.exclude.XMLParser.parseXML(XMLParser.java:442)
    at com.oti.j9.exclude.XMLParser.parse(XMLParser.java:470)
    at com.oti.j9.exclude.XMLParser.parse(XMLParser.java:459)
    at TestConfigParser.runTests(TestConfigParser.java:78)
    at MainTester.main(MainTester.java:106)

cmdLineTester_verbosetest_6_FAILED

https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly/367/

No artifacts.

Testing: -verbose:class -verbose:Xgccon 
Test start time: 2022/09/21 20:32:15 Pacific Standard Time
Running command: "/Users/jenkins/workspace/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_0/openjdkbinary/j2sdk-image/bin/java"  -XX:+UseCompressedOops -Xjit -Xgcpolicy:balanced  -Xdump -verbose:class -verbose:Xgccon  -cp "/Users/jenkins/workspace/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/TestConfig/resources:/Users/jenkins/workspace/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_0/aqa-tests/TKG/../TKG/lib/testng.jar:/Users/jenkins/workspace/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_0/aqa-tests/TKG/../TKG/lib/jcommander.jar:/Users/jenkins/workspace/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/JIT_Test/jitt.jar" org.testng.TestNG -d "/Users/jenkins/workspace/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_0/aqa-tests/TKG/../TKG/output_16638151285423/cmdLineTester_verbosetest_6" "/Users/jenkins/workspace/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/JIT_Test/testng.xml" -testnames AllocationTest -groups level.extended
Time spent starting: 5 milliseconds
JVMDUMP039I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError" at 2022/09/21 20:32:16 - please wait.
...
JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
Exception in thread "Thread-38" java.lang.OutOfMemoryError: Java heap space
    at TestSuite.evaluateVariables(TestSuite.java:235)
    at TestSuite.evaluateVariables(TestSuite.java:146)
    at Output.match(Output.java:62)
    at Test$StreamMatcher.run(Test.java:497)
Time spent executing: 36971 milliseconds
Test result: PASSED

Testing: -verbose:gc -verbose 
Test start time: 2022/09/21 20:32:52 Pacific Standard Time
Running command: "/Users/jenkins/workspace/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_0/openjdkbinary/j2sdk-image/bin/java"  -XX:+UseCompressedOops -Xjit -Xgcpolicy:balanced  -Xdump -verbose:gc -verbose  -cp "/Users/jenkins/workspace/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/TestConfig/resources:/Users/jenkins/workspace/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_0/aqa-tests/TKG/../TKG/lib/testng.jar:/Users/jenkins/workspace/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_0/aqa-tests/TKG/../TKG/lib/jcommander.jar:/Users/jenkins/workspace/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/JIT_Test/jitt.jar" org.testng.TestNG -d "/Users/jenkins/workspace/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_0/aqa-tests/TKG/../TKG/output_16638151285423/cmdLineTester_verbosetest_6" "/Users/jenkins/workspace/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/JIT_Test/testng.xml" -testnames AllocationTest -groups level.extended
Time spent starting: 6 milliseconds
JVMDUMP039I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError" at 2022/09/21 20:32:53 - please wait.
...
JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
Exception in thread "Thread-42" java.lang.OutOfMemoryError: Java heap space
    at java.util.TreeSet.<init>(TreeSet.java:124)
    at TestSuite.evaluateVariables(TestSuite.java:222)
    at TestSuite.evaluateVariables(TestSuite.java:146)
    at Output.match(Output.java:62)
    at Test$StreamMatcher.run(Test.java:497)
***[TEST INFO 2022/09/21 20:47:52] ProcessKiller detected a timeout after 900000 milliseconds!***
INFO: The current OS is 'Mac OS X'. 'Debug on timeout' is currently only supported on Linux.
***[TEST INFO 2022/09/21 20:47:52] executing kill -ABRT 16308***
***[TEST INFO 2022/09/21 20:47:52] kill -ABRT signal sent***
***[TEST INFO 2022/09/21 20:52:52] stdout timed out***
***[TEST INFO 2022/09/21 20:52:52] ABRT timed out***
***[TEST INFO 2022/09/21 20:52:52] executing kill -9 16308***
***[TEST INFO 2022/09/21 20:52:52] kill -9 signal sent***
***[TEST INFO 2022/09/21 20:52:52] ProcessKiller destroy test process after timeout***
Output from test:
 [OUT] [IncludeExcludeTestAnnotationTransformer] [INFO] EXCLUDE_FILE environment variable: /Users/jenkins/workspace/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_0/aqa-tests/TKG/../TestConfig/resources/excludes/latest_exclude_8.txt
 [OUT] [IncludeExcludeTestAnnotationTransformer] [INFO] Processing exclude file: /Users/jenkins/workspace/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_0/aqa-tests/TKG/../TestConfig/resources/excludes/latest_exclude_8.txt
 [OUT] ...
 [OUT] ... TestNG 6.14.2 by Cédric Beust (cedric@beust.com)
 [OUT] ...
 [OUT] 
 [OUT] [Allocation] [INFO] 100000 x ObjectAllocation.allocArrays (0) = 3
 [OUT] [Allocation] [INFO] 100000 x ObjectAllocation.allocArrays (100) = 20
...
 [ERR] <gc-op id="222" type="copy forward" timems="1.101" contextid="219" timestamp="2022-09-21T20:32:53.501">
 [ERR]   <memory-copied type="eden" objects="1" bytes="2016" bytesdiscarded="0" />
 [ERR]   <memory-copied type="other" objects="0" bytes="0" bytesdiscarded="0" />
 [ERR]   <memory-cardclean objects="0" bytes="0" />
 [ERR]   <regions eden="32" other="1" />
 [ERR]   <remembered-set-cleared processed="348" cleared="0" durationms="0.045" />
 [ERR]   <stringconstants candidates="2825" cleared="0"  />
Time spent executing: 1200087 milliseconds
Test result: FAILED

Internal build [Linux S390 64bit Compressed Pointers] 80 Load_Level_2.mauve.5mins.Mode557 -XX:+UseCompressedOops -Xgcpolicy:balanced -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:count=0

Ran 60x grinders, no repeats.

j> 02:59:23 20220922 02:59:22 Execution Timer INFO: Execution Timer started
j> 02:59:23 20220922 02:59:23 Thread Control Engine INFO: Starting JobSet Primary
j> 02:59:36 JVMDUMP039I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError" at 2022/09/22 02:59:35 - please wait.
...
j> 02:59:36 JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
p> 20220922-02:59:36 Dump /tmp/bld_37077/mauve.5mins/43415257/JLTF-mauve-mode557-20220922-0258/core.20220922.025935.61402.0001.dmp spotted.
p> 20220922-02:59:36 Attempted to collect /proc/pid/maps and /proc/pid/smaps
p> 20220922-02:59:36 Dump /tmp/bld_37077/mauve.5mins/43415257/JLTF-mauve-mode557-20220922-0258/heapdump.20220922.025935.61402.0002.phd spotted.
p> 20220922-02:59:36 Dump /tmp/bld_37077/mauve.5mins/43415257/JLTF-mauve-mode557-20220922-0258/javacore.20220922.025935.61402.0003.txt spotted.
p> 20220922-02:59:36 Dump /tmp/bld_37077/mauve.5mins/43415257/JLTF-mauve-mode557-20220922-0258/Snap.20220922.025935.61402.0004.trc spotted.
j> 02:59:37 20220922 02:59:36 <Primary|SimpleDriver|gnu.testlet.java.text.DecimalFormatSymbols.DumpDefault11|192|Default Invocant> ERROR: OutOfMemoryError thrown from arbitrary java method public static void gnu.testlet.SingleTestHarness.main(java.lang.String[]) throws java.lang.Exception
j> 02:59:37 Throwable trace:
j> 02:59:37 java.lang.OutOfMemoryError: Java heap space
j> 02:59:37     at java.lang.StringBuffer.toString(StringBuffer.java:1783)
j> 02:59:37     at gnu.testlet.java.text.DecimalFormatSymbols.DumpDefault11.test(Unknown Source)
j> 02:59:37     at gnu.testlet.SingleTestHarness.main(Unknown Source)
j> 02:59:37     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
j> 02:59:37     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:90)
j> 02:59:37     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
j> 02:59:37     at java.lang.reflect.Method.invoke(Method.java:508)
j> 02:59:37     at com.ibm.jtc.test.jltf.workunitadapters.ArbitraryJavaWorkUnit.runWork(ArbitraryJavaWorkUnit.java:445)
j> 02:59:37     at com.ibm.jtc.test.jltf.threads.WorkUnitRunner.run(WorkUnitRunner.java:113)
j> 02:59:37     at com.ibm.jtc.test.jltf.threads.pooling.PooledRunnable.runWork(PooledRunnable.java:170)
j> 02:59:37     at com.ibm.jtc.test.jltf.threads.pooling.PooledRunnable.getAndRunWork(PooledRunnable.java:136)
j> 02:59:37     at com.ibm.jtc.test.jltf.threads.pooling.PooledRunnable.run(PooledRunnable.java:93)
j> 02:59:37     at com.ibm.jtc.test.jltf.threads.PooledLangThreadFactory$JavaLangPooledThread.run(PooledLangThreadFactory.java:152)
j> 02:59:54 20220922 02:59:53 Runtime State Reporter IMPORTANT: 22705 tests complete, 0 currently running
...
j> 03:03:54 20220922 03:03:53 Runtime State Reporter IMPORTANT: 364405 tests complete, 0 currently running
j> 03:04:24 20220922 03:04:23 Thread Control Engine INFO: Stopping JobSet Primary
pshipton commented 2 years ago

Changes from previous build https://github.com/eclipse-openj9/openj9/compare/f06248f89...abdbf1dfbd9

In the internal build the changes are: https://github.com/eclipse-openj9/openj9/pull/15846 https://github.com/eclipse-openj9/openj9/pull/15827 https://github.com/eclipse-openj9/openj9/pull/15914

@gacholio @tajila

tajila commented 2 years ago

@pshipton Ill take a look, but none of these look likely. Were there omr changes as well?

dmitripivkine commented 2 years ago

If all cases are in Balanced, the problematic change might be https://github.com/eclipse-openj9/openj9/pull/14740 @amicic

tajila commented 2 years ago

The x86 and mac failures were with balanced, so it looks like its limited that policy

dmitripivkine commented 2 years ago

Change has been reverted. I hope it is one caused the problem

pshipton commented 2 years ago

I'll close this assuming it's fixed.