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.

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

jdk20 OpenJDK java/util/concurrent/locks/Lock/OOMEInAQS OOM crash vmState=0x00040000 #16659

Closed
pshipton opened this issue Feb 2, 2023 · 91 comments
Assignees
Labels
comp:vm jdk20 perm excluded The test is unsuitable and permanently excluded.

Comments

@pshipton
Copy link
Member

pshipton commented Feb 2, 2023

https://openj9-jenkins.osuosl.org/job/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/1
jdk_util.0
java/util/concurrent/locks/Lock/OOMEInAQS.java

11:34:55  ACTION: main -- Error. Program `/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/openjdkbinary/j2sdk-image/bin/java' timed out (timeout set to 960000ms, elapsed time including timeout handling was 1702367ms).
11:34:55  REASON: User specified action: run main/othervm -XX:-UseGCOverheadLimit -Xmx24M -XX:-UseTLAB OOMEInAQS 
11:34:55  TIME:   1702.467 seconds
11:34:55  messages:
11:34:55  command: main -XX:-UseGCOverheadLimit -Xmx24M -XX:-UseTLAB OOMEInAQS
11:34:55  reason: User specified action: run main/othervm -XX:-UseGCOverheadLimit -Xmx24M -XX:-UseTLAB OOMEInAQS 
11:34:55  started: Thu Feb 02 11:06:28 EST 2023
11:34:55  Mode: othervm [/othervm specified]
11:34:55  Timeout information:
11:34:55  Running jcmd on process 18895
11:34:55  Timeout refired 300 times
11:34:55  Error getting data from 18895: Exception connecting to 18895
11:34:55  Usage : jcmd <vmid> <arguments>
11:34:55  
11:34:55     -J : supply arguments to the Java VM running jcmd
11:34:55     -l : list JVM processes on the local machine
11:34:55     -h : print this help message
11:34:55  
11:34:55     <vmid> : Attach API VM ID as shown in jps or other Attach API-based tools
11:34:55  
11:34:55     arguments:
11:34:55        help : print the list of diagnostic commands
11:34:55        help <command> : print help for the specific command
11:34:55        <command> [command arguments] : command from the list returned by "help"
11:34:55  
11:34:55  list JVM processes on the local machine. Default behavior when no options are specified.
11:34:55  
11:34:55  NOTE: this utility might significantly affect the performance of the target JVM.
11:34:55      The available diagnostic commands are determined by
11:34:55      the target VM and may vary between VMs.
11:34:55  Timeout handler interrupted: 
11:34:55  java.lang.InterruptedException
11:34:55  	at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1691)
11:34:55  	at java.base/java.lang.ProcessImpl.waitFor(ProcessImpl.java:447)
11:34:55  	at jtreg.openj9.CoreDumpTimeoutHandler.runJcmdCommand(CoreDumpTimeoutHandler.java:117)
11:34:55  	at jtreg.openj9.CoreDumpTimeoutHandler.runJcmd(CoreDumpTimeoutHandler.java:137)
11:34:55  	at jtreg.openj9.CoreDumpTimeoutHandler.runActions(CoreDumpTimeoutHandler.java:55)
11:34:55  	at com.sun.javatest.regtest.TimeoutHandler.handleTimeout(TimeoutHandler.java:132)
11:34:55  	at com.sun.javatest.regtest.exec.ProcessCommand$2.run(ProcessCommand.java:317)
11:34:55  --- Timeout information end.
11:34:55  finished: Thu Feb 02 11:34:50 EST 2023
11:34:55  elapsed time (seconds): 1702.467
11:34:55  configuration:
11:34:55  STDOUT:
11:34:55  fillHeap time: 5817 millis, whole test time: 79838 millis
11:34:55  Timeout refired 960 times
11:34:55  STDERR:
11:34:55  JVMDUMP055I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError", exception "Java heap space" at 2023/02/02 11:06:28 - please wait.
11:34:55  JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/aqa-tests/TKG/output_16753524039056/jdk_util_0/work/scratch/0/javacore.20230202.110628.18895.0001.txt' in response to an event
11:34:55  JVMDUMP010I Java dump written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/aqa-tests/TKG/output_16753524039056/jdk_util_0/work/scratch/0/javacore.20230202.110628.18895.0001.txt
11:34:55  JVMDUMP032I JVM requested Snap dump using '/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/aqa-tests/TKG/output_16753524039056/jdk_util_0/work/scratch/0/Snap.20230202.110628.18895.0002.trc' in response to an event
11:34:55  JVMDUMP010I Snap dump written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/aqa-tests/TKG/output_16753524039056/jdk_util_0/work/scratch/0/Snap.20230202.110628.18895.0002.trc
11:34:55  JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
11:34:55  JVMDUMP055I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError", exception "Java heap space" at 2023/02/02 11:06:28 - please wait.
11:34:55  JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/aqa-tests/TKG/output_16753524039056/jdk_util_0/work/scratch/0/javacore.20230202.110628.18895.0003.txt' in response to an event
11:34:55  JVMDUMP010I Java dump written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/aqa-tests/TKG/output_16753524039056/jdk_util_0/work/scratch/0/javacore.20230202.110628.18895.0003.txt
11:34:55  JVMDUMP032I JVM requested Snap dump using '/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/aqa-tests/TKG/output_16753524039056/jdk_util_0/work/scratch/0/Snap.20230202.110628.18895.0004.trc' in response to an event
11:34:55  JVMDUMP010I Snap dump written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/aqa-tests/TKG/output_16753524039056/jdk_util_0/work/scratch/0/Snap.20230202.110628.18895.0004.trc
11:34:55  JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
11:34:55  JVMDUMP055I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError", exception "Java heap space" at 2023/02/02 11:06:29 - please wait.
11:34:55  JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/aqa-tests/TKG/output_16753524039056/jdk_util_0/work/scratch/0/javacore.20230202.110629.18895.0005.txt' in response to an event
11:34:55  JVMDUMP010I Java dump written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/aqa-tests/TKG/output_16753524039056/jdk_util_0/work/scratch/0/javacore.20230202.110629.18895.0005.txt
11:34:55  JVMDUMP032I JVM requested Snap dump using '/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/aqa-tests/TKG/output_16753524039056/jdk_util_0/work/scratch/0/Snap.20230202.110629.18895.0006.trc' in response to an event
11:34:55  JVMDUMP010I Snap dump written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/aqa-tests/TKG/output_16753524039056/jdk_util_0/work/scratch/0/Snap.20230202.110629.18895.0006.trc
11:34:55  JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
11:34:55  JVMDUMP055I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError", exception "Java heap space" at 2023/02/02 11:06:29 - please wait.
11:34:55  JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/aqa-tests/TKG/output_16753524039056/jdk_util_0/work/scratch/0/javacore.20230202.110629.18895.0007.txt' in response to an event
11:34:55  JVMDUMP010I Java dump written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/aqa-tests/TKG/output_16753524039056/jdk_util_0/work/scratch/0/javacore.20230202.110629.18895.0007.txt
11:34:55  JVMDUMP032I JVM requested Snap dump using '/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/aqa-tests/TKG/output_16753524039056/jdk_util_0/work/scratch/0/Snap.20230202.110629.18895.0008.trc' in response to an event
11:34:55  JVMDUMP010I Snap dump written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_s390x_linux_OpenJDK20/aqa-tests/TKG/output_16753524039056/jdk_util_0/work/scratch/0/Snap.20230202.110629.18895.0008.trc
11:34:55  JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
11:34:55  Exception in thread "Attach API wait loop" java/lang/OutOfMemoryError: Java heap space
11:34:55  	at java/lang/Throwable.printStackTrace (java.base@20-internal/Throwable.java:554)
11:34:55  	at java/lang/Throwable.printStackTraceHelper (java.base@20-internal/Throwable.java:338)
11:34:55  	at java/lang/Throwable.printStackTrace (java.base@20-internal/Throwable.java:307)
11:34:55  	at java/lang/Throwable.printStackTrace (java.base@20-internal/Throwable.java:250)
11:34:55  STATUS:Passed.
11:34:55  Unhandled exception
11:34:55  Type=Segmentation error vmState=0x00040000
11:34:55  J9Generic_Signal_Number=00000018 Signal_Number=0000000b Error_Value=000000a9 Signal_Code=00000001
11:34:55  Handler1=000003FF9FD444B8 Handler2=000003FF9FC31CF0 InaccessibleAddress=0000000000000000
11:34:55  gpr0=000003FF00000002 gpr1=000003FFA468A1E0 gpr2=00000000000004A0 gpr3=0000000000000000
11:34:55  gpr4=000003FF9FB8C610 gpr5=0000000000000001 gpr6=000000000C957BD0 gpr7=000003FF97B56328
11:34:55  gpr8=00000000000004A0 gpr9=000003FF9FB98360 gpr10=000003FFA026EFA0 gpr11=0000000000000000
11:34:55  gpr12=000003FF24000A28 gpr13=00000000000004A0 gpr14=000003FF9FB8C61A gpr15=000003FF9F9FDC70
11:34:55  psw=000003FFA468A1EA mask=0705200180000000 fpc=0008fe00 bea=000003FF9FB845AC
11:34:55  fpr0 000000000000c010 (f: 49168.000000, d: 2.429222e-319)
11:34:55  fpr1 48dbdc2000000000 (f: 0.000000, d: 9.707746e+42)
11:34:55  fpr2 0000000000000000 (f: 0.000000, d: 0.000000e+00)
11:34:55  fpr3 3674da7000100000 (f: 1048576.000000, d: 2.282942e-46)
11:34:55  fpr4 000003ff4547b7b0 (f: 1162327936.000000, d: 2.171376e-311)
11:34:55  fpr5 3e92492500000000 (f: 0.000000, d: 2.724785e-07)
11:34:55  fpr6 0000000000100000 (f: 1048576.000000, d: 5.180654e-318)
11:34:55  fpr7 3e3a332500000000 (f: 0.000000, d: 6.100112e-09)
11:34:55  fpr8 0000000000000000 (f: 0.000000, d: 0.000000e+00)
11:34:55  fpr9 000000000053f3b8 (f: 5501880.000000, d: 2.718290e-317)
11:34:55  fpr10 000003ffa001ee60 (f: 2684481024.000000, d: 2.172128e-311)
11:34:55  fpr11 0000000000c92438 (f: 13182008.000000, d: 6.512777e-317)
11:34:55  fpr12 0005f3b9bf592484 (f: 3210290432.000000, d: 8.277349e-309)
11:34:55  fpr13 000003ff14006fa8 (f: 335572896.000000, d: 2.170967e-311)
11:34:55  fpr14 000000000053f3c0 (f: 5501888.000000, d: 2.718294e-317)
11:34:55  fpr15 000003ff1404dc88 (f: 335862912.000000, d: 2.170968e-311)
11:34:55  Module=/lib64/libpthread.so.0
11:34:55  Module_base_address=000003FFA4680000 Symbol=pthread_mutex_lock
11:34:55  Symbol_address=000003FFA468A1E0
11:34:55  Target=2_90_20230202_1 (Linux 3.10.0-1160.76.1.el7.s390x)
11:34:55  CPU=s390x (4 logical CPUs) (0x1ec1b1000 RAM)
11:34:55  ----------- Stack Backtrace -----------
11:34:55  pthread_mutex_lock+0xa (0x000003FFA468A1EA [libpthread.so.0+0xa1ea])
11:34:55  omrthread_interrupt+0x62 (0x000003FF9FB8C61A [libj9thr29.so+0xc61a])
11:34:55  Java_java_lang_Thread_interruptImpl+0x84 (0x000003FF97B563AC [libjclse29.so+0x563ac])
11:34:55  ffi_call_SYSV+0x54 (0x000003FF9FF17014 [libj9vm29.so+0x217014])
11:34:55  ffi_call+0xa2 (0x000003FF9FF16A5A [libj9vm29.so+0x216a5a])
11:34:55  _ZN32VM_BytecodeInterpreterCompressed3runEP10J9VMThread+0x154c6 (0x000003FF9FDBDD36 [libj9vm29.so+0xbdd36])
11:34:55  bytecodeLoopCompressed+0xce (0x000003FF9FDA885E [libj9vm29.so+0xa885e])
11:34:55  c_cInterpreter+0x64 (0x000003FF9FE91694 [libj9vm29.so+0x191694])
11:34:55  ---------------------------------------
@pshipton
Copy link
Member Author

pshipton commented Feb 7, 2023

5x grinder https://openj9-jenkins.osuosl.org/job/Grinder/1984/ - passed 10 iterations, 5 each in modes 0, 1.

@pshipton pshipton removed this from the Java 20 milestone Feb 7, 2023
@pshipton
Copy link
Member Author

pshipton commented Mar 2, 2023

https://openj9-jenkins.osuosl.org/job/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/5
jdk_util_1 - these run with -Xdump:system:none
java/util/concurrent/locks/Lock/OOMEInAQS.java

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/5/openjdk_test_output.tar.gz

23:16:41  ACTION: main -- Failed. Execution failed: `main' threw exception: java.lang.OutOfMemoryError: Java heap space
23:16:41  REASON: User specified action: run main/othervm -XX:-UseGCOverheadLimit -Xmx24M -XX:-UseTLAB OOMEInAQS 
23:16:41  TIME:   47.849 seconds
23:16:41  messages:
23:16:41  command: main -XX:-UseGCOverheadLimit -Xmx24M -XX:-UseTLAB OOMEInAQS
23:16:41  reason: User specified action: run main/othervm -XX:-UseGCOverheadLimit -Xmx24M -XX:-UseTLAB OOMEInAQS 
23:16:41  started: Wed Mar 01 23:15:52 EST 2023
23:16:41  Mode: othervm [/othervm specified]
23:16:41  finished: Wed Mar 01 23:16:40 EST 2023
23:16:41  elapsed time (seconds): 47.849
23:16:41  configuration:
23:16:41  STDOUT:
23:16:41  STDERR:
23:16:41  JVMDUMP055I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError", exception "Java heap space" at 2023/03/01 23:15:53 - please wait.
23:16:41  JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/aqa-tests/TKG/output_16777248415384/jdk_util_1/work/scratch/0/javacore.20230301.231553.6046.0001.txt' in response to an event
23:16:41  JVMDUMP010I Java dump written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/aqa-tests/TKG/output_16777248415384/jdk_util_1/work/scratch/0/javacore.20230301.231553.6046.0001.txt
23:16:41  JVMDUMP032I JVM requested Snap dump using '/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/aqa-tests/TKG/output_16777248415384/jdk_util_1/work/scratch/0/Snap.20230301.231553.6046.0002.trc' in response to an event
23:16:41  JVMDUMP010I Snap dump written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/aqa-tests/TKG/output_16777248415384/jdk_util_1/work/scratch/0/Snap.20230301.231553.6046.0002.trc
23:16:41  JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
23:16:41  JVMDUMP055I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError", exception "Java heap space" at 2023/03/01 23:15:53 - please wait.
23:16:41  JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/aqa-tests/TKG/output_16777248415384/jdk_util_1/work/scratch/0/javacore.20230301.231553.6046.0003.txt' in response to an event
23:16:41  JVMDUMP010I Java dump written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/aqa-tests/TKG/output_16777248415384/jdk_util_1/work/scratch/0/javacore.20230301.231553.6046.0003.txt
23:16:41  JVMDUMP032I JVM requested Snap dump using '/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/aqa-tests/TKG/output_16777248415384/jdk_util_1/work/scratch/0/Snap.20230301.231553.6046.0004.trc' in response to an event
23:16:41  JVMDUMP010I Snap dump written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/aqa-tests/TKG/output_16777248415384/jdk_util_1/work/scratch/0/Snap.20230301.231553.6046.0004.trc
23:16:41  JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
23:16:41  JVMDUMP055I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError", exception "Java heap space" at 2023/03/01 23:15:53 - please wait.
23:16:41  JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/aqa-tests/TKG/output_16777248415384/jdk_util_1/work/scratch/0/javacore.20230301.231553.6046.0005.txt' in response to an event
23:16:41  JVMDUMP010I Java dump written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/aqa-tests/TKG/output_16777248415384/jdk_util_1/work/scratch/0/javacore.20230301.231553.6046.0005.txt
23:16:41  JVMDUMP032I JVM requested Snap dump using '/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/aqa-tests/TKG/output_16777248415384/jdk_util_1/work/scratch/0/Snap.20230301.231553.6046.0006.trc' in response to an event
23:16:41  JVMDUMP010I Snap dump written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/aqa-tests/TKG/output_16777248415384/jdk_util_1/work/scratch/0/Snap.20230301.231553.6046.0006.trc
23:16:41  JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
23:16:41  JVMDUMP055I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError", exception "Java heap space" at 2023/03/01 23:15:53 - please wait.
23:16:41  JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/aqa-tests/TKG/output_16777248415384/jdk_util_1/work/scratch/0/javacore.20230301.231553.6046.0007.txt' in response to an event
23:16:41  JVMDUMP010I Java dump written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/aqa-tests/TKG/output_16777248415384/jdk_util_1/work/scratch/0/javacore.20230301.231553.6046.0007.txt
23:16:41  JVMDUMP032I JVM requested Snap dump using '/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/aqa-tests/TKG/output_16777248415384/jdk_util_1/work/scratch/0/Snap.20230301.231553.6046.0008.trc' in response to an event
23:16:41  JVMDUMP010I Snap dump written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/aqa-tests/TKG/output_16777248415384/jdk_util_1/work/scratch/0/Snap.20230301.231553.6046.0008.trc
23:16:41  JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
23:16:41  Exception in thread "Attach API wait loop" java/lang/OutOfMemoryError: Java heap space
23:16:41  	at java/lang/Throwable.printStackTrace (java.base@20-internal/Throwable.java:554)
23:16:41  	at java/lang/Throwable.printStackTraceHelper (java.base@20-internal/Throwable.java:338)
23:16:41  	at java/lang/Throwable.printStackTrace (java.base@20-internal/Throwable.java:307)
23:16:41  	at java/lang/Throwable.printStackTrace (java.base@20-internal/Throwable.java:250)
23:16:41  java.lang.OutOfMemoryError: Java heap space
23:16:41  	at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.newConditionNode(AbstractQueuedSynchronizer.java:1622)
23:16:41  	at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1692)
23:16:41  	at OOMEInAQS.run(OOMEInAQS.java:104)
23:16:41  
23:16:41  JavaTest Message: Test threw exception: java.lang.OutOfMemoryError: Java heap space
23:16:41  JavaTest Message: shutting down test
23:16:41  
23:16:41  STATUS:Failed.`main' threw exception: java.lang.OutOfMemoryError: Java heap space
1STHEAPTYPE    Object Memory
NULL           id                 start              end                size               space/region
1STHEAPSPACE   0x00007FB61C0B7E50         --                 --                 --         Generational
1STHEAPREGION  0x00007FB61C0B87C0 0x00007FB6142B0000 0x00007FB615810000 0x0000000001560000 Generational/Tenured Region
1STHEAPREGION  0x00007FB61C0B8370 0x00007FB615810000 0x00007FB615900000 0x00000000000F0000 Generational/Nursery Region
1STHEAPREGION  0x00007FB61C0B7F20 0x00007FB615900000 0x00007FB615AB0000 0x00000000001B0000 Generational/Nursery Region
NULL
1STHEAPTOTAL   Total memory:                    25165824 (0x0000000001800000)
1STHEAPINUSE   Total memory in use:             19132256 (0x000000000123EF60)
1STHEAPFREE    Total memory free:                6033568 (0x00000000005C10A0)
1STGCHTYPE     GC History
3STHSTTYPE     04:15:53:095166000 GMT j9mm.101 -   J9AllocateIndexableObject() returning NULL! 8388632 bytes requested for object of class 00007FB61C1A5600 from memory space 'Generational' id=00007FB61C0B7E50
3STHSTTYPE     04:15:53:095122000 GMT j9mm.134 -   Allocation failure end: newspace=1769472/2752512 oldspace=4268192/22413312 loa=224256/224256
3STHSTTYPE     04:15:53:095116000 GMT j9mm.470 -   Allocation failure cycle end: newspace=1769472/2752512 oldspace=4268192/22413312 loa=224256/224256
3STHSTTYPE     04:15:53:095074000 GMT j9mm.475 -   GlobalGC end: workstackoverflow=0 overflowcount=0 memory=6037664/25165824
3STHSTTYPE     04:15:53:095013000 GMT j9mm.90 -   GlobalGC collect complete
3STHSTTYPE     04:15:53:094943000 GMT j9mm.137 -   Compact end: bytesmoved=17825024
3STHSTTYPE     04:15:53:065952000 GMT j9mm.136 -   Compact start: reason=compact to meet allocation
3STHSTTYPE     04:15:53:065948000 GMT j9mm.57 -   Sweep end
3STHSTTYPE     04:15:53:064961000 GMT j9mm.56 -   Sweep start
3STHSTTYPE     04:15:53:064959000 GMT j9mm.94 -   Class unloading end: classloadersunloaded=0 classesunloaded=7
3STHSTTYPE     04:15:53:064535000 GMT j9mm.60 -   Class unloading start
3STHSTTYPE     04:15:53:064533000 GMT j9mm.55 -   Mark end
3STHSTTYPE     04:15:53:058255000 GMT j9mm.54 -   Mark start
3STHSTTYPE     04:15:53:058204000 GMT j9mm.474 -   GlobalGC start: globalcount=3
3STHSTTYPE     04:15:53:058122000 GMT j9mm.475 -   GlobalGC end: workstackoverflow=0 overflowcount=0 memory=6026624/25165824
3STHSTTYPE     04:15:53:058054000 GMT j9mm.90 -   GlobalGC collect complete
3STHSTTYPE     04:15:53:057994000 GMT j9mm.137 -   Compact end: bytesmoved=50728
3STHSTTYPE     04:15:53:045409000 GMT j9mm.136 -   Compact start: reason=compact to meet allocation
3STHSTTYPE     04:15:53:045404000 GMT j9mm.57 -   Sweep end
3STHSTTYPE     04:15:53:044480000 GMT j9mm.56 -   Sweep start
3STHSTTYPE     04:15:53:044478000 GMT j9mm.55 -   Mark end
3STHSTTYPE     04:15:53:037133000 GMT j9mm.54 -   Mark start
3STHSTTYPE     04:15:53:037080000 GMT j9mm.474 -   GlobalGC start: globalcount=2
3STHSTTYPE     04:15:53:037059000 GMT j9mm.135 -   Exclusive access: exclusiveaccessms=0.035 meanexclusiveaccessms=0.035 threads=0 lastthreadtid=0x00007FB61C3EA148 beatenbyotherthread=0
3STHSTTYPE     04:15:53:037058000 GMT j9mm.469 -   Allocation failure cycle start: newspace=1769472/2752512 oldspace=4098096/22413312 loa=1569792/1569792 requestedbytes=8388632
3STHSTTYPE     04:15:53:037027000 GMT j9mm.470 -   Allocation failure cycle end: newspace=1769472/2752512 oldspace=4098096/22413312 loa=1569792/1569792
3STHSTTYPE     04:15:53:036994000 GMT j9mm.468 -   Cycle End: type 2 approximateFreeMemorySize 5867568
3STHSTTYPE     04:15:53:036942000 GMT j9mm.560 -   LocalGC end: rememberedsetoverflow=0 causedrememberedsetoverflow=0 scancacheoverflow=0 failedflipcount=0 failedflipbytes=0 failedtenurecount=0 failedtenurebytes=0 flipcount=0 flipbytes=0 newspace=1769472/2752512 oldspace=4098096/22413312 loa=1569792/1569792 tenureage=0
3STHSTTYPE     04:15:53:036801000 GMT j9mm.140 -   Tilt ratio: 54
3STHSTTYPE     04:15:53:030938000 GMT j9mm.64 -   LocalGC start: globalcount=2 scavengecount=6 weakrefs=0 soft=0 phantom=0 finalizers=0
3STHSTTYPE     04:15:53:030921000 GMT j9mm.467 -   Cycle Start: type 2 approximateFreeMemorySize 5764480
3STHSTTYPE     04:15:53:030874000 GMT j9mm.135 -   Exclusive access: exclusiveaccessms=0.035 meanexclusiveaccessms=0.035 threads=0 lastthreadtid=0x00007FB61C3EA148 beatenbyotherthread=0
3STHSTTYPE     04:15:53:030872000 GMT j9mm.469 -   Allocation failure cycle start: newspace=1417552/2752512 oldspace=4346928/22413312 loa=1569792/1569792 requestedbytes=8388632
3STHSTTYPE     04:15:53:030871000 GMT j9mm.133 -   Allocation failure start: newspace=1417552/2752512 oldspace=4346928/22413312 loa=1569792/1569792 requestedbytes=8388632
3STHSTTYPE     04:15:53:030701000 GMT j9mm.134 -   Allocation failure end: newspace=1417552/2752512 oldspace=4346928/22413312 loa=1569792/1569792
3STHSTTYPE     04:15:53:014624000 GMT j9mm.470 -   Allocation failure cycle end: newspace=1417552/2752512 oldspace=4346928/22413312 loa=1569792/1569792
3STHSTTYPE     04:15:53:014584000 GMT j9mm.475 -   GlobalGC end: workstackoverflow=0 overflowcount=0 memory=5764480/25165824
3STHSTTYPE     04:15:53:014418000 GMT j9mm.90 -   GlobalGC collect complete
3STHSTTYPE     04:15:53:014353000 GMT j9mm.137 -   Compact end: bytesmoved=89776
3STHSTTYPE     04:15:53:002257000 GMT j9mm.136 -   Compact start: reason=compact to meet allocation
3STHSTTYPE     04:15:53:002253000 GMT j9mm.57 -   Sweep end
3STHSTTYPE     04:15:53:001597000 GMT j9mm.56 -   Sweep start
3STHSTTYPE     04:15:53:001596000 GMT j9mm.55 -   Mark end
3STHSTTYPE     04:15:52:997481000 GMT j9mm.54 -   Mark start
3STHSTTYPE     04:15:52:997431000 GMT j9mm.474 -   GlobalGC start: globalcount=1
3STHSTTYPE     04:15:52:997411000 GMT j9mm.135 -   Exclusive access: exclusiveaccessms=0.037 meanexclusiveaccessms=0.037 threads=0 lastthreadtid=0x00007FB61C3EA148 beatenbyotherthread=0
3STHSTTYPE     04:15:52:997411000 GMT j9mm.469 -   Allocation failure cycle start: newspace=1258496/2752512 oldspace=5067848/14745600 loa=884736/884736 requestedbytes=8388632
3STHSTTYPE     04:15:52:997391000 GMT j9mm.470 -   Allocation failure cycle end: newspace=1258496/2752512 oldspace=5067848/14745600 loa=884736/884736
3STHSTTYPE     04:15:52:997364000 GMT j9mm.468 -   Cycle End: type 2 approximateFreeMemorySize 6326344
3STHSTTYPE     04:15:52:997342000 GMT j9mm.560 -   LocalGC end: rememberedsetoverflow=0 causedrememberedsetoverflow=0 scancacheoverflow=0 failedflipcount=0 failedflipbytes=0 failedtenurecount=0 failedtenurebytes=0 flipcount=1278 flipbytes=89776 newspace=1258496/2752512 oldspace=5067848/14745600 loa=884736/884736 tenureage=0
3STHSTTYPE     04:15:52:997214000 GMT j9mm.140 -   Tilt ratio: 50
3STHSTTYPE     04:15:52:994819000 GMT j9mm.64 -   LocalGC start: globalcount=1 scavengecount=5 weakrefs=0 soft=0 phantom=0 finalizers=0
3STHSTTYPE     04:15:52:994803000 GMT j9mm.467 -   Cycle Start: type 2 approximateFreeMemorySize 6288792
3STHSTTYPE     04:15:52:994758000 GMT j9mm.135 -   Exclusive access: exclusiveaccessms=0.037 meanexclusiveaccessms=0.037 threads=0 lastthreadtid=0x00007FB61C3EA148 beatenbyotherthread=0
3STHSTTYPE     04:15:52:994757000 GMT j9mm.469 -   Allocation failure cycle start: newspace=1220944/2621440 oldspace=5067848/14745600 loa=884736/884736 requestedbytes=8388632
3STHSTTYPE     04:15:52:994743000 GMT j9mm.133 -   Allocation failure start: newspace=1220944/2621440 oldspace=5067848/14745600 loa=884736/884736 requestedbytes=8388632
3STHSTTYPE     04:15:52:994588000 GMT j9mm.134 -   Allocation failure end: newspace=1220944/2621440 oldspace=5067848/14745600 loa=884736/884736
3STHSTTYPE     04:15:52:977877000 GMT j9mm.470 -   Allocation failure cycle end: newspace=1220944/2621440 oldspace=5067848/14745600 loa=884736/884736
3STHSTTYPE     04:15:52:977819000 GMT j9mm.475 -   GlobalGC end: workstackoverflow=0 overflowcount=0 memory=6288792/17367040
3STHSTTYPE     04:15:52:977673000 GMT j9mm.90 -   GlobalGC collect complete
3STHSTTYPE     04:15:52:977614000 GMT j9mm.137 -   Compact end: bytesmoved=1088040
3STHSTTYPE     04:15:52:971567000 GMT j9mm.136 -   Compact start: reason=compact to meet allocation
3STHSTTYPE     04:15:52:971563000 GMT j9mm.57 -   Sweep end
3STHSTTYPE     04:15:52:970976000 GMT j9mm.56 -   Sweep start
3STHSTTYPE     04:15:52:970973000 GMT j9mm.94 -   Class unloading end: classloadersunloaded=0 classesunloaded=0
3STHSTTYPE     04:15:52:970941000 GMT j9mm.60 -   Class unloading start
3STHSTTYPE     04:15:52:970941000 GMT j9mm.55 -   Mark end
3STHSTTYPE     04:15:52:967177000 GMT j9mm.54 -   Mark start
3STHSTTYPE     04:15:52:967059000 GMT j9mm.474 -   GlobalGC start: globalcount=0
3STHSTTYPE     04:15:52:966996000 GMT j9mm.135 -   Exclusive access: exclusiveaccessms=0.062 meanexclusiveaccessms=0.062 threads=0 lastthreadtid=0x00007FB61C3EA148 beatenbyotherthread=0
3STHSTTYPE     04:15:52:966995000 GMT j9mm.469 -   Allocation failure cycle start: newspace=1131776/2621440 oldspace=4738360/6291456 loa=315392/315392 requestedbytes=8388632
3STHSTTYPE     04:15:52:966976000 GMT j9mm.470 -   Allocation failure cycle end: newspace=1131776/2621440 oldspace=4738360/6291456 loa=315392/315392
3STHSTTYPE     04:15:52:966948000 GMT j9mm.468 -   Cycle End: type 2 approximateFreeMemorySize 5870136
3STHSTTYPE     04:15:52:966924000 GMT j9mm.560 -   LocalGC end: rememberedsetoverflow=0 causedrememberedsetoverflow=0 scancacheoverflow=0 failedflipcount=0 failedflipbytes=0 failedtenurecount=0 failedtenurebytes=0 flipcount=1279 flipbytes=89880 newspace=1131776/2621440 oldspace=4738360/6291456 loa=315392/315392 tenureage=0
3STHSTTYPE     04:15:52:966825000 GMT j9mm.140 -   Tilt ratio: 50
3STHSTTYPE     04:15:52:964269000 GMT j9mm.64 -   LocalGC start: globalcount=0 scavengecount=4 weakrefs=0 soft=0 phantom=0 finalizers=0
3STHSTTYPE     04:15:52:964251000 GMT j9mm.467 -   Cycle Start: type 2 approximateFreeMemorySize 5434352
3STHSTTYPE     04:15:52:964207000 GMT j9mm.135 -   Exclusive access: exclusiveaccessms=0.062 meanexclusiveaccessms=0.062 threads=0 lastthreadtid=0x00007FB61C3EA148 beatenbyotherthread=0
3STHSTTYPE     04:15:52:964205000 GMT j9mm.469 -   Allocation failure cycle start: newspace=360296/2621440 oldspace=5074056/6291456 loa=315392/315392 requestedbytes=8388632
3STHSTTYPE     04:15:52:964204000 GMT j9mm.133 -   Allocation failure start: newspace=360296/2621440 oldspace=5074056/6291456 loa=315392/315392 requestedbytes=8388632
3STHSTTYPE     04:15:52:891069000 GMT j9mm.134 -   Allocation failure end: newspace=908112/2621440 oldspace=5104072/6291456 loa=315392/315392
3STHSTTYPE     04:15:52:891056000 GMT j9mm.470 -   Allocation failure cycle end: newspace=909160/2621440 oldspace=5104072/6291456 loa=315392/315392
3STHSTTYPE     04:15:52:891038000 GMT j9mm.468 -   Cycle End: type 2 approximateFreeMemorySize 6013232
3STHSTTYPE     04:15:52:891015000 GMT j9mm.560 -   LocalGC end: rememberedsetoverflow=0 causedrememberedsetoverflow=0 scancacheoverflow=0 failedflipcount=0 failedflipbytes=0 failedtenurecount=0 failedtenurebytes=0 flipcount=845 flipbytes=320080 newspace=909160/2621440 oldspace=5104072/6291456 loa=315392/315392 tenureage=0
3STHSTTYPE     04:15:52:890828000 GMT j9mm.140 -   Tilt ratio: 50
3STHSTTYPE     04:15:52:887246000 GMT j9mm.64 -   LocalGC start: globalcount=0 scavengecount=3 weakrefs=0 soft=0 phantom=0 finalizers=0
3STHSTTYPE     04:15:52:887236000 GMT j9mm.467 -   Cycle Start: type 2 approximateFreeMemorySize 5880568
3STHSTTYPE     04:15:52:887202000 GMT j9mm.135 -   Exclusive access: exclusiveaccessms=0.114 meanexclusiveaccessms=0.072 threads=1 lastthreadtid=0x00007FB5F4004448 beatenbyotherthread=0
3STHSTTYPE     04:15:52:887201000 GMT j9mm.469 -   Allocation failure cycle start: newspace=0/2228224 oldspace=5880568/6291456 loa=315392/315392 requestedbytes=1048
3STHSTTYPE     04:15:52:887199000 GMT j9mm.133 -   Allocation failure start: newspace=0/2228224 oldspace=5880568/6291456 loa=315392/315392 requestedbytes=1048
3STHSTTYPE     04:15:52:881081000 GMT j9mm.134 -   Allocation failure end: newspace=89136/2228224 oldspace=5920608/6291456 loa=315392/315392
3STHSTTYPE     04:15:52:881065000 GMT j9mm.470 -   Allocation failure cycle end: newspace=93792/2228224 oldspace=5920608/6291456 loa=315392/315392
3STHSTTYPE     04:15:52:881029000 GMT j9mm.468 -   Cycle End: type 2 approximateFreeMemorySize 6014400
3STHSTTYPE     04:15:52:881005000 GMT j9mm.560 -   LocalGC end: rememberedsetoverflow=0 causedrememberedsetoverflow=0 scancacheoverflow=0 failedflipcount=0 failedflipbytes=0 failedtenurecount=0 failedtenurebytes=0 flipcount=8367 flipbytes=855704 newspace=93792/2228224 oldspace=5920608/6291456 loa=315392/315392 tenureage=0
3STHSTTYPE     04:15:52:880839000 GMT j9mm.140 -   Tilt ratio: 50
3STHSTTYPE     04:15:52:877794000 GMT j9mm.64 -   LocalGC start: globalcount=0 scavengecount=2 weakrefs=0 soft=0 phantom=0 finalizers=0
3STHSTTYPE     04:15:52:877776000 GMT j9mm.467 -   Cycle Start: type 2 approximateFreeMemorySize 5920608
3STHSTTYPE     04:15:52:877732000 GMT j9mm.135 -   Exclusive access: exclusiveaccessms=0.126 meanexclusiveaccessms=0.084 threads=1 lastthreadtid=0x00007FB61C3EA148 beatenbyotherthread=0
3STHSTTYPE     04:15:52:877731000 GMT j9mm.469 -   Allocation failure cycle start: newspace=0/2097152 oldspace=5920608/6291456 loa=315392/315392 requestedbytes=4656
3STHSTTYPE     04:15:52:877729000 GMT j9mm.133 -   Allocation failure start: newspace=0/2097152 oldspace=5920608/6291456 loa=315392/315392 requestedbytes=4656
3STHSTTYPE     04:15:52:853925000 GMT j9mm.134 -   Allocation failure end: newspace=338528/2097152 oldspace=5947512/6291456 loa=315392/315392
3STHSTTYPE     04:15:52:853911000 GMT j9mm.470 -   Allocation failure cycle end: newspace=339152/2097152 oldspace=5947512/6291456 loa=315392/315392
3STHSTTYPE     04:15:52:853894000 GMT j9mm.468 -   Cycle End: type 2 approximateFreeMemorySize 6286664
3STHSTTYPE     04:15:52:853870000 GMT j9mm.560 -   LocalGC end: rememberedsetoverflow=0 causedrememberedsetoverflow=0 scancacheoverflow=0 failedflipcount=0 failedflipbytes=0 failedtenurecount=0 failedtenurebytes=0 flipcount=8075 flipbytes=580192 newspace=339152/2097152 oldspace=5947512/6291456 loa=315392/315392 tenureage=0
3STHSTTYPE     04:15:52:853737000 GMT j9mm.140 -   Tilt ratio: 50
3STHSTTYPE     04:15:52:850218000 GMT j9mm.64 -   LocalGC start: globalcount=0 scavengecount=1 weakrefs=0 soft=0 phantom=0 finalizers=0
3STHSTTYPE     04:15:52:850146000 GMT j9mm.467 -   Cycle Start: type 2 approximateFreeMemorySize 5947512
3STHSTTYPE     04:15:52:850053000 GMT j9mm.135 -   Exclusive access: exclusiveaccessms=0.043 meanexclusiveaccessms=0.043 threads=0 lastthreadtid=0x00007FB61C0E7648 beatenbyotherthread=0
3STHSTTYPE     04:15:52:850052000 GMT j9mm.469 -   Allocation failure cycle start: newspace=0/2097152 oldspace=5947512/6291456 loa=315392/315392 requestedbytes=624
3STHSTTYPE     04:15:52:850048000 GMT j9mm.133 -   Allocation failure start: newspace=0/2097152 oldspace=5947512/6291456 loa=315392/315392 requestedbytes=624
1XMCURTHDINFO  Current thread
3XMTHREADINFO      "MainThread" J9VMThread:0x00007FB61C3E9700, omrthread_t:0x00007FB61C3E5450, java/lang/Thread:0x00007FB6153F2C68, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x17, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00007FB61431E030)
3XMTHREADINFO1            (native thread ID:0x1C28, native priority:0x5, native policy:UNKNOWN, vmstate:R, vm thread flags:0x00041020)
3XMTHREADINFO2            (native stack address range from:0x00007FB5F83C1000, to:0x00007FB5F8441000, size:0x80000)
3XMCPUTIME               CPU usage total: 0.163338429 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=4096 (0x1000)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at OOMEInAQS.fillHeap(OOMEInAQS.java:129)
4XESTACKTRACE                at OOMEInAQS.main(OOMEInAQS.java:71)

@pshipton
Copy link
Member Author

pshipton commented Mar 2, 2023

@summary Check that AQS-based locks, conditions, and CountDownLatches do not fail when encountering OOME

The test is new for jdk20, and the OOM is intentional.

@pshipton pshipton added this to the Java 20 0.39? milestone Mar 21, 2023
@pshipton
Copy link
Member Author

@pshipton
Copy link
Member Author

pshipton commented Apr 3, 2023

https://openj9-jenkins.osuosl.org/job/Test_openjdk20_j9_sanity.openjdk_s390x_linux_Nightly/26
https://openj9-jenkins.osuosl.org/job/Test_openjdk20_j9_sanity.openjdk_x86-64_linux_Nightly/26

Crash on zlinux
https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk20_j9_sanity.openjdk_s390x_linux_Nightly/29/openjdk_test_output.tar.gz

00:18:42  Type=Segmentation error vmState=0x00040000
00:18:42  J9Generic_Signal_Number=00000018 Signal_Number=0000000b Error_Value=00000000 Signal_Code=00000001
00:18:42  Handler1=000003FF877448C8 Handler2=000003FF87631998 InaccessibleAddress=0000000000000000
00:18:42  gpr0=000003FF8747DE70 gpr1=000003FF8818A590 gpr2=00000000000004A0 gpr3=000003FF00000000
00:18:42  gpr4=000003FF8819F2E8 gpr5=0000000000000068 gpr6=00000000001597F8 gpr7=000003FF85256E08
00:18:42  gpr8=00000000000004A0 gpr9=000003FF87598360 gpr10=000003FF8028ABD0 gpr11=0000000000000000
00:18:42  gpr12=000003FF0C000CC8 gpr13=000003FF8792AB64 gpr14=000003FF8758C5B2 gpr15=000003FF8747DC58
00:18:42  psw=000003FF8818A590 mask=0705200180000000 fpc=00080000 bea=000003FF875845AC
00:18:42  fpr0 000000000000c010 (f: 49168.000000, d: 2.429222e-319)
00:18:42  fpr1 494d87c08747b670 (f: 2269623808.000000, d: 1.317095e+45)
00:18:42  fpr2 0000000000021018 (f: 135192.000000, d: 6.679372e-319)
00:18:42  fpr3 3f336e21dbeabbfe (f: 3689593856.000000, d: 2.964814e-04)
00:18:42  fpr4 0000000000000000 (f: 0.000000, d: 0.000000e+00)
00:18:42  fpr5 0000000000000000 (f: 0.000000, d: 0.000000e+00)
00:18:42  fpr6 000003ff2d47b830 (f: 759674944.000000, d: 2.171177e-311)
00:18:42  fpr7 0000000000000000 (f: 0.000000, d: 0.000000e+00)
00:18:42  fpr8 0000000000000000 (f: 0.000000, d: 0.000000e+00)
00:18:42  fpr9 0000000000000000 (f: 0.000000, d: 0.000000e+00)
00:18:42  fpr10 000003ff8743f000 (f: 2269376512.000000, d: 2.171923e-311)
00:18:42  fpr11 0000000000000000 (f: 0.000000, d: 0.000000e+00)
00:18:42  fpr12 0005f8a2ce8e01a4 (f: 3465413120.000000, d: 8.304023e-309)
00:18:42  fpr13 000003ff0c0368a8 (f: 201549984.000000, d: 2.170901e-311)
00:18:42  fpr14 000003ff9abc65e0 (f: 2596038144.000000, d: 2.172084e-311)
00:18:42  fpr15 000003ff0c060668 (f: 201721440.000000, d: 2.170901e-311)
00:18:42  Module=/lib/s390x-linux-gnu/libpthread.so.0
00:18:42  Module_base_address=000003FF88180000 Symbol=pthread_mutex_lock
00:18:42  Symbol_address=000003FF8818A590
00:18:42  Target=2_90_20230405_31 (Linux 5.4.0-137-generic)
00:18:42  CPU=s390x (4 logical CPUs) (0x1f58f7000 RAM)
00:18:42  ----------- Stack Backtrace -----------
00:18:42  pthread_mutex_lock+0x0 (0x000003FF8818A590 [libpthread.so.0+0xa590])
00:18:42  omrthread_interrupt+0x62 (0x000003FF8758C5B2 [libj9thr29.so+0xc5b2])
00:18:42  Java_java_lang_Thread_interruptImpl+0xb6 (0x000003FF85256EBE [libjclse29.so+0x56ebe])
00:18:42  ffi_call_SYSV+0x54 (0x000003FF8792AB64 [libj9vm29.so+0x22ab64])
00:18:42  ffi_call+0xa2 (0x000003FF8792A5BA [libj9vm29.so+0x22a5ba])
00:18:42  _ZN32VM_BytecodeInterpreterCompressed3runEP10J9VMThread+0x1a6e0 (0x000003FF877C65C8 [libj9vm29.so+0xc65c8])
00:18:42  bytecodeLoopCompressed+0xee (0x000003FF877ABED6 [libj9vm29.so+0xabed6])
00:18:42  c_cInterpreter+0x64 (0x000003FF878A4694 [libj9vm29.so+0x1a4694])
00:18:42  ---------------------------------------

@pshipton
Copy link
Member Author

@JasonFengJ9
Copy link
Member

JDK20 aarch64_linux(ub18-aarch64-7)

openjdk version "20" 2023-03-21
IBM Semeru Runtime Open Edition 20+36 (build 20+36)
Eclipse OpenJ9 VM 20+36 (build master-94bbd248a, JRE 20 Linux aarch64-64-Bit Compressed References 20230321_4 (JIT enabled, AOT enabled)
OpenJ9   - 94bbd248a
OMR      - 8e2bd3aa4
JCL      - 773141a82 based on jdk-20+36)

[2023-04-16T13:59:57.004Z] variation: -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache Mode150
[2023-04-16T13:59:57.004Z] JVM_OPTIONS:  -Xdump:system:none -Xdump:heap:none -Xdump:system:events=gpf+abort+traceassert+corruptcache -XX:+UseCompressedOops 

[2023-04-16T14:30:46.555Z] TEST: java/util/concurrent/locks/Lock/OOMEInAQS.java

[2023-04-16T14:30:46.556Z] STDERR:
[2023-04-16T14:30:46.556Z] JVMDUMP055I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError", exception "Java heap space" at 2023/04/16 10:02:10 - please wait.

[2023-04-16T14:30:46.556Z] JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
[2023-04-16T14:30:46.556Z] Exception in thread "Attach API wait loop" java/lang/OutOfMemoryError: Java heap space
[2023-04-16T14:30:46.556Z] 	at java/lang/Throwable.printStackTrace (java.base@20/Throwable.java:554)
[2023-04-16T14:30:46.556Z] 	at java/lang/Throwable.printStackTraceHelper (java.base@20/Throwable.java:338)
[2023-04-16T14:30:46.556Z] 	at java/lang/Throwable.printStackTrace (java.base@20/Throwable.java:307)
[2023-04-16T14:30:46.557Z] 	at java/lang/Throwable.printStackTrace (java.base@20/Throwable.java:250)

[2023-04-16T14:30:46.557Z] TEST RESULT: Error. Program `/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_aarch64_linux_testList_0/openjdkbinary/j2sdk-image/bin/java' timed out (timeout set to 960000ms, elapsed time including timeout handling was 1704331ms).
[2023-04-16T14:30:46.557Z] --------------------------------------------------
[2023-04-16T14:30:46.557Z] Test results: passed: 921; error: 1
[2023-04-16T14:30:52.287Z] Report written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_aarch64_linux_testList_0/aqa-tests/TKG/output_16816527461004/jdk_util_0/report/html/report.html
[2023-04-16T14:30:52.287Z] Results written to /home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_aarch64_linux_testList_0/aqa-tests/TKG/output_16816527461004/jdk_util_0/work
[2023-04-16T14:30:52.287Z] Error: Some tests failed or other problems occurred.
[2023-04-16T14:30:52.287Z] -----------------------------------
[2023-04-16T14:30:52.287Z] jdk_util_0_FAILED

@dmitripivkine
Copy link
Contributor

FYI: I was wondering why it goes OOM without heap expansion, -Xmx1540m is set... I noticed there is another -Xmx24M option, most right option wins. I am not sure is it intended

2CIUSERARG               -ea
2CIUSERARG               -esa
2CIUSERARG               -Xmx1540m <-----------
2CIUSERARG               -Xdump:system:none
2CIUSERARG               -Xdump:heap:none
2CIUSERARG               -Xdump:system:events=gpf+abort+traceassert+corruptcache
2CIUSERARG               -XX:+UseCompressedOops
2CIUSERARG               -Djava.library.path=/home/jenkins/workspace/Test_openjdk20_j9_sanity.openjdk_aarch64_linux_testList_0/openjdkbinary/openjdk-test-image/jdk/jtreg/native
2CIUSERARG               -XX:-UseGCOverheadLimit
2CIUSERARG               -Xmx24M <-----------
2CIUSERARG               -XX:-UseTLAB

@JasonFengJ9
Copy link
Member

The OOM is intentional [1].

 * @summary Check that AQS-based locks, conditions, and CountDownLatches do not fail when encountering OOME
 * @run main/othervm -XX:-UseGCOverheadLimit -Xmx24M -XX:-UseTLAB OOMEInAQS

[1] https://github.com/ibmruntimes/openj9-openjdk-jdk20/blob/3214624c8dcc654f4274d9694daed58010edeb0f/test/jdk/java/util/concurrent/locks/Lock/OOMEInAQS.java#L40-L41

@pshipton
Copy link
Member Author

@tajila can VM start the investigation on this one and see why the crash occurs.

@pshipton
Copy link
Member Author

See the crash in #16659 (comment) with a stack trace.

@tajila
Copy link
Contributor

tajila commented Apr 18, 2023

The segfault is caused because a thread being interrupted is being shutdown:

Thread 0x000000000E1486D8 "Attach API wait loop" is already shutdown when "Attach API teardown" attempts to interrupt it

!stack 0x11ea500
<11ea500> !j9method 0x00000000010B0308 java/lang/Thread.interruptImpl()V
<11ea500> !j9method 0x00000000010B0268 java/lang/Thread.interrupt0()V
<11ea500> !j9method 0x00000000010AFA88 java/lang/Thread.interrupt()V
<11ea500> !j9method 0x0000000001199FE0 openj9/internal/tools/attach/target/AttachHandler.terminate(Z)Z
<11ea500> !j9method 0x00000000011E3CE0 openj9/internal/tools/attach/target/AttachHandler$teardownHook.run()V

@tajila
Copy link
Contributor

tajila commented Apr 18, 2023

				boolean destroySemaphore = mainHandler.terminate(true);//<-- this also terminates wait loop

@tajila
Copy link
Contributor

tajila commented Apr 18, 2023

The wait loop thread (j9vmthread 0x000000000124C100) is in the vm->deadthreadlist

@tajila
Copy link
Contributor

tajila commented Apr 18, 2023

Grinder with more method tracing on zlinux https://openj9-jenkins.osuosl.org/job/Grinder/2253/

@tajila
Copy link
Contributor

tajila commented Apr 18, 2023

No cores in previous grinder, rebuilding https://openj9-jenkins.osuosl.org/job/Grinder/2257/

@pshipton
Copy link
Member Author

@pshipton
Copy link
Member Author

Started some grinders with better options, the earlier ones didn't run the test. It is running the test standalone and things don't always fail that way if the JIT is involved.
https://openj9-jenkins.osuosl.org/job/Grinder/2267/
https://openj9-jenkins.osuosl.org/job/Grinder/2268/
https://openj9-jenkins.osuosl.org/job/Grinder/2269/

@pshipton
Copy link
Member Author

pshipton commented Apr 19, 2023

It failed in the first grinder, but I was stupid and didn't manually copy the core and other artifacts before stopping the run.
We need to run with the right options to avoid core files being created for OOM, otherwise there are so many core files they can't be archived. The default options need to be retained since they avoid cores for OOM. Set the trace via EXTRA_OPTIONS (add options) rather than JVM_OPTIONS (replace options). It may also run the test faster if it's not creating a core file every time.

https://openj9-jenkins.osuosl.org/job/Grinder/2270

@pshipton
Copy link
Member Author

pshipton commented Oct 23, 2023

tajila added a commit to tajila/openj9-openjdk-jdk that referenced this issue Oct 23, 2023
tajila added a commit to tajila/openj9-openjdk-jdk that referenced this issue Oct 23, 2023
tajila added a commit to tajila/openj9-openjdk-jdk21 that referenced this issue Oct 24, 2023
@tajila
Copy link
Contributor

tajila commented Oct 25, 2023

The JDK21 changes have been merged. I can't confirm that it fixes the issues given that it is quite intermittent.

@pshipton
Copy link
Member Author

I'll close it and then we can reopen if it's seen again.

tajila added a commit to tajila/openj9 that referenced this issue Oct 25, 2023
@pshipton
Copy link
Member Author

pshipton commented Jan 5, 2024

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/133
jdk_util_0
java/util/concurrent/locks/Lock/OOMEInAQS.java

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk21_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/133/openjdk_test_output.tar.gz

21:04:13  ACTION: main -- Error. Program `/home/jenkins/workspace/Test_openjdk21_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/jdkbinary/j2sdk-image/bin/java' timed out: timeout handler did not complete within its own timeout. (timeout set to 960000ms, elapsed time including timeout handling was 1447340ms).
21:04:13  REASON: User specified action: run main/othervm -XX:-UseGCOverheadLimit -Xmx48M -XX:-UseTLAB OOMEInAQS 
21:04:13  TIME:   1447.382 seconds
21:04:13  messages:
21:04:13  command: main -XX:-UseGCOverheadLimit -Xmx48M -XX:-UseTLAB OOMEInAQS
21:04:13  reason: User specified action: run main/othervm -XX:-UseGCOverheadLimit -Xmx48M -XX:-UseTLAB OOMEInAQS 
21:04:13  started: Fri Jan 05 01:40:00 UTC 2024
21:04:13  Mode: othervm [/othervm specified]
21:04:13  Timeout information:
21:04:13  Running jcmd on process 1588770
21:04:13  Timeout signalled after 300 seconds
21:04:13  Error getting data from 1588770: Exception connecting to 1588770
21:04:13  Usage : jcmd <vmid> <arguments>
21:04:13  
21:04:13     -J : supply arguments to the Java VM running jcmd
21:04:13     -l : list JVM processes on the local machine
21:04:13     -h : print this help message
21:04:13  
21:04:13     <vmid> : Attach API VM ID as shown in jps or other Attach API-based tools
21:04:13  
21:04:13     arguments:
21:04:13        help : print the list of diagnostic commands
21:04:13        help <command> : print help for the specific command
21:04:13        <command> [command arguments] : command from the list returned by "help"
21:04:13  
21:04:13  list JVM processes on the local machine. Default behavior when no options are specified.
21:04:13  
21:04:13  NOTE: this utility might significantly affect the performance of the target JVM.
21:04:13      The available diagnostic commands are determined by
21:04:13      the target VM and may vary between VMs.
21:04:13  Error getting data from 1588770: Exception connecting to 1588770
21:04:13  Usage : jcmd <vmid> <arguments>
21:04:13  
21:04:13     -J : supply arguments to the Java VM running jcmd
21:04:13     -l : list JVM processes on the local machine
21:04:13     -h : print this help message
21:04:13  
21:04:13     <vmid> : Attach API VM ID as shown in jps or other Attach API-based tools
21:04:13  
21:04:13     arguments:
21:04:13        help : print the list of diagnostic commands
21:04:13        help <command> : print help for the specific command
21:04:13        <command> [command arguments] : command from the list returned by "help"
21:04:13  
21:04:13  list JVM processes on the local machine. Default behavior when no options are specified.
21:04:13  
21:04:13  NOTE: this utility might significantly affect the performance of the target JVM.
21:04:13      The available diagnostic commands are determined by
21:04:13      the target VM and may vary between VMs.
21:04:13  Timeout handler interrupted: 
21:04:13  java.lang.InterruptedException
21:04:13  	at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1691)
21:04:13  	at java.base/java.lang.ProcessImpl.waitFor(ProcessImpl.java:425)
21:04:13  	at jtreg.openj9.CoreDumpTimeoutHandler.runJcmdCommand(CoreDumpTimeoutHandler.java:117)
21:04:13  	at jtreg.openj9.CoreDumpTimeoutHandler.runJcmd(CoreDumpTimeoutHandler.java:138)
21:04:13  	at jtreg.openj9.CoreDumpTimeoutHandler.runActions(CoreDumpTimeoutHandler.java:55)
21:04:13  	at com.sun.javatest.regtest.TimeoutHandler.handleTimeout(TimeoutHandler.java:132)
21:04:13  	at com.sun.javatest.regtest.exec.ProcessCommand$2.run(ProcessCommand.java:317)
21:04:13  --- Timeout information end.
21:04:13  finished: Fri Jan 05 02:04:07 UTC 2024
21:04:13  elapsed time (seconds): 1447.382
21:04:13  configuration:
21:04:13  STDOUT:
21:04:13  Timeout signalled after 960 seconds
21:04:13  fillHeap time: 72683 millis, whole test time: 1033768 millis
21:04:13  STDERR:
21:04:13  JVMDUMP055I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError", exception "Java heap space" at 2024/01/05 01:40:03 - please wait.
21:04:13  JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Test_openjdk21_j9_sanity.openjdk_s390x_linux_Nightly_testList_1/aqa-tests/TKG/output_17044133151937/jdk_util_0/work/scratch/2/javacore.20240105.014003.1588770.0001.txt' in response to an event

@pshipton
Copy link
Member Author

@tajila
Copy link
Contributor

tajila commented Jan 18, 2024

The test forces OOME's so the following is expected:

19:24:18  JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Test_openjdk21_j9_sanity.openjdk_s390x_linux_Release_testList_1/aqa-tests/TKG/output_17055286614125/jdk_util_0/work/scratch/0/javacore.20240118.000034.2988659.0001.txt' in response to an event
19:24:18  JVMDUMP010I Java dump written to /home/jenkins/workspace/Test_openjdk21_j9_sanity.openjdk_s390x_linux_Release_testList_1/aqa-tests/TKG/output_17055286614125/jdk_util_0/work/scratch/0/javacore.20240118.000034.2988659.0001.txt
19:24:18  JVMDUMP032I JVM requested Snap dump using '/home/jenkins/workspace/Test_openjdk21_j9_sanity.openjdk_s390x_linux_Release_testList_1/aqa-tests/TKG/output_17055286614125/jdk_util_0/work/scratch/0/Snap.20240118.000034.2988659.0002.trc' in response to an event
19:24:18  JVMDUMP010I Snap dump written to /home/jenkins/workspace/Test_openjdk21_j9_sanity.openjdk_s390x_linux_Release_testList_1/aqa-tests/TKG/output_17055286614125/jdk_util_0/work/scratch/0/Snap.20240118.000034.2988659.0002.trc
19:24:18  JVMDUMP013I Processed dump event "systhrow", detail "java/lang/OutOfMemoryError".
19:24:18  JVMDUMP055I Processing dump event "systhrow", detail "java/lang/OutOfMemoryError", exception "Java heap space" at 2024/01/18 00:00:41 - please wait.

I think the only issue is that it is running slow, likely due to excessive GC's, which causes the timeout. The timeout handler is also slow for the same reasons.

This is an extreme test case, so I dont think it should block the release.

@pshipton
Copy link
Member Author

@TobiAjila we can't have this test intermittently failing all the time. Should we exclude it or can it be fixed to be less aggressive?

@tajila
Copy link
Contributor

tajila commented Jan 26, 2024

The test is designed to stress OOM paths. I think now that we've fixed the segfault we can disable this test. Im not sure how to modify it to be less agressive.

@tajila
Copy link
Contributor

tajila commented Jan 29, 2024

Ill open a PR to exclude it

@pshipton
Copy link
Member Author

I suppose this is perm excluded. Changing the label and closing.

@pshipton pshipton added perm excluded The test is unsuitable and permanently excluded. and removed test excluded triageRequired labels Feb 23, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
comp:vm jdk20 perm excluded The test is unsuitable and permanently excluded.
Projects
None yet
Development

No branches or pull requests

5 participants