jdk11: jtreg java/util/concurrent/ArrayBlockingQueue/WhiteBox.java crashes on MacOS

[andrew-m-leonard]

Failure link

https://hyc-runtimes-jenkins.swg-devops.com/view/Test_grinder/job/Grinder_Advanced/10/console

If the link is not public, instead include

• test category (functionality, system, etc): openjdk
• test suite name: java/util/concurrent/ArrayBlockingQueue/WhiteBox.java
• OS/architecture (i.e. Ubuntu 16.04 x64): MacOS
• OpenJDK version (i.e. 8u202-b08): jdk-11.0.3+7_openj9-0.14.0 & 3
• public build SHAs (i.e. -version output):
  12:52:16 openjdk version "11.0.3" 2019-04-16
  12:52:16 OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.3+7)
  12:52:16 Eclipse OpenJ9 VM AdoptOpenJDK (build openj9-0.14.3, JRE 11 Mac OS X amd64-64-Bit Compressed References 20190531_242 (JIT enabled, AOT enabled)
  12:52:16 OpenJ9 - b8ab016
  12:52:16 OMR - b56045d2
  12:52:16 JCL - dcdc97f9dc based on jdk-11.0.3+7)

Optional info

• intermittent failure (yes|no): no, but failure different on different Machines
• regression or new test: regression
• if regression, what are the last passing / first failing public SHAs (OpenJ9, OMR, JCL) :

Failure output

12:52:23  JVM_OPTIONS: -Xcompressedrefs 
12:52:23  { itercnt=1; \
12:52:23  	mkdir -p "/Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/scripts/testKitGen/../../../TestConfig/test_output_15595627327379/jdk_custom_0"; \
12:52:23  	cd "/Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/scripts/testKitGen/../../../TestConfig/test_output_15595627327379/jdk_custom_0"; \
12:52:23  	"/Users/jenkins/workspace/Grinder_Advanced/openjdkbinary/j2sdk-image/bin/java" -Xmx512m -jar "/Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/scripts/testKitGen/../../../../jvmtest/openjdk/jtreg/lib/jtreg.jar" \
12:52:23  	-agentvm -a -ea -esa -v:fail,error,time,nopass -retain:fail,error -ignore:quiet -timeoutFactor:8 -xml:verify -concurrency:4 -vmoptions:"-Xmx512m -Xcompressedrefs " \
12:52:23  	-w ""/Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/scripts/testKitGen/../../../TestConfig/test_output_15595627327379/jdk_custom_0"/work" \
12:52:23  	-r "/Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/scripts/testKitGen/../../../../jvmtest/openjdk/report" \
12:52:23  	-jdk:"/Users/jenkins/workspace/Grinder_Advanced/openjdkbinary/j2sdk-image" \
12:52:23  	"/Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/scripts/testKitGen/../../../openjdk/openjdk-jdk/test/jdk/java/util/concurrent/ArrayBlockingQueue/WhiteBox.java"; \
12:52:23  	if [ $? -eq 0 ] ; then echo ""; echo "jdk_custom_0""_PASSED"; echo ""; cd /Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/scripts/testKitGen/../../..;  else echo ""; echo "jdk_custom_0""_FAILED"; echo ""; fi; } 2>&1 | tee -a "/Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/scripts/testKitGen/../../../TestConfig/test_output_15595627327379/TestTargetResult";
12:52:27  Directory "/Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/scripts/testKitGen/../../../TestConfig/test_output_15595627327379/jdk_custom_0/work" not found: creating
12:52:27  /Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/openjdk/openjdk-jdk/test/jdk/TEST.groups: group jdk_security3: file not found: lib/security
12:52:39  XML output with verification to /Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/test_output_15595627327379/jdk_custom_0/work
12:52:45  [2019-06-03 07:52:44,825] Agent[1]: stderr: Unhandled exception
12:52:45  [2019-06-03 07:52:44,825] Agent[1]: stderr: Type=Segmentation error vmState=0x00000000
12:52:45  [2019-06-03 07:52:44,825] Agent[1]: stderr: J9Generic_Signal_Number=00000004 Signal_Number=0000000b Error_Value=00000000 Signal_Code=00000001
12:52:45  [2019-06-03 07:52:44,825] Agent[1]: stderr: Handler1=000000000371D220 Handler2=000000000393D750 InaccessibleAddress=00007FDAF903308C
12:52:45  [2019-06-03 07:52:44,825] Agent[1]: stderr: RDI=00007F92F7509170 RSI=00007F92F900DC68 RAX=0000004800000005 RBX=00007F92F9033068
12:52:45  [2019-06-03 07:52:44,826] Agent[1]: stderr: RCX=00007F92F900DC68 RDX=00007FDAF903306C R8=0000700003DD91B8 R9=FFFFFFFF00000000
12:52:45  [2019-06-03 07:52:44,826] Agent[1]: stderr: R10=00007F92F780AB78 R11=00007F92F900DC68 R12=0000000000000000 R13=00007FDAF903306C
12:52:45  [2019-06-03 07:52:44,826] Agent[1]: stderr: R14=00007F92F900DC68 R15=00007F92F7509170
12:52:45  [2019-06-03 07:52:44,826] Agent[1]: stderr: RIP=000000000374BD24 GS=0000 FS=0000 RSP=0000700003DD8EA0
12:52:45  [2019-06-03 07:52:44,826] Agent[1]: stderr: RFlags=0000000000010206 CS=002B RBP=0000700003DD8EA0 ERR=F903308C00000004
12:52:45  [2019-06-03 07:52:44,827] Agent[1]: stderr: TRAPNO=000000040000000E CPU=308C000000040000 FAULTVADDR=00007FDAF903308C
12:52:45  [2019-06-03 07:52:44,827] Agent[1]: stderr: XMM0 0000000000000000 (f: 0.000000, d: 0.000000e+00)
12:52:45  [2019-06-03 07:52:44,827] Agent[1]: stderr: XMM1 0000000000000000 (f: 0.000000, d: 0.000000e+00)
12:52:45  [2019-06-03 07:52:44,827] Agent[1]: stderr: XMM2 c3e0000000000000 (f: 0.000000, d: -9.223372e+18)
12:52:45  [2019-06-03 07:52:44,827] Agent[1]: stderr: XMM3 bf455018a8000000 (f: 2818572288.000000, d: -6.504174e-04)
12:52:45  [2019-06-03 07:52:44,827] Agent[1]: stderr: XMM4 be8c66f8d759984b (f: 3612973056.000000, d: -2.116131e-07)
12:52:45  [2019-06-03 07:52:44,828] Agent[1]: stderr: XMM5 bfb2aa0400000000 (f: 0.000000, d: -7.290673e-02)
12:52:45  [2019-06-03 07:52:44,828] Agent[1]: stderr: XMM6 000fffffffffffff (f: 4294967296.000000, d: 2.225074e-308)
12:52:45  [2019-06-03 07:52:44,828] Agent[1]: stderr: XMM7 3ff0000000000000 (f: 0.000000, d: 1.000000e+00)
12:52:45  [2019-06-03 07:52:44,828] Agent[1]: stderr: XMM8 0000000000000000 (f: 0.000000, d: 0.000000e+00)
12:52:45  [2019-06-03 07:52:44,828] Agent[1]: stderr: XMM9 0000000000000000 (f: 0.000000, d: 0.000000e+00)
12:52:45  [2019-06-03 07:52:44,828] Agent[1]: stderr: XMM10 0000000000000000 (f: 0.000000, d: 0.000000e+00)
12:52:45  [2019-06-03 07:52:44,828] Agent[1]: stderr: XMM11 0000000000000000 (f: 0.000000, d: 0.000000e+00)
12:52:45  [2019-06-03 07:52:44,829] Agent[1]: stderr: XMM12 0000000000000000 (f: 0.000000, d: 0.000000e+00)
12:52:45  [2019-06-03 07:52:44,829] Agent[1]: stderr: XMM13 0000000000000000 (f: 0.000000, d: 0.000000e+00)
12:52:45  [2019-06-03 07:52:44,829] Agent[1]: stderr: XMM14 0000000000000000 (f: 0.000000, d: 0.000000e+00)
12:52:45  [2019-06-03 07:52:44,829] Agent[1]: stderr: XMM15 0000000000000000 (f: 0.000000, d: 0.000000e+00)
12:52:45  [2019-06-03 07:52:44,829] Agent[1]: stderr: Module=/Users/jenkins/workspace/Grinder_Advanced/openjdkbinary/j2sdk-image/lib/compressedrefs/libj9vm29.dylib
12:52:45  [2019-06-03 07:52:44,830] Agent[1]: stderr: Module_base_address=000000000367B000 Symbol=segmentInsertionComparator
12:52:45  [2019-06-03 07:52:44,830] Agent[1]: stderr: Symbol_address=000000000374BD20
12:52:45  [2019-06-03 07:52:44,830] Agent[1]: stderr: Target=2_90_20190531_242 (Mac OS X 10.13.6)
12:52:45  [2019-06-03 07:52:44,830] Agent[1]: stderr: CPU=amd64 (4 logical CPUs) (0x200000000 RAM)
12:52:45  [2019-06-03 07:52:44,830] Agent[1]: stderr: ----------- Stack Backtrace -----------
12:52:45  [2019-06-03 07:52:44,830] Agent[1]: stderr: ---------------------------------------
12:52:45  [2019-06-03 07:52:44,831] Agent[1]: stderr: JVMDUMP039I Processing dump event "gpf", detail "" at 2019/06/03 07:52:44 - please wait.
12:52:45  [2019-06-03 07:52:44,831] Agent[1]: stderr: JVMDUMP032I JVM requested System dump using '/Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/test_output_15595627327379/jdk_custom_0/work/scratch/0/core.20190603.075244.27000.0001.dmp' in response to an event
12:52:51  [2019-06-03 07:52:50,352] Agent[1]: stderr: JVMDUMP010I System dump written to /Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/test_output_15595627327379/jdk_custom_0/work/scratch/0/core.20190603.075244.27000.0001.dmp
12:52:51  [2019-06-03 07:52:50,353] Agent[1]: stderr: JVMDUMP032I JVM requested Java dump using '/Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/test_output_15595627327379/jdk_custom_0/work/scratch/0/javacore.20190603.075244.27000.0002.txt' in response to an event
12:52:51  [2019-06-03 07:52:50,375] Agent[1]: stderr: JVMDUMP012E Error in Java dump: /Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/test_output_15595627327379/jdk_custom_0/work/scratch/0/javacore.20190603.075244.27000.0002.txt
12:52:51  [2019-06-03 07:52:50,375] Agent[1]: stderr: JVMDUMP032I JVM requested Snap dump using '/Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/test_output_15595627327379/jdk_custom_0/work/scratch/0/Snap.20190603.075244.27000.0003.trc' in response to an event
12:52:51  [2019-06-03 07:52:50,476] Agent[1]: stderr: JVMDUMP010I Snap dump written to /Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/test_output_15595627327379/jdk_custom_0/work/scratch/0/Snap.20190603.075244.27000.0003.trc
12:52:51  [2019-06-03 07:52:50,477] Agent[1]: stderr: JVMDUMP007I JVM Requesting JIT dump using '/Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/test_output_15595627327379/jdk_custom_0/work/scratch/0/jitdump.20190603.075244.27000.0004.dmp'
12:52:51  [2019-06-03 07:52:50,529] Agent[1]: stderr: JVMDUMP010I JIT dump written to /Users/jenkins/workspace/Grinder_Advanced/openjdk-tests/TestConfig/test_output_15595627327379/jdk_custom_0/work/scratch/0/jitdump.20190603.075244.27000.0004.dmp
12:52:51  [2019-06-03 07:52:50,529] Agent[1]: stderr: JVMDUMP013I Processed dump event "gpf", detail "".
12:52:51  --------------------------------------------------
12:52:51  TEST: java/util/concurrent/ArrayBlockingQueue/WhiteBox.java

[DanHeidinga]

@andrew-m-leonard I see a couple of different crashes in the Jenkins output. Are you able to capture the javacores / system cores / etc from the crashes to aid the investigations?

[andrew-m-leonard]

13:26:32 [2019-06-03 08:26:32,170] Agent[1]: stderr: 12:26:32.170 0x8913300 omrport.359 * ** ASSERTION FAILED ** at ../../omr/port/common/omrmemtag.c:145: ((memoryCorruptionDetected))

[andrew-m-leonard]

@DanHeidinga I'm not aware of a way of getting hyc-runtimes dumps? @AdamBrousseau does the worspace get cleared?

[JasonFengJ9]

This might be the same issue reported at #5399, particularly #5399 (comment).

[smlambert]

Dumps are in the archived openjdk_test_output.tar.gz file uploaded to artifactory.

[DanHeidinga]

Similar issue on 0.14.0 release:
https://hyc-runtimes-jenkins.swg-devops.com/view/Test_grinder/job/Grinder_Advanced/13/console

Assertion failure:

13:26:32  [2019-06-03 08:26:32,170] Agent[1]: stderr: 12:26:32.170 0x8913300 omrport.359    *   ** ASSERTION FAILED ** at ../../omr/port/common/omrmemtag.c:145: ((memoryCorruptionDetected))

$ lldb jdk-11.0.3+7/Contents/Home/bin/java -c core.20190603.082632.59714.0001.dmp 
(lldb) bt
* thread #1, stop reason = signal SIGSTOP
  * frame #0: 0x00007fff97448286 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff952699f9 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x0000000006134ee3 libj9prt29.dylib`omrdump_create + 275
    frame #3: 0x0000000006180a79 libj9dmp29.dylib`doSystemDump + 297
    frame #4: 0x00000000061855d5 libj9dmp29.dylib`protectedDumpFunction + 21
    frame #5: 0x0000000006136267 libj9prt29.dylib`omrsig_protect + 983
    frame #6: 0x00000000061851d6 libj9dmp29.dylib`runDumpAgent + 790
    frame #7: 0x000000000619b0d1 libj9dmp29.dylib`triggerDumpAgents + 1393
    frame #8: 0x0000000006d412d9 libj9trc29.dylib`triggerHit + 761
    frame #9: 0x0000000006d356fa libj9trc29.dylib`doTracePoint + 3626
    frame #10: 0x0000000006d314eb libj9trc29.dylib`javaTrace + 203
    frame #11: 0x0000000006133d84 libj9prt29.dylib`unwrapBlockAndCheckTags + 292
    frame #12: 0x0000000006133c15 libj9prt29.dylib`omrmem_free_memory + 85
    frame #13: 0x0000000006dd8d54 libj9jit29.dylib`std::__1::deque<TR::reference_wrapper<J9MemorySegment>, TR::typed_allocator<TR::reference_wrapper<J9MemorySegment>, J9::RawAllocator> >::erase(std::__1::__deque_iterator<TR::reference_wrapper<J9MemorySegment>, TR::reference_wrapper<J9MemorySegment> const*, TR::reference_wrapper<J9MemorySegment> const&, TR::reference_wrapper<J9MemorySegment> const* const*, long, 512l>) + 1076
    frame #14: 0x0000000006dd802e libj9jit29.dylib`J9::SystemSegmentProvider::~SystemSegmentProvider() + 190
    frame #15: 0x0000000006db0869 libj9jit29.dylib`TR::CompilationInfoPerThread::shouldPerformCompilation(TR_MethodToBeCompiled&) + 1593

[DanHeidinga]

This might be the same issue reported at #5399, particularly #5399 (comment).

In the cores from the 0.14.0 grinder, there are a couple of occurrences of #5399.
One of the issue in the comment above.

And another with a crash in segmentInsertionComparator:

    frame #13: 0x00007fff9b7adf1a libsystem_platform.dylib`_sigtramp + 26
    frame #14: 0x000000000ced0a45 libj9vm29.dylib`segmentInsertionComparator + 5
    frame #15: 0x000000000cfe65f2 libj9vm29.dylib`insertNode + 194
    frame #16: 0x000000000cfe6621 libj9vm29.dylib`insertNode + 241
    frame #17: 0x000000000cfe6621 libj9vm29.dylib`insertNode + 241
    frame #18: 0x000000000cfe6621 libj9vm29.dylib`insertNode + 241
    frame #19: 0x000000000cfe6621 libj9vm29.dylib`insertNode + 241
    frame #20: 0x000000000cfe6621 libj9vm29.dylib`insertNode + 241
    frame #21: 0x000000000cfe651d libj9vm29.dylib`avl_insert + 29
    frame #22: 0x000000000ced088f libj9vm29.dylib`allocateVirtualMemorySegmentInListInternal + 559
    frame #23: 0x000000000cecffe3 libj9vm29.dylib`allocateMemorySegmentInList + 147
    frame #24: 0x000000000ce91f7d libj9vm29.dylib`allocateClassMemorySegment + 205
    frame #25: 0x000000000ce9b752 libj9vm29.dylib`internalCreateRAMClassFromROMClassImpl(J9VMThread*, J9ClassLoader*, J9ROMClass*, unsigned long, J9Class*, J9ROMMethod**, long, int, J9Class*, unsigned long, J9Class*, J9CreateRAMClassState*, J9ClassLoader*, J9Class*, J9Module*) + 9298
    frame #26: 0x000000000ce985e9 libj9vm29.dylib`internalCreateRAMClassFromROMClass + 2825
    frame #27: 0x000000000cfd2733 libj9vm29.dylib`internalDefineClass + 2883
    frame #28: 0x000000000ec8f879 libjclse29.dylib`defineClassCommon + 1897
    frame #29: 0x000000000ec823bd libjclse29.dylib`Java_java_lang_ClassLoader_defineClassImpl + 173
    frame #30: 0x00000000236d4653
    frame #31: 0x000000000ce8c48d libj9vm29.dylib`sendLoadClass + 429
    frame #32: 0x000000000ce936b6 libj9vm29.dylib`internalFindClassInModule + 5126
    frame #33: 0x000000000cecb0ca libj9vm29.dylib`resolveClassRef + 506
    frame #34: 0x000000000ce305a7 libj9vm29.dylib`VM_BytecodeInterpreter::run(J9VMThread*) + 131815
    frame #35: 0x000000000ce102b7 libj9vm29.dylib`bytecodeLoop + 151
    frame #36: 0x000000000cf70052 libj9vm29.dylib`cInterpreter + 22
    frame #37: 0x000000000ce8fe92 libj9vm29.dylib`sidecarInvokeReflectMethodImpl + 1474
    frame #38: 0x000000000ce90711 libj9vm29.dylib`sidecarInvokeReflectMethod + 129
    frame #39: 0x000000000ecbfebd libjclse29.dylib`JVM_InvokeMethod_Impl + 109
    frame #40: 0x00000000236c9c45
    frame #41: 0x000000000ce8fe92 libj9vm29.dylib`sidecarInvokeReflectMethodImpl + 1474
    frame #42: 0x000000000ce90711 libj9vm29.dylib`sidecarInvokeReflectMethod + 129
    frame #43: 0x000000000ecbfebd libjclse29.dylib`JVM_InvokeMethod_Impl + 109
    frame #44: 0x00000000236c9c45
    frame #45: 0x000000000ce8d47f libj9vm29.dylib`runJavaThread + 415
    frame #46: 0x000000000cf66367 libj9vm29.dylib`javaProtectedThreadProc + 183
    frame #47: 0x000000000c538267 libj9prt29.dylib`omrsig_protect + 983
    frame #48: 0x000000000cf66283 libj9vm29.dylib`javaThreadProc + 83
    frame #49: 0x000000000c4f80b9 libj9thr29.dylib`thread_wrapper + 361
    frame #50: 0x00007fff9526805a libsystem_pthread.dylib`_pthread_body + 131
    frame #51: 0x00007fff95267fd7 libsystem_pthread.dylib`_pthread_start + 176
    frame #52: 0x00007fff952653ed libsystem_pthread.dylib`thread_start + 13

[DanHeidinga]

From the javacore: 1XHEXCPCODE InaccessibleAddress: 00007F18590ADB4C

(lldb) disassemble -n segmentInsertionComparator
libj9vm29.dylib`segmentInsertionComparator:
    0xced0a40 <+0>:  pushq  %rbp
    0xced0a41 <+1>:  movq   %rsp, %rbp
    0xced0a44 <+4>:  movq   0x20(%rdx), %rcx
    0xced0a48 <+8>:  xorl   %eax, %eax
    0xced0a4a <+10>: cmpq   %rcx, 0x20(%rsi)
    0xced0a4e <+14>: je     0xced0a60                 ; <+32>
    0xced0a50 <+16>: movl   $0x1, %ecx
    0xced0a55 <+21>: movq   $-0x1, %rax
    0xced0a5c <+28>: cmovaq %rcx, %rax
    0xced0a60 <+32>: popq   %rbp
    0xced0a61 <+33>: retq   
    0xced0a62 <+34>: nopw   %cs:(%rax,%rax)

Registers

(lldb) register read rdx rcx
     rdx = 0x00007f18590adb2c
     rcx = 0x00007fa05981a268

so rdx is the bad value.

https://github.com/eclipse/openj9/blob/1fd11ed3ef289907b5241a64bf3de46ae2e4aa81/runtime/vm/segment.c#L629-L640

Likely the walkNode.

Need to get this into ddr and see if the avl tree is corrupt

[DanHeidinga]

I've opened a PR at OMR to make it easier to reason about the AVL code (eclipse-omr/omr#3944) and while it makes it easier to read the code, it won't fix this issue.