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

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

Closed pshipton closed 8 months ago

pshipton commented 1 year ago

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 commented 1 year ago

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

pshipton commented 1 year ago

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 commented 1 year ago

@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 commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk20_j9_sanity.openjdk_ppc64_aix_Nightly/9

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk20_j9_sanity.openjdk_ppc64_aix_Nightly/9/openjdk_test_output.tar.gz

pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk20_j9_sanity.openjdk_ppc64le_linux_Nightly/18

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk20_j9_sanity.openjdk_ppc64le_linux_Nightly/18/openjdk_test_output.tar.gz

pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk20_j9_sanity.openjdk_s390x_linux_Nightly/20

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk20_j9_sanity.openjdk_s390x_linux_Nightly/20/openjdk_test_output.tar.gz

pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk20_j9_sanity.openjdk_s390x_linux_Nightly/21

pshipton commented 1 year ago

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 commented 1 year ago

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

pshipton commented 1 year ago

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

JasonFengJ9 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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

pshipton commented 1 year ago

See the crash in https://github.com/eclipse-openj9/openj9/issues/16659#issuecomment-1494265248 with a stack trace.

tajila commented 1 year ago

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 commented 1 year ago 
                boolean destroySemaphore = mainHandler.terminate(true);//<-- this also terminates wait loop
tajila commented 1 year ago

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

tajila commented 1 year ago

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

tajila commented 1 year ago

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

pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk20_j9_sanity.openjdk_s390x_linux_Nightly/37

pshipton commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

No I'm wrong, we need to set the options specially since jdk_custom doesn't do it. The options are normally set by jdk_lang which isn't being used.

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

tajila commented 1 year ago

Rebuilding the previous grinder with more iterations -> https://openj9-jenkins.osuosl.org/job/Grinder/2272/

pshipton commented 1 year ago

There are two ways to iterate. ITERATIONS, and TKG_ITERATIONS. The second way doesn't need to recompile the test every time. I was running 50 TKG_ITERATIONS and your new grinder is also running 50 ITERATIONS so you will get 2500 runs each in modes 0 and 1 (total 5000), or more likely a timeout.

The grinder is configured to stop after a failure, but that only works with TKG_ITERATIONS, so it will continue iterating the 50 ITERATIONS.

Started a second grinder to increase the chances, using 2 ITERATIONS and 50 TKG_ITERATIONS. https://openj9-jenkins.osuosl.org/job/Grinder/2273/ and 100 TKG_ITERATIONS https://openj9-jenkins.osuosl.org/job/Grinder/2274/

llxia commented 1 year ago

Thanks @pshipton for the explanation. :)

For more detail in TKG_ITERATIONS, please see #17 Grinder with TKG_ITERATIONS in https://github.com/eclipse-openj9/openj9/wiki/AQA-Lightning-Talk-Series or direct link to the demo recording https://youtu.be/0O7q2ib8bVA?t=12

pshipton commented 1 year ago

The problem occurred in the first grinder, I will go and get the result files manually because I don't expect the grinder will ever finish and archive them.

pshipton commented 1 year ago

@tajila I've put the results in /team/tobi/openjdk-crash16659.tar.gz

JVM and debug image https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Build_JDK20_s390x_linux_Nightly/31/

tajila commented 1 year ago

It seems the wait loop thread never attached, at least based on trace output

16:38:51.111540034 *0x1DD1F00 j9trc.5              Event       Thread started VMthread = 0x1dd1f00, name = Attach API wait loop, nativeID = 0x3ff18011e70
16:38:51.111540424  0x1DD1F00 j9vm.16              Entry      >runJavaThread
16:38:51.111541927  0x1DD1F00 j9vm.97              Event       Allocated new profiling buffer at 0x3ff0c003f40
16:38:51.111542950  0x1DD1F00 j9vm.682             Entry      >WalkStackFrames - walkThread=0x1dd1f00 flags=0x2c0000 sp=0x1daaf08 a0=0x1daaf30 pc=0x3 literals=0x0 els=0x3ff8f6fea10 j2i=0x0
16:38:51.111543500  0x1DD1F00 j9vm.683             Exit       <WalkStackFrames - walkThread=0x1dd1f00, rc=0
16:38:51.111559305  0x1DD1F00 j9jcl.487            Entry      >Java_com_ibm_tools_attach_javaSE_IPC_waitSemaphoreImpl waiting on semaphore (0x3ff0c005120)
16:38:51.111559657  0x1DD1F00 j9prt.1337           Entry      >j9shsem_wait handle=0x3ff0c005120, semset = 0 flag = 0, semid=16515075
tajila commented 1 year ago

I guess the constructor is actualy WaitLoop.<init> maybe thats why it was missed, but its definite running java code

tajila commented 1 year ago

Ran another grinder with more options https://openj9-jenkins.osuosl.org/job/Grinder/2275/

It seems like threadcleanup is not happeing properly for the waitloop thread. Not sure why at this point.

JasonFengJ9 commented 1 year ago

I guess the constructor is actualy WaitLoop. maybe thats why it was missed, but its definite running java code

WaitLoop is where the AttachAPI waits for attachment notification and initiates attachment with the attacher VM. This test doesn't exercise the AttachAPI functionalities. It might be worth to try a grinder w/ -Dcom.ibm.tools.attach.enable=no, launched https://openj9-jenkins.osuosl.org/job/Grinder/2276/ based on https://github.com/eclipse-openj9/openj9/issues/16659#issuecomment-1516834421

tajila commented 1 year ago

WaitLoop is where the AttachAPI waits for attachment notification and initiates attachment with the attacher VM. This test doesn't exercise the AttachAPI functionalities. It might be worth to try a grinder w/ -Dcom.ibm.tools.attach.enable=no, launched https://openj9-jenkins.osuosl.org/job/Grinder/2276/ based on https://github.com/eclipse-openj9/openj9/issues/16659#issuecomment-1516834421

Even iif that passes, we still need to know why the WaitLoop vmthread was deallocated by the eetop still points to the vmthread. The crash is still unexplained.

pshipton commented 1 year ago

There is a recreation in https://openj9-jenkins.osuosl.org/view/Test/job/Grinder/2277 Artifacts https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Grinder/2277/openjdk_test_output.tar.gz

Stopped the other grinders to give the machines to the nightly builds.

JasonFengJ9 commented 1 year ago

Got a native stacktrace from https://github.com/eclipse-openj9/openj9/issues/16659#issuecomment-1517067859

#12 <signal handler called>
#13 __GI___pthread_mutex_lock (mutex=mutex@entry=0x4a0) at ../nptl/pthread_mutex_lock.c:67
#14 0x000003ff9250c5b2 in threadInterrupt (interruptFlag=4, thread=0x0) at /home/jenkins/workspace/Build_JDK20_s390x_linux_Nightly/omr/thread/common/omrthread.c:2876
#15 omrthread_interrupt (thread=0x0) at /home/jenkins/workspace/Build_JDK20_s390x_linux_Nightly/omr/thread/common/omrthread.c:2751
#16 0x000003ff901d6ebe in VM_VMHelpers::threadInterruptImpl (targetObject=0x157c10, currentThread=0x1f43500) at /home/jenkins/workspace/Build_JDK20_s390x_linux_Nightly/openj9/runtime/oti/VMHelpers.hpp:2045
#17 Java_java_lang_Thread_interruptImpl (env=0x1f43500, rcv=<optimized out>) at /home/jenkins/workspace/Build_JDK20_s390x_linux_Nightly/openj9/runtime/jcl/common/thread.cpp:292
#18 0x000003ff928aab64 in ffi_call_SYSV () from /home/jenkins/workspace/Grinder/openjdkbinary/j2sdk-image/lib/default/libj9vm29.so
#19 0x000003ff928aa5ba in ffi_call (cif=<optimized out>, fn=<optimized out>, rvalue=<optimized out>, avalue=<optimized out>) at /home/jenkins/workspace/Build_JDK20_s390x_linux_Nightly/openj9/runtime/libffi/s390/ffi.c:532
#20 0x000003ff927b0b66 in VM_DebugBytecodeInterpreterCompressed::cJNICallout (isStatic=false, function=0x3ff901d6e08 <Java_java_lang_Thread_interruptImpl(JNIEnv*, jobject)>, returnStorage=0x1f43620, returnType=<synthetic pointer>, 
    javaArgs=<optimized out>, receiverAddress=<optimized out>, _pc=<synthetic pointer>: <optimized out>, _sp=<synthetic pointer>: <optimized out>, this=0x3ff923fe290)
    at /home/jenkins/workspace/Build_JDK20_s390x_linux_Nightly/openj9/runtime/vm/BytecodeInterpreter.hpp:2514
#21 VM_DebugBytecodeInterpreterCompressed::callCFunction (returnType=<synthetic pointer>, isStatic=false, bp=<synthetic pointer>, javaArgs=<optimized out>, receiverAddress=<optimized out>, 
    jniMethodStartAddress=0x3ff901d6e08 <Java_java_lang_Thread_interruptImpl(JNIEnv*, jobject)>, _pc=<synthetic pointer>: <optimized out>, _sp=<synthetic pointer>: <optimized out>, this=0x3ff923fe290)
    at /home/jenkins/workspace/Build_JDK20_s390x_linux_Nightly/openj9/runtime/vm/BytecodeInterpreter.hpp:2332
#22 VM_DebugBytecodeInterpreterCompressed::runJNINative (_pc=<synthetic pointer>: <optimized out>, _sp=<synthetic pointer>: <optimized out>, this=0x3ff923fe290)
    at /home/jenkins/workspace/Build_JDK20_s390x_linux_Nightly/openj9/runtime/vm/BytecodeInterpreter.hpp:2222
#23 VM_DebugBytecodeInterpreterCompressed::run (this=this@entry=0x3ff923fe3d8, vmThread=<optimized out>) at /home/jenkins/workspace/Build_JDK20_s390x_linux_Nightly/openj9/runtime/vm/BytecodeInterpreter.hpp:10782
#24 0x000003ff92788ca2 in debugBytecodeLoopCompressed (currentThread=<optimized out>) at /home/jenkins/workspace/Build_JDK20_s390x_linux_Nightly/openj9/runtime/vm/BytecodeInterpreter.inc:112
#25 0x000003ff92824694 in c_cInterpreter () at /home/jenkins/workspace/Build_JDK20_s390x_linux_Nightly/build/linux-s390x-server-release/vm/runtime/vm/zcinterp.s:278
#26 0x000003ff9269d390 in runJavaThread (currentThread=0x1f43500) at /home/jenkins/workspace/Build_JDK20_s390x_linux_Nightly/openj9/runtime/vm/callin.cpp:682
#27 0x000003ff92727512 in javaProtectedThreadProc (portLibrary=portLibrary@entry=0x3ff92e4ffa0 <j9portLibrary>, entryarg=entryarg@entry=0x1f43500) at /home/jenkins/workspace/Build_JDK20_s390x_linux_Nightly/openj9/runtime/vm/vmthread.cpp:2101
#28 0x000003ff925b2ae8 in omrsig_protect (portLibrary=0x3ff92e4ffa0 <j9portLibrary>, fn=0x3ff92727470 <javaProtectedThreadProc(J9PortLibrary*, void*)>, fn_arg=0x1f43500, handler=0x3ff926c48c8 <structuredSignalHandler>, handler_arg=0x1f43500, 
    flags=506, result=0x3ff923fee18) at /home/jenkins/workspace/Build_JDK20_s390x_linux_Nightly/omr/port/unix/omrsignal.c:425
#29 0x000003ff92723530 in javaThreadProc (entryarg=0x3ff8c028470) at /home/jenkins/workspace/Build_JDK20_s390x_linux_Nightly/openj9/runtime/vm/vmthread.cpp:380
#30 0x000003ff92508a46 in thread_wrapper (arg=0x3ff8c26dac0) at /home/jenkins/workspace/Build_JDK20_s390x_linux_Nightly/omr/thread/common/omrthread.c:1724
#31 0x000003ff93107e66 in start_thread (arg=0x3ff923ff900) at pthread_create.c:477
#32 0x000003ff92f7cbe6 in thread_start () at ../sysdeps/unix/sysv/linux/s390/s390-64/clone.S:65
tajila commented 1 year ago

I think the trace options in the last run werent respected, -Xtrace:maximal={j9vm.3,j9vm.4,j9vm.16,j9vm.17},mt,methods={*Thread.exit(),*Thread.<init>*(),*WaitLoop.*()},buffers=2m

tajila commented 1 year ago

Running a grinder with https://openj9-jenkins.osuosl.org/job/Grinder/2282/ with https://github.com/eclipse-openj9/openj9/pull/17238. If we see the assertion then I have a pretty good idea what the issue may be

tajila commented 1 year ago

Grinder with different set of trace options https://openj9-jenkins.osuosl.org/job/Grinder/2283/

pshipton commented 1 year ago

Recreation in https://openj9-jenkins.osuosl.org/job/Grinder/2282 https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Grinder/2282/openjdk_test_output.tar.gz

pshipton commented 1 year ago

For the record, grinder 2283 passed.

tajila commented 1 year ago

A new run with custom build, https://openj9-jenkins.osuosl.org/job/Grinder/2286/

tajila commented 1 year ago

@pshipton there was a crash in the last run, do you know how to get the diagnostics?

tajila commented 1 year ago

here is a rebuild in case the last results are lost, https://openj9-jenkins.osuosl.org/job/Grinder/2287/

pshipton commented 1 year ago

The diagnostics are gone. The build timed out, didn't archive the diagnostics, and deleted the workspace. I suggest not setting ITERATIONS to 2 so the build will stop sooner after a failure, but it will still run the 2 valid modes of jdk_custom. If you see a failure you can cancel the build and it will stop and archive the diagnostics. I will try to keep an eye on the new running grinder.

Not sure we should do so, but there should be some way to increase the timeout, although I don't see a configurable parameter for that currently in the grinder so we get the default.

For the future I think we should remove the multiple modes from the jdk_custom target as suggested in https://github.com/adoptium/aqa-tests/issues/4495#issuecomment-1498290854. This can be done using a branch, and if ITERATIONS is set to 1 then the build will stop after the first failure.

pshipton commented 1 year ago

Started a new grinder that should stop after the first failure. https://openj9-jenkins.osuosl.org/job/Grinder/2289/

pshipton commented 1 year ago

Crash recreated in https://openj9-jenkins.osuosl.org/job/Grinder/2287/ and artifacts are available.

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Grinder/2287/openjdk_test_output.tar.gz

tajila commented 1 year ago

Im still not seeing the tracepoints I added which makes me think the thread is interrupted bnefore it starts.

Another grinder with more diagnostics, https://openj9-jenkins.osuosl.org/job/Grinder/2294/

tajila commented 1 year ago

rebuild of previous https://openj9-jenkins.osuosl.org/job/Grinder/2295/

tajila commented 1 year ago

another rebuild, https://openj9-jenkins.osuosl.org/job/Grinder/2296/