Openj9: JTReg VM Failure: java/nio/charset/coders/BashStreams.java
Failure link
https://github.com/ibmruntimes/openj9-openjdk-jdk11/blob/f4e1e81163ae8ead82ac546d7f8d2e7a3ed24871/test/jdk/java/nio/charset/coders/BashStreams.java#L1 fails on JDK11-openj9 AIX
- test category, openjdk
- OS/architecture, ppc64_aix
03:11:02 openjdk version "11.0.7" 2020-04-14
03:11:02 OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.7+4-202002250055)
03:11:02 Eclipse OpenJ9 VM AdoptOpenJDK (build master-f262649, JRE 11 AIX ppc64-64-Bit Compressed References 20200224_503 (JIT enabled, AOT enabled)
03:11:02 OpenJ9 - f262649
03:11:02 OMR - 00c57af
03:11:02 JCL - f4e1e81 based on jdk-11.0.7+4)
Optional info
- New test
Failure output (captured from console output)
06:10:25 [2020-02-25 01:10:20,085] Agent[1]: stderr: Unhandled exception
06:10:25 [2020-02-25 01:10:20,086] Agent[1]: stderr: Type=Segmentation error vmState=0x00020011
06:10:25 [2020-02-25 01:10:20,086] Agent[1]: stderr: J9Generic_Signal_Number=00000018 Signal_Number=0000000b Error_Value=00000000 Signal_Code=00000032
06:10:25 [2020-02-25 01:10:20,086] Agent[1]: stderr: Handler1=09001000A0731BB0 Handler2=09001000A067CF10
06:10:25 [2020-02-25 01:10:20,086] Agent[1]: stderr: R0=000000003069A000 R1=0000010023E7AB00 R2=08001000A01D5ED8 R3=0000010022D59DB0
06:10:25 [2020-02-25 01:10:20,086] Agent[1]: stderr: R4=0000000000000000 R5=0000000099669966 R6=000001001046D570 R7=000001001046D940
06:10:25 [2020-02-25 01:10:20,086] Agent[1]: stderr: R8=0000000000000000 R9=00000000000003D0 R10=0000000000000000 R11=0000000000000000
06:10:25 [2020-02-25 01:10:20,086] Agent[1]: stderr: R12=00000100230B2A38 R13=0000010023E87800 R14=00059F6057AB6D57 R15=09001000A04E7480
06:10:25 [2020-02-25 01:10:20,086] Agent[1]: stderr: R16=0000000000000000 R17=08001000A01D57E8 R18=0000000000001628 R19=00000000000F0000
06:10:25 [2020-02-25 01:10:20,086] Agent[1]: stderr: R20=0000000000000001 R21=0000000000000000 R22=00000100100DA400 R23=00000100100D8B48
06:10:25 [2020-02-25 01:10:20,086] Agent[1]: stderr: R24=00000000000015E8 R25=00000000000000C0 R26=0000010022D59DB0 R27=00000100104E34E0
06:10:25 [2020-02-25 01:10:20,086] Agent[1]: stderr: R28=0000000000000018 R29=0000000000000000 R30=00000100103FDF18 R31=00000100104E3420
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: IAR=0900000006F93EB8 LR=0900000006FAAF1C MSR=A00000000200D032 CTR=0000000000000000
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: CR=4200024000000000 FPSCR=8202000000000000 XER=0000000082020000
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR0 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR1 c3e0000000000000 (f: 0.000000, d: -9.223372e+18)
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR2 41cdcd6500000000 (f: 0.000000, d: 1.000000e+09)
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR3 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR4 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR5 c3e0000000000000 (f: 0.000000, d: -9.223372e+18)
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR6 402e000000000000 (f: 0.000000, d: 1.500000e+01)
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR7 412e848000000000 (f: 0.000000, d: 1.000000e+06)
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR8 4058400000000000 (f: 0.000000, d: 9.700000e+01)
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR9 4530000000000000 (f: 0.000000, d: 1.934281e+25)
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR10 412e848000000000 (f: 0.000000, d: 1.000000e+06)
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR11 43300000000f4240 (f: 1000000.000000, d: 4.503600e+15)
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR12 4530000000000000 (f: 0.000000, d: 1.934281e+25)
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR13 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR14 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR15 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,087] Agent[1]: stderr: FPR16 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: FPR17 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: FPR18 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: FPR19 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: FPR20 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: FPR21 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: FPR22 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: FPR23 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: FPR24 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: FPR25 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: FPR26 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: FPR27 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: FPR28 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: FPR29 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: FPR30 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: FPR31 0000000000000000 (f: 0.000000, d: 0.000000e+00)
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: Module=/home/jenkins/workspace/Test_openjdk11_j9_sanity.openjdk_ppc64_aix/openjdkbinary/j2sdk-image/lib/compressedrefs/libj9jit29.so
06:10:25 [2020-02-25 01:10:20,088] Agent[1]: stderr: Module_base_address=0900000006149000
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: Target=2_90_20200224_503 (AIX 7.1)
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: CPU=ppc64 (16 logical CPUs) (0x200000000 RAM)
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: ----------- Stack Backtrace -----------
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: (0x0900000006FAAF1C [libj9jit29.so+0xe61f1c])
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: J9HookDispatch__FPP15J9HookInterfaceUlPv+0x1c8 (0x090000000133144C [libj9hookable29.so+0x44c])
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: cleanUpClassLoader+0x330 (0x090000000116A5F4 [libj9vm29.so+0xad5f4])
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: cleanUpClassLoaders__21MM_ClassLoaderManagerFP18MM_EnvironmentBaseP13J9ClassLoaderPP15J9MemorySegmentPP13J9ClassLoaderPVb+0x29c (0x09000000014CBE20 [libj9gc29.so+0x13e20])
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: unloadDeadClassLoaders__26MM_GlobalCollectorDelegateFP18MM_EnvironmentBase+0x174 (0x0900000001544878 [libj9gc29.so+0x8c878])
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: postMarkProcessing__26MM_GlobalCollectorDelegateFP18MM_EnvironmentBase+0x70 (0x09000000015443B4 [libj9gc29.so+0x8c3b4])
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: masterThreadGarbageCollect__19MM_ParallelGlobalGCFP18MM_EnvironmentBaseP22MM_AllocateDescriptionbT3+0x234 (0x09000000015AA6B8 [libj9gc29.so+0xf26b8])
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: internalGarbageCollect__15MM_ConcurrentGCFP18MM_EnvironmentBaseP17MM_MemorySubSpaceP22MM_AllocateDescription+0x4c (0x090000000159B130 [libj9gc29.so+0xe3130])
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: garbageCollect__12MM_CollectorFP18MM_EnvironmentBaseP17MM_MemorySubSpaceP22MM_AllocateDescriptionUiP28MM_ObjectAllocationInterfaceT2P20MM_AllocationContext+0x2e8 (0x09000000015312EC [libj9gc29.so+0x792ec])
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: garbageCollect__17MM_MemorySubSpaceFP18MM_EnvironmentBaseP22MM_AllocateDescriptionUi+0x120 (0x09000000014F5B04 [libj9gc29.so+0x3db04])
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: percolateGarbageCollect__17MM_MemorySubSpaceFP18MM_EnvironmentBaseP22MM_AllocateDescriptionUi+0x7c (0x09000000014F56C0 [libj9gc29.so+0x3d6c0])
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: percolateGarbageCollect__12MM_ScavengerFP18MM_EnvironmentBaseP17MM_MemorySubSpaceP22MM_AllocateDescription15PercolateReasonUi+0x124 (0x090000000166D1A8 [libj9gc29.so+0x1b51a8])
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: internalGarbageCollect__12MM_ScavengerFP18MM_EnvironmentBaseP17MM_MemorySubSpaceP22MM_AllocateDescription+0x160 (0x09000000016602E4 [libj9gc29.so+0x1a82e4])
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: garbageCollect__12MM_CollectorFP18MM_EnvironmentBaseP17MM_MemorySubSpaceP22MM_AllocateDescriptionUiP28MM_ObjectAllocationInterfaceT2P20MM_AllocationContext+0x2e8 (0x09000000015312EC [libj9gc29.so+0x792ec])
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: allocationRequestFailed__26MM_MemorySubSpaceSemiSpaceFP18MM_EnvironmentBaseP22MM_AllocateDescriptionQ2_17MM_MemorySubSpace14AllocationTypeP28MM_ObjectAllocationInterfaceP17MM_MemorySubSpaceT5+0x408 (0x090000000167C98C [libj9gc29.so+0x1c498c])
06:10:25 [2020-02-25 01:10:20,089] Agent[1]: stderr: allocateTLH__24MM_MemorySubSpaceGenericFP18MM_EnvironmentBaseP22MM_AllocateDescriptionP28MM_ObjectAllocationInterfaceP17MM_MemorySubSpaceT4b+0x2d8 (0x09000000016B2E9C [libj9gc29.so+0x1fae9c])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: refresh__23MM_TLHAllocationSupportFP18MM_EnvironmentBaseP22MM_AllocateDescriptionb+0x6ec (0x09000000016BDB90 [libj9gc29.so+0x205b90])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: allocateFromTLH__23MM_TLHAllocationSupportFP18MM_EnvironmentBaseP22MM_AllocateDescriptionb+0x178 (0x09000000016BE0DC [libj9gc29.so+0x2060dc])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: allocateObject__25MM_TLHAllocationInterfaceFP18MM_EnvironmentBaseP22MM_AllocateDescriptionP14MM_MemorySpaceb+0x508 (0x09000000016BC12C [libj9gc29.so+0x20412c])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: allocateArrayletSpine__25MM_TLHAllocationInterfaceFP18MM_EnvironmentBaseP22MM_AllocateDescriptionP14MM_MemorySpaceb+0x2c (0x09000000016BC2F0 [libj9gc29.so+0x2042f0])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: OMR_GC_AllocateObject__FP12OMR_VMThreadP25MM_AllocateInitialization+0x204 (0x090000000153A408 [libj9gc29.so+0x82408])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: J9AllocateIndexableObject+0xdd4 (0x0900000001539038 [libj9gc29.so+0x81038])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: old_slow_jitNewArray+0x218 (0x09000000062EB53C [libj9jit29.so+0x1a253c])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: (0x09000000062D5C20 [libj9jit29.so+0x18cc20])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: sidecarInvokeReflectMethodImpl+0x4b0 (0x0900000001126C34 [libj9vm29.so+0x69c34])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: sidecarInvokeReflectMethod+0x30 (0x0900000001129134 [libj9vm29.so+0x6c134])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: JVM_InvokeMethod_Impl+0xb0 (0x0900000001BF8614 [libjclse29.so+0x93614])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: JVM_InvokeMethod+0x64 (0x090000000106C768 [libjvm.so+0xf768])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: JVM_InvokeMethod+0x6c (0x0900000000FCD4F0 [libjvm.so+0x64f0])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: JVM_InvokeMethod+0x6c (0x0900000000F924F0 [libjvm.so+0x64f0])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: (0x09000000026EEB9C [libjava.so+0xeb9c])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: (0x0000010010588230)
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: runJavaThread+0x1d4 (0x0900000001127C38 [libj9vm29.so+0x6ac38])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: javaProtectedThreadProc+0x11c (0x09000000010BFAA0 [libj9vm29.so+0x2aa0])
06:10:25 [2020-02-25 01:10:20,090] Agent[1]: stderr: omrsig_protect+0x488 (0x09000000013A1ACC [libj9prt29.so+0x6aacc])
06:10:25 [2020-02-25 01:10:20,091] Agent[1]: stderr: javaThreadProc+0x68 (0x09000000010BF88C [libj9vm29.so+0x288c])
06:10:25 [2020-02-25 01:10:20,091] Agent[1]: stderr: thread_wrapper+0x33c (0x0900000001008700 [libj9thr29.so+0x4700])
06:10:25 [2020-02-25 01:10:20,091] Agent[1]: stderr: _pthread_body+0xf0 (0x0900000000570E14 [libpthreads.a+0x3e14])
06:10:25 [2020-02-25 01:10:20,139] Agent[1]: stderr: ---------------------------------------
06:10:25 [2020-02-25 01:10:20,139] Agent[1]: stderr: JVMDUMP039I Processing dump event "gpf", detail "" at 2020/02/25 01:10:20 - please wait.
06:10:25 [2020-02-25 01:10:20,139] Agent[1]: stderr: JVMDUMP032I JVM requested System dump using '/home/jenkins/workspace/Test_openjdk11_j9_sanity.openjdk_ppc64_aix/openjdk-tests/TKG/test_output_15826004162219/jdk_nio_0/work/scratch/core.20200225.011020.26542160.0001.dmp' in response to an event
06:10:26 [2020-02-25 01:10:25,873] Agent[1]: stderr: JVMDUMP010I System dump written to /home/jenkins/workspace/Test_openjdk11_j9_sanity.openjdk_ppc64_aix/openjdk-tests/TKG/test_output_15826004162219/jdk_nio_0/work/scratch/core.20200225.011020.26542160.0001.dmp
06:10:26 [2020-02-25 01:10:25,874] Agent[1]: stderr: JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Test_openjdk11_j9_sanity.openjdk_ppc64_aix/openjdk-tests/TKG/test_output_15826004162219/jdk_nio_0/work/scratch/javacore.20200225.011020.26542160.0002.txt' in response to an event
06:10:26 [2020-02-25 01:10:26,064] Agent[1]: stderr: JVMDUMP010I Java dump written to /home/jenkins/workspace/Test_openjdk11_j9_sanity.openjdk_ppc64_aix/openjdk-tests/TKG/test_output_15826004162219/jdk_nio_0/work/scratch/javacore.20200225.011020.26542160.0002.txt
06:10:26 [2020-02-25 01:10:26,064] Agent[1]: stderr: JVMDUMP032I JVM requested Snap dump using '/home/jenkins/workspace/Test_openjdk11_j9_sanity.openjdk_ppc64_aix/openjdk-tests/TKG/test_output_15826004162219/jdk_nio_0/work/scratch/Snap.20200225.011020.26542160.0003.trc' in response to an event
06:10:26 [2020-02-25 01:10:26,166] Agent[1]: stderr: JVMDUMP010I Snap dump written to /home/jenkins/workspace/Test_openjdk11_j9_sanity.openjdk_ppc64_aix/openjdk-tests/TKG/test_output_15826004162219/jdk_nio_0/work/scratch/Snap.20200225.011020.26542160.0003.trc
06:10:26 [2020-02-25 01:10:26,168] Agent[1]: stderr: JVMDUMP007I JVM Requesting JIT dump using '/home/jenkins/workspace/Test_openjdk11_j9_sanity.openjdk_ppc64_aix/openjdk-tests/TKG/test_output_15826004162219/jdk_nio_0/work/scratch/jitdump.20200225.011020.26542160.0004.dmp'
06:10:26 [2020-02-25 01:10:26,168] Agent[1]: stderr: JVMDUMP010I JIT dump written to /home/jenkins/workspace/Test_openjdk11_j9_sanity.openjdk_ppc64_aix/openjdk-tests/TKG/test_output_15826004162219/jdk_nio_0/work/scratch/jitdump.20200225.011020.26542160.0004.dmp
06:10:26 [2020-02-25 01:10:26,168] Agent[1]: stderr: JVMDUMP013I Processed dump event "gpf", detail "".
TEST RESULT: Error. Agent communication error: java.io.EOFException; check console log for any additional details
06:10:26 --------------------------------------------------
06:11:41 [2020-02-25 01:11:31,924] Agent[4]: stdout: Filesystem 512-blocks Free %Used Iused %Iused Mounted on
06:11:41 [2020-02-25 01:11:31,928] Agent[4]: stdout: /dev/hd4 20971520 19642240 7% 35689 2% /
06:11:41 [2020-02-25 01:11:31,928] Agent[4]: stdout: /dev/hd2 41943040 25398472 40% 84055 3% /usr
06:11:41 [2020-02-25 01:11:31,928] Agent[4]: stdout: /dev/hd9var 20971520 19553888 7% 4873 1% /var
06:11:41 [2020-02-25 01:11:31,928] Agent[4]: stdout: /dev/hd3 62914560 60025760 5% 259165 4% /tmp
06:11:41 [2020-02-25 01:11:31,928] Agent[4]: stdout: /dev/hd1 83886080 57176872 32% 260315 4% /home
06:11:41 [2020-02-25 01:11:31,928] Agent[4]: stdout: /dev/hd11admin 524288 523488 1% 7 1% /admin
06:11:41 [2020-02-25 01:11:31,928] Agent[4]: stdout: /proc - - - - - /proc
06:11:41 [2020-02-25 01:11:31,928] Agent[4]: stdout: /dev/hd10opt 41943040 37939080 10% 33750 1% /opt
06:11:41 [2020-02-25 01:11:31,928] Agent[4]: stdout: /dev/livedump 524288 523552 1% 4 1% /var/adm/ras/livedump
06:11:41 [2020-02-25 01:11:31,928] Agent[4]: stdout: /aha - - - 33 1% /aha
Dumps: https://ibm.box.com/s/ra34mxfgz1mh8bih1pw1dqqeu5rnq2pb
M-Davies
All 76 comments
@M-Davies how often does it fail?
pshipton
on 25 Feb 2020
Does it fail on jdk14 as well?
pshipton
on 25 Feb 2020
It failed on two of the last four jdk11 nightlies, hasn't been seen on jdk14 (the jdk_nio test fails in other ways though). @M-Davies is running a grinder to confirm.
lumpfish
on 25 Feb 2020
I don't believe this affects JDK14. I've ran 2 10 iteration grinders on two seperate aix machines and couldn't reproduce the error.
~I'm running another at https://ci.adoptopenjdk.net/view/Test_grinder/job/Grinder/2333/console that is trying to recreate the exact conditions the test was conducted under. If that passes, I'm going to make a judgement that this was a very intermittent failure.~ It passed
M-Davies
on 25 Feb 2020
At class unloading time, cleaning classloaders time GC trying to unload one of classloaders (I will try to find out which one). As a part of operation it calls cleanUpClassLoader() in VM in jvmfree.c.
This function triggers J9HOOK_VM_CLASS_LOADER_UNLOAD hook. There is only one subscriber to this hook in JIT code jitHookClassLoaderUnload() in HookedByTheJit.cpp and it is where crash occur
dmitripivkine
on 25 Feb 2020
This is table of Classloaders in the system. "Object is not marked" means this classloader is about to be unloaded:
!j9classloader 0x00000100231D4848 | grep classLoaderObject > Object 0x00000000E02B7B28 is not marked
!j9classloader 0x0000010023037188 | grep classLoaderObject > Object 0x00000000E02B2268 is marked
!j9classloader 0x00000100230B2128 | grep classLoaderObject > Object 0x00000000E021F178 is marked
!j9classloader 0x00000100230B2698 | grep classLoaderObject > Object 0x00000000E0296568 is marked
!j9classloader 0x00000100230B2A38 | grep classLoaderObject > Object 0x00000000FFC8A550 is marked
!j9classloader 0x0000010022DB4718 | grep classLoaderObject > Object 0x00000000FFC8E4F8 is marked
!j9classloader 0x0000010022DB4800 | grep classLoaderObject > Object 0x00000000FFC606A8 is marked
!j9classloader 0x0000010022DB48E8 | grep classLoaderObject > Object 0x00000000FFC608A8 is marked
!j9classloader 0x0000010022DB49D0 | grep classLoaderObject > Object 0x00000000FFC60C18 is marked
!j9classloader 0x0000010022DB4AB8 | grep classLoaderObject > Object 0x00000000FFC61660 is marked
!j9classloader 0x0000010022DB4BA0 | grep classLoaderObject > Object 0x00000000FFC61D50 is marked
!j9classloader 0x0000010022DB4C88 | grep classLoaderObject > Object 0x00000000FFC62470 is marked
!j9classloader 0x0000010022DB4D70 | grep classLoaderObject > Object 0x00000000FFC61AE0 is marked
!j9classloader 0x0000010022DB4E58 | grep classLoaderObject > Object 0x00000000FFC61C80 is marked
!j9classloader 0x0000010022DB4F40 | grep classLoaderObject > Object 0x00000000FFC62230 is marked
!j9classloader 0x0000010022DB5028 | grep classLoaderObject > Object 0x00000000E0215390 is marked
!j9classloader 0x0000010022DB5110 | grep classLoaderObject > Object 0x00000000FFC62348 is marked
!j9classloader 0x0000010022DB51F8 | grep classLoaderObject > Object 0x00000000E0214F18 is marked
!j9classloader 0x0000010022DB52E0 | grep classLoaderObject > Object 0x00000000E09E7C60 is not marked
!j9classloader 0x0000010022DB53C8 | grep classLoaderObject > Object 0x00000000E09EA978 is not marked
!j9classloader 0x0000010022DB54B0 | grep classLoaderObject > Object 0x00000000E09EABB0 is not marked
!j9classloader 0x0000010022DB5598 | grep classLoaderObject > Object 0x00000000E0BDC0B8 is not marked
!j9classloader 0x00000100103FD098 | grep classLoaderObject > Object 0x00000000E003C368 is marked
!j9classloader 0x00000100103FD180 | grep classLoaderObject > Object 0x00000000E003FEF8 is marked
!j9classloader 0x00000100103FD268 | grep classLoaderObject > Object 0x00000000E003FF78 is marked
!j9classloader 0x00000100103FD350 | grep classLoaderObject > Object 0x00000000E003C420 is marked
!j9classloader 0x00000100103FD438 | grep classLoaderObject > Object 0x00000000E013B550 is marked
!j9classloader 0x00000100103FD520 | grep classLoaderObject > Object 0x00000000E0BD9448 is not marked
!j9classloader 0x00000100103FD608 | grep classLoaderObject > Object 0x00000000E0BC64F8 is not marked
!j9classloader 0x00000100103FD6F0 | grep classLoaderObject > Object 0x00000000E01C3280 is marked
!j9classloader 0x00000100103FD7D8 | grep classLoaderObject > Object 0x00000000E0BAFCE0 is not marked
!j9classloader 0x00000100103FD8C0 | grep classLoaderObject > Object 0x00000000E0BAED40 is not marked
!j9classloader 0x00000100103FD9A8 | grep classLoaderObject > Object 0x00000000E0BA8C58 is not marked
!j9classloader 0x00000100103FDA90 | grep classLoaderObject > Object 0x00000000E0970AC0 is not marked
!j9classloader 0x00000100103FDB78 | grep classLoaderObject > Object 0x00000000E09709A8 is not marked
!j9classloader 0x00000100103FDC60 | grep classLoaderObject > Object 0x00000000E0970890 is not marked
!j9classloader 0x00000100103FDD48 | grep classLoaderObject > Object 0x00000000E0970770 is not marked
!j9classloader 0x00000100103FDE30 | grep classLoaderObject > Object 0x00000000E0970608 is not marked
!j9classloader 0x00000100103FDF18 | grep classLoaderObject > Object 0x00000000E09702B0 is not marked
The crash occur in J9Method_HT::onClassUnloading(J9ClassLoader*)()
This is c-stack (with preserved registers):
10 masterSynchSignalHandler(??, ??, ??), line 1066 in "omrsignal.c"
---------
$r0:0x000000003069a000 $stkp:0x0000010023e7ab00 $toc:0x08001000a01d5ed8
$r3:0x0000010022d59db0 $r4:0x0000000000000000 $r5:0x0000000099669966
$r6:0x000001001046d570 $r7:0x000001001046d940 $r8:0x0000000000000000
$r9:0x00000000000003d0 $r10:0x0000000000000000 $r11:0x0000000000000000
$r12:0x00000100230b2a38 $r13:0x0000010023e87800 $r14:0x00059f6057ab6d57
$r15:0x09001000a04e7480 $r16:0x0000000000000000 $r17:0x08001000a01d57e8
$r18:0x0000000000001628 $r19:0x00000000000f0000 $r20:0x0000000000000001
$r21:0x0000000000000000 $r22:0x00000100100da400 $r23:0x00000100100d8b48
$r24:0x00000000000015e8 $r25:0x00000000000000c0 $r26:0x0000010022d59db0
$r27:0x00000100104e34e0 $r28:0x0000000000000018 $r29:0x0000000000000000
$r30:0x00000100103fdf18 $r31:0x00000100104e3420
$iar:0x0900000006f93eb8 $msr:0xa00000000200d032 $cr:0x0000000042000240
$link:0x0900000006faaf1c $ctr:0x0000000000000000 $xer:0x0000000000000000
Condition status = 0:g 1:e 5:e 6:g
[unset $noflregs to view floating point registers]
[unset $novregs to view vector registers]
[unset $novsregs to view vector scalar registers]
11 J9Method_HT::onClassUnloading(J9ClassLoader*)() at 0x900000006f93eb8
---------
$stkp:0x0000010023e7abb0 $r14:0x00059f6057ab6d57 $r15:0x09001000a04e7480
$r16:0x0000000000000000 $r17:0x08001000a01d57e8 $r18:0x0000000000001628
$r19:0x00000000000f0000 $r20:0x0000000000000001 $r21:0x0000000000000000
$r22:0x00000100100da400 $r23:0x00000100100d8b48 $r24:0x00000000000015e8
$r25:0x00000100100d8b40 $r26:0x0000000000001900 $r27:0x0000000000000000
$r28:0x0000010010469570 $r29:0x00000100103fdf18 $r30:0x000001001046d4b0
$r31:0x00000000305c6f00
$iar:0x0900000006faaf18 $link:0x090000000133144c
[unset $noflregs to view floating point registers]
[unset $novregs to view vector registers]
[unset $novsregs to view vector scalar registers]
12 HookedByTheJit.JitShutdown.jitHookClassLoaderUnload(J9HookInterface**,unsigned long,void*,void*)() at 0x900000006faaf18
---------
$stkp:0x0000010023e7ac40 $r14:0x00059f6057ab6d57 $r15:0x09001000a04e7480
$r16:0x0000000000000000 $r17:0x08001000a01d57e8 $r18:0x0000000000001628
$r19:0x00000000000f0000 $r20:0x0000000000000001 $r21:0x0000000000000000
$r22:0x00000100100da400 $r23:0x00000100100d8b48 $r24:0x00000000000015e8
$r25:0x00000100100d8b40 $r26:0x0000000000001900 $r27:0x0000000000000000
$r28:0x0000010010197ff8 $r29:0x0000000000000044 $r30:0x0000010023e7ade0
$r31:0x00000100100d8e18
$iar:0x0900000001331448 $link:0x090000000116a5f4
[unset $noflregs to view floating point registers]
[unset $novregs to view vector registers]
[unset $novsregs to view vector scalar registers]
13 unnamed block in J9HookDispatch(J9HookInterface**,unsigned long,void*)(hookInterface = 0x0000010023e7ce40, taggedEventNum = 8189, eventData = (nil)), line 235 in "hookable.cpp"
---------
$stkp:0x0000010023e7ac40 $r14:0x00059f6057ab6d57 $r15:0x09001000a04e7480
$r16:0x0000000000000000 $r17:0x08001000a01d57e8 $r18:0x0000000000001628
$r19:0x00000000000f0000 $r20:0x0000000000000001 $r21:0x0000000000000000
$r22:0x00000100100da400 $r23:0x00000100100d8b48 $r24:0x00000000000015e8
$r25:0x00000100100d8b40 $r26:0x0000000000001900 $r27:0x0000000000000000
$r28:0x0000010010197ff8 $r29:0x0000000000000044 $r30:0x0000010023e7ade0
$r31:0x00000100100d8e18
$iar:0x0900000001331448 $link:0x090000000116a5f4
[unset $noflregs to view floating point registers]
[unset $novregs to view vector registers]
[unset $novsregs to view vector scalar registers]
14 unnamed block in J9HookDispatch(J9HookInterface**,unsigned long,void*)(hookInterface = 0x0000010023e7ce40, taggedEventNum = 8189, eventData = (nil)), line 235 in "hookable.cpp"
---------
$stkp:0x0000010023e7ac40 $r14:0x00059f6057ab6d57 $r15:0x09001000a04e7480
$r16:0x0000000000000000 $r17:0x08001000a01d57e8 $r18:0x0000000000001628
$r19:0x00000000000f0000 $r20:0x0000000000000001 $r21:0x0000000000000000
$r22:0x00000100100da400 $r23:0x00000100100d8b48 $r24:0x00000000000015e8
$r25:0x00000100100d8b40 $r26:0x0000000000001900 $r27:0x0000000000000000
$r28:0x0000010010197ff8 $r29:0x0000000000000044 $r30:0x0000010023e7ade0
$r31:0x00000100100d8e18
$iar:0x0900000001331448 $link:0x090000000116a5f4
[unset $noflregs to view floating point registers]
[unset $novregs to view vector registers]
[unset $novsregs to view vector scalar registers]
15 unnamed block in J9HookDispatch(J9HookInterface**,unsigned long,void*)(hookInterface = 0x0000010023e7ce40, taggedEventNum = 8189, eventData = (nil)), line 235 in "hookable.cpp"
---------
$stkp:0x0000010023e7ac40 $r14:0x00059f6057ab6d57 $r15:0x09001000a04e7480
$r16:0x0000000000000000 $r17:0x08001000a01d57e8 $r18:0x0000000000001628
$r19:0x00000000000f0000 $r20:0x0000000000000001 $r21:0x0000000000000000
$r22:0x00000100100da400 $r23:0x00000100100d8b48 $r24:0x00000000000015e8
$r25:0x00000100100d8b40 $r26:0x0000000000001900 $r27:0x0000000000000000
$r28:0x0000010010197ff8 $r29:0x0000000000000044 $r30:0x0000010023e7ade0
$r31:0x00000100100d8e18
$iar:0x0900000001331448 $link:0x090000000116a5f4
[unset $noflregs to view floating point registers]
[unset $novregs to view vector registers]
[unset $novsregs to view vector scalar registers]
16 unnamed block in J9HookDispatch(J9HookInterface**,unsigned long,void*)(hookInterface = 0x0000010023e7ce40, taggedEventNum = 8189, eventData = (nil)), line 235 in "hookable.cpp"
---------
$stkp:0x0000010023e7ac40 $r14:0x00059f6057ab6d57 $r15:0x09001000a04e7480
$r16:0x0000000000000000 $r17:0x08001000a01d57e8 $r18:0x0000000000001628
$r19:0x00000000000f0000 $r20:0x0000000000000001 $r21:0x0000000000000000
$r22:0x00000100100da400 $r23:0x00000100100d8b48 $r24:0x00000000000015e8
$r25:0x00000100100d8b40 $r26:0x0000000000001900 $r27:0x0000000000000000
$r28:0x0000010010197ff8 $r29:0x0000000000000044 $r30:0x0000010023e7ade0
$r31:0x00000100100d8e18
$iar:0x0900000001331448 $link:0x090000000116a5f4
[unset $noflregs to view floating point registers]
[unset $novregs to view vector registers]
[unset $novsregs to view vector scalar registers]
17 unnamed block in J9HookDispatch(J9HookInterface**,unsigned long,void*)(hookInterface = 0x0000010023e7ce40, taggedEventNum = 8189, eventData = (nil)), line 235 in "hookable.cpp"
---------
$stkp:0x0000010023e7ac40 $r14:0x00059f6057ab6d57 $r15:0x09001000a04e7480
$r16:0x0000000000000000 $r17:0x08001000a01d57e8 $r18:0x0000000000001628
$r19:0x00000000000f0000 $r20:0x0000000000000001 $r21:0x0000000000000000
$r22:0x00000100100da400 $r23:0x00000100100d8b48 $r24:0x00000000000015e8
$r25:0x00000100100d8b40 $r26:0x0000000000001900 $r27:0x0000000000000000
$r28:0x0000010010197ff8 $r29:0x0000000000000044 $r30:0x0000010023e7ade0
$r31:0x00000100100d8e18
$iar:0x0900000001331448 $link:0x090000000116a5f4
[unset $noflregs to view floating point registers]
[unset $novregs to view vector registers]
[unset $novsregs to view vector scalar registers]
18 J9HookDispatch(J9HookInterface**,unsigned long,void*)(hookInterface = 0x0000010023e7ce40, taggedEventNum = 8189, eventData = (nil)), line 235 in "hookable.cpp"
---------
$stkp:0x0000010023e7ad70 $r14:0x00000000303dfd40 $r15:0x00000000305c6f00
$r16:0x00000100103fdf18 $r17:0x0000000000406c00 $r18:0x0000000000406b00
$r19:0x0000000000000001 $r20:0x0900000001815fd0 $r21:0x09001000a0005420
$r22:0x09001000a0681310 $r23:0x09001000a0681050 $r24:0x0000000000000000
$r25:0x0000000000000000 $r26:0x0000000000000000 $r27:0x00000100100d68b0
$r28:0x00000100102c4770 $r29:0x09001000a070d7d8 $r30:0x00000100103fdf18
$r31:0x00000000305c6f00
$iar:0x090000000116a5f0 $link:0x09000000014cbe20
[unset $noflregs to view floating point registers]
[unset $novregs to view vector registers]
[unset $novsregs to view vector scalar registers]
19 cleanUpClassLoader(??, ??), line 361 in "jvmfree.c"
---------
$stkp:0x0000010023e7ae30 $r14:0x00000000303dfd40 $r15:0x00000000305c6f00
$r16:0x00000100103fdf18 $r17:0x0000000000406c00 $r18:0x0000000000406b00
$r19:0x0000000000000001 $r20:0x0900000001815fd0 $r21:0x09001000a0005420
$r22:0x09001000a0681310 $r23:0x09001000a0681050 $r24:0x0000000000000000
$r25:0x0000000000000000 $r26:0x0000000000000000 $r27:0x0000010023067bd8
$r28:0x00000100102c4770 $r29:0x0000000000000000 $r30:0x00000100103fde30
$r31:0x0000010023e7afc8
$iar:0x09000000014cbe1c $link:0x0900000001544878
[unset $noflregs to view floating point registers]
[unset $novregs to view vector registers]
[unset $novsregs to view vector scalar registers]
20 MM_ClassLoaderManager::cleanUpClassLoaders(MM_EnvironmentBase*,J9ClassLoader*,J9MemorySegment**,J9ClassLoader**,volatile bool*)(??, ??, ??, ??, ??, ??), line 241 in "EnvironmentBase.hpp"
---------
$stkp:0x0000010023e7af50 $r14:0x00000000303dfd40 $r15:0x00000000305c6f00
$r16:0x0000000000000001 $r17:0xffffffffffffffff $r18:0x0000010023e7ce40
$r19:0x0000000000001ffd $r20:0x0000000000000003 $r21:0x00000100101aef90
$r22:0x0000000000000000 $r23:0x0000000000000000 $r24:0x0000000000020015
$r25:0x00000100103fdf18 $r26:0x0000000000020012 $r27:0x09001000a04e7480
$r28:0x00000100101af280 $r29:0x0000000000000000 $r30:0x00000100101a73b0
$r31:0x0000010023067bd8
$iar:0x0900000001544874 $link:0x09000000015443b4
[unset $noflregs to view floating point registers]
[unset $novregs to view vector registers]
[unset $novsregs to view vector scalar registers]
Please let me know if you need more help. I do have core dumps/JVM downloaded.
dmitripivkine
on 25 Feb 2020
There is classloader address in the registers of crashed method $r29:0x00000100103fdf18 and I am sure it causes a trouble:
11 J9Method_HT::onClassUnloading(J9ClassLoader*)() at 0x900000006f93eb8
---------
$stkp:0x0000010023e7abb0 $r14:0x00059f6057ab6d57 $r15:0x09001000a04e7480
$r16:0x0000000000000000 $r17:0x08001000a01d57e8 $r18:0x0000000000001628
$r19:0x00000000000f0000 $r20:0x0000000000000001 $r21:0x0000000000000000
$r22:0x00000100100da400 $r23:0x00000100100d8b48 $r24:0x00000000000015e8
$r25:0x00000100100d8b40 $r26:0x0000000000001900 $r27:0x0000000000000000
$r28:0x0000010010469570 $r29:0x00000100103fdf18 $r30:0x000001001046d4b0
$r31:0x00000000305c6f00
$iar:0x0900000006faaf18 $link:0x090000000133144c
[unset $noflregs to view floating point registers]
[unset $novregs to view vector registers]
[unset $novsregs to view vector scalar registers]
> !j9classloader 0x00000100103FDF18
J9ClassLoader at 0x100103fdf18 {
Fields for J9ClassLoader:
0x0: struct J9Pool* sharedLibraries = !j9pool 0x0000000000000000
0x8: struct J9HashTable* classHashTable = !j9hashtable 0x000001002211A490
0x10: struct J9HashTable* romClassOrphansHashTable = !j9hashtable 0x0000000000000000
0x18: struct J9Object* classLoaderObject = !j9object 0x00000000E09702B0 // java/net/URLClassLoader
0x20: struct J9ClassPathEntry* classPathEntries = !j9classpathentry 0x0000000000000000
0x28: UDATA classPathEntryCount = 0x0000000000000000 (0)
0x30: struct J9ClassLoader* unloadLink = !j9classloader 0x00000100103FDE30
0x38: struct J9ClassLoader* gcLinkNext = !j9classloader 0x0000000000000000
0x40: struct J9ClassLoader* gcLinkPrevious = !j9classloader 0x0000000000000000
0x48: UDATA gcFlags = 0x0000000000000002 (2)
0x50: struct J9VMThread* gcThreadNotification = !j9vmthread 0x0000000000000000
0x58: struct J9Pool* jniIDs = !j9pool 0x00000100102E0110
0x60: UDATA flags = 0x0000000000000100 (256)
0x68: struct J9JITExceptionTable* jitMetaDataList = !j9jitexceptiontable 0x0000000000000000
0x70: struct J9MemorySegment* classSegments = !j9memorysegment 0x0000010022DAC9E8
0x78: struct J9RAMClassFreeListBlock* ramClassLargeBlockFreeList = !j9ramclassfreelistblock 0x00000000302D1340
0x80: struct J9RAMClassFreeListBlock* ramClassSmallBlockFreeList = !j9ramclassfreelistblock 0x0000000000000000
0x88: struct J9RAMClassFreeListBlock* ramClassTinyBlockFreeList = !j9ramclassfreelistblock 0x0000000000000000
0x90: UDATA* ramClassUDATABlockFreeList = !j9x 0x00000000302D10C0
0x98: struct J9HashTable* redefinedClasses = !j9hashtable 0x0000000000000000
0xa0: struct J9NativeLibrary* librariesHead = !j9nativelibrary 0x0000000000000000
0xa8: struct J9NativeLibrary* librariesTail = !j9nativelibrary 0x0000000000000000
0xb0: volatile UDATA gcRememberedSet = 0x0000000000000000 (0)
0xb8: struct J9HashTable* moduleHashTable = !j9hashtable 0x0000010021F2FF90
0xc0: struct J9HashTable* packageHashTable = !j9hashtable 0x0000010021F30890
0xc8: struct J9HashTable* moduleExtraInfoHashTable = !j9hashtable 0x0000000000000000
0xd0: struct J9HashTable* classLocationHashTable = !j9hashtable 0x0000000000000000
0xd8: struct J9HashTable* classRelationshipsHashTable = !j9hashtable 0x0000000000000000
}
@gita-omr could someone with AIX skills have an initial look at this to find the right place to send it?
andrewcraik
on 25 Feb 2020
I think it's more of debugging skills that is needed :) We will try to take a look next week.
gita-omr
on 25 Feb 2020
This has now occurred on jdk14 aix too running test java/nio/channels/FileChannel/TransferToChannel.java: https://ci.adoptopenjdk.net/job/Test_openjdk14_j9_sanity.openjdk_ppc64_aix/12/console
03:59:17 [2020-03-02 19:59:03,568] Agent[1]: stderr: Unhandled exception
03:59:17 [2020-03-02 19:59:03,569] Agent[1]: stderr: Type=Segmentation error vmState=0x00020011
03:59:17 [2020-03-02 19:59:03,569] Agent[1]: stderr: J9Generic_Signal_Number=00000018 Signal_Number=0000000b Error_Value=00000000 Signal_Code=00000032
03:59:17 [2020-03-02 19:59:03,569] Agent[1]: stderr: Handler1=09001000A06E65A8 Handler2=09001000A06BBFE0
03:59:17 [2020-03-02 19:59:03,569] Agent[1]: stderr: R0=000000003030AC00 R1=0000010024305ED0 R2=08001000A01F7F30 R3=00000100235985C0
03:59:17 [2020-03-02 19:59:03,569] Agent[1]: stderr: R4=0000000099669966 R5=0000000000000000 R6=0000010010484FB0 R7=0000010010485380
03:59:17 [2020-03-02 19:59:03,569] Agent[1]: stderr: R8=0000000000000000 R9=00000000000003D0 R10=0000000000000000 R11=0000000000000000
03:59:17 [2020-03-02 19:59:03,569] Agent[1]: stderr: R12=0000000030310900 R13=0000010024312800 R14=00059FEB5314F185 R15=09001000A0644DC8
03:59:17 [2020-03-02 19:59:03,569] Agent[1]: stderr: R16=0000000000000000 R17=08001000A01F7BE8 R18=0000000000001768 R19=00000000000F0000
03:59:17 [2020-03-02 19:59:03,569] Agent[1]: stderr: R20=0000000000000001 R21=0000000000000000 R22=00000100100E0418 R23=00000100100DEA20
03:59:17 [2020-03-02 19:59:03,569] Agent[1]: stderr: R24=00000100100DEA18 R25=0000000000000008 R26=00000100235985C0 R27=00000100104FADE8
03:59:17 [2020-03-02 19:59:03,570] Agent[1]: stderr: R28=0000000000000001 R29=0000000000000000 R30=0000010024305FF0 R31=00000100104FADE0
03:59:17 [2020-03-02 19:59:03,570] Agent[1]: stderr: IAR=090000000C8A1EBC LR=090000000C8B3948 MSR=A00000000200D032 CTR=0000000000000000
03:59:17 [2020-03-02 19:59:03,570] Agent[1]: stderr: CR=4200028000000000 FPSCR=8202000000000000 XER=0000000082020000
03:59:17 [2020-03-02 19:59:03,570] Agent[1]: stderr: FPR0 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,570] Agent[1]: stderr: FPR1 c3e0000000000000 (f: 0.000000, d: -9.223372e+18)
03:59:17 [2020-03-02 19:59:03,570] Agent[1]: stderr: FPR2 41cdcd6500000000 (f: 0.000000, d: 1.000000e+09)
03:59:17 [2020-03-02 19:59:03,571] Agent[1]: stderr: FPR3 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,571] Agent[1]: stderr: FPR4 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,571] Agent[1]: stderr: FPR5 c3e0000000000000 (f: 0.000000, d: -9.223372e+18)
03:59:17 [2020-03-02 19:59:03,571] Agent[1]: stderr: FPR6 bfe0000000000000 (f: 0.000000, d: -5.000000e-01)
03:59:17 [2020-03-02 19:59:03,571] Agent[1]: stderr: FPR7 412e848000000000 (f: 0.000000, d: 1.000000e+06)
03:59:17 [2020-03-02 19:59:03,571] Agent[1]: stderr: FPR8 3ff0000000000000 (f: 0.000000, d: 1.000000e+00)
03:59:17 [2020-03-02 19:59:03,571] Agent[1]: stderr: FPR9 4530000000000000 (f: 0.000000, d: 1.934281e+25)
03:59:17 [2020-03-02 19:59:03,571] Agent[1]: stderr: FPR10 412e848000000000 (f: 0.000000, d: 1.000000e+06)
03:59:17 [2020-03-02 19:59:03,571] Agent[1]: stderr: FPR11 43300000000f4240 (f: 1000000.000000, d: 4.503600e+15)
03:59:17 [2020-03-02 19:59:03,571] Agent[1]: stderr: FPR12 4530000000000000 (f: 0.000000, d: 1.934281e+25)
03:59:17 [2020-03-02 19:59:03,571] Agent[1]: stderr: FPR13 4049000000000000 (f: 0.000000, d: 5.000000e+01)
03:59:17 [2020-03-02 19:59:03,571] Agent[1]: stderr: FPR14 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,571] Agent[1]: stderr: FPR15 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,571] Agent[1]: stderr: FPR16 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,572] Agent[1]: stderr: FPR17 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,572] Agent[1]: stderr: FPR18 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,572] Agent[1]: stderr: FPR19 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,572] Agent[1]: stderr: FPR20 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,572] Agent[1]: stderr: FPR21 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,572] Agent[1]: stderr: FPR22 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,572] Agent[1]: stderr: FPR23 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,572] Agent[1]: stderr: FPR24 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,572] Agent[1]: stderr: FPR25 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,572] Agent[1]: stderr: FPR26 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,572] Agent[1]: stderr: FPR27 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,572] Agent[1]: stderr: FPR28 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,572] Agent[1]: stderr: FPR29 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,572] Agent[1]: stderr: FPR30 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,572] Agent[1]: stderr: FPR31 0000000000000000 (f: 0.000000, d: 0.000000e+00)
03:59:17 [2020-03-02 19:59:03,573] Agent[1]: stderr: Module=/ramdisk0/build/workspace/Test_openjdk14_j9_sanity.openjdk_ppc64_aix/openjdkbinary/j2sdk-image/lib/compressedrefs/libj9jit29.so
03:59:17 [2020-03-02 19:59:03,573] Agent[1]: stderr: Module_base_address=090000000B898000
03:59:17 [2020-03-02 19:59:03,573] Agent[1]: stderr: Target=2_90_20200302_23 (AIX 7.1)
03:59:17 [2020-03-02 19:59:03,573] Agent[1]: stderr: CPU=ppc64 (20 logical CPUs) (0x800000000 RAM)
03:59:17 [2020-03-02 19:59:03,573] Agent[1]: stderr: ----------- Stack Backtrace -----------
03:59:17 [2020-03-02 19:59:03,573] Agent[1]: stderr: (0x090000000C8B3948 [libj9jit29.so+0x101b948])
03:59:17 [2020-03-02 19:59:03,573] Agent[1]: stderr: _ZL14J9HookDispatchPP15J9HookInterfacemPv+0x1e8 (0x090000000277C76C [libj9hookable29.so+0x76c])
03:59:17 [2020-03-02 19:59:03,573] Agent[1]: stderr: _ZN21MM_ClassLoaderManager24cleanUpClassLoadersStartEP18MM_EnvironmentBaseP13J9ClassLoaderP10MM_HeapMapP19MM_ClassUnloadStats+0x4bc (0x090000000836D440 [libj9gc29.so+0x17440])
03:59:17 [2020-03-02 19:59:03,573] Agent[1]: stderr: _ZN26MM_GlobalCollectorDelegate22unloadDeadClassLoadersEP18MM_EnvironmentBase+0x124 (0x09000000083F1DA8 [libj9gc29.so+0x9bda8])
03:59:17 [2020-03-02 19:59:03,573] Agent[1]: stderr: _ZN26MM_GlobalCollectorDelegate18postMarkProcessingEP18MM_EnvironmentBase+0x70 (0x09000000083F1954 [libj9gc29.so+0x9b954])
03:59:17 [2020-03-02 19:59:03,573] Agent[1]: stderr: _ZN19MM_ParallelGlobalGC26masterThreadGarbageCollectEP18MM_EnvironmentBaseP22MM_AllocateDescriptionbb+0x1fc (0x0900000008455A80 [libj9gc29.so+0xffa80])
03:59:17 [2020-03-02 19:59:03,573] Agent[1]: stderr: _ZN15MM_ConcurrentGC22internalGarbageCollectEP18MM_EnvironmentBaseP17MM_MemorySubSpaceP22MM_AllocateDescription+0x50 (0x090000000843E9B4 [libj9gc29.so+0xe89b4])
03:59:17 [2020-03-02 19:59:03,573] Agent[1]: stderr: _ZN12MM_Collector14garbageCollectEP18MM_EnvironmentBaseP17MM_MemorySubSpaceP22MM_AllocateDescriptionjP28MM_ObjectAllocationInterfaceS3_P20MM_AllocationContext+0x278 (0x09000000083DE27C [libj9gc29.so+0x8827c])
03:59:17 [2020-03-02 19:59:03,574] Agent[1]: stderr: _ZN17MM_MemorySubSpace20systemGarbageCollectEP18MM_EnvironmentBasej+0x150 (0x0900000008393914 [libj9gc29.so+0x3d914])
03:59:17 [2020-03-02 19:59:03,574] Agent[1]: stderr: _ZN17MM_MemorySubSpace20systemGarbageCollectEP18MM_EnvironmentBasej+0x60 (0x0900000008393824 [libj9gc29.so+0x3d824])
03:59:17 [2020-03-02 19:59:03,574] Agent[1]: stderr: _ZN17MM_MemorySubSpace20systemGarbageCollectEP18MM_EnvironmentBasej+0x60 (0x0900000008393824 [libj9gc29.so+0x3d824])
03:59:17 [2020-03-02 19:59:03,574] Agent[1]: stderr: _ZN14MM_MemorySpace20systemGarbageCollectEP18MM_EnvironmentBasej+0x30 (0x090000000838E4F4 [libj9gc29.so+0x384f4])
03:59:17 [2020-03-02 19:59:03,574] Agent[1]: stderr: _ZN7MM_Heap20systemGarbageCollectEP18MM_EnvironmentBasej+0x14 (0x090000000838B918 [libj9gc29.so+0x35918])
03:59:17 [2020-03-02 19:59:03,574] Agent[1]: stderr: j9gc_modron_global_collect+0x3c (0x09000000083874C0 [libj9gc29.so+0x314c0])
03:59:17 [2020-03-02 19:59:03,574] Agent[1]: stderr: JVM_GC_Impl (0x090000000881B550 [libjclse29.so+0x94550])
03:59:17 [2020-03-02 19:59:03,574] Agent[1]: stderr: JVM_GC (0x0900000003FCD47C [libjvm.so+0x1047c])
03:59:17 [2020-03-02 19:59:03,574] Agent[1]: stderr: JVM_GC (0x0900000003F85B3C [libjvm.so+0x4b3c])
03:59:17 [2020-03-02 19:59:03,574] Agent[1]: stderr: JVM_GC (0x0900000003F49B3C [libjvm.so+0x4b3c])
03:59:17 [2020-03-02 19:59:03,574] Agent[1]: stderr: Java_java_lang_Runtime_gc+0xc (0x090000000473E1B0 [libjava.so+0x151b0])
03:59:17 [2020-03-02 19:59:03,574] Agent[1]: stderr: (0x090000000416B53C [libj9vm29.so+0x14e53c])
03:59:17 [2020-03-02 19:59:03,574] Agent[1]: stderr: ffi_call+0x98 (0x090000000416A83C [libj9vm29.so+0x14d83c])
03:59:17 [2020-03-02 19:59:03,574] Agent[1]: stderr: (0x0900000004175AA4 [libj9vm29.so+0x158aa4])
03:59:17 [2020-03-02 19:59:03,575] Agent[1]: stderr: (0x09000000040947FC [libj9vm29.so+0x777fc])
03:59:17 [2020-03-02 19:59:03,575] Agent[1]: stderr: sidecarInvokeReflectMethodImpl+0x490 (0x0900000004083794 [libj9vm29.so+0x66794])
03:59:17 [2020-03-02 19:59:03,575] Agent[1]: stderr: sidecarInvokeReflectMethod+0x54 (0x0900000004084838 [libj9vm29.so+0x67838])
03:59:17 [2020-03-02 19:59:03,575] Agent[1]: stderr: JVM_InvokeMethod_Impl+0xa8 (0x090000000881A60C [libjclse29.so+0x9360c])
03:59:17 [2020-03-02 19:59:03,575] Agent[1]: stderr: JVM_InvokeMethod+0x64 (0x0900000003FCCC28 [libjvm.so+0xfc28])
03:59:17 [2020-03-02 19:59:03,575] Agent[1]: stderr: JVM_InvokeMethod+0x6c (0x0900000003F87BF0 [libjvm.so+0x6bf0])
03:59:17 [2020-03-02 19:59:03,575] Agent[1]: stderr: JVM_InvokeMethod+0x6c (0x0900000003F4BBF0 [libjvm.so+0x6bf0])
03:59:17 [2020-03-02 19:59:03,575] Agent[1]: stderr: Java_jdk_internal_reflect_NativeMethodAccessorImpl_invoke0+0x18 (0x090000000473671C [libjava.so+0xd71c])
03:59:17 [2020-03-02 19:59:03,575] Agent[1]: stderr: (0x00000100105A0FB0)
03:59:17 [2020-03-02 19:59:03,575] Agent[1]: stderr: runJavaThread+0x1d8 (0x090000000407F83C [libj9vm29.so+0x6283c])
03:59:17 [2020-03-02 19:59:03,575] Agent[1]: stderr: javaProtectedThreadProc+0x11c (0x090000000401F9E0 [libj9vm29.so+0x29e0])
03:59:17 [2020-03-02 19:59:03,575] Agent[1]: stderr: omrsig_protect+0x4a4 (0x0900000004324A48 [libj9prt29.so+0x6ca48])
03:59:17 [2020-03-02 19:59:03,575] Agent[1]: stderr: javaThreadProc+0x68 (0x090000000401F84C [libj9vm29.so+0x284c])
03:59:17 [2020-03-02 19:59:03,575] Agent[1]: stderr: thread_wrapper+0x558 (0x090000000429F63C [libj9thr29.so+0x563c])
03:59:17 [2020-03-02 19:59:03,575] Agent[1]: stderr: _pthread_body+0xf0 (0x0900000000567E14 [libpthreads.a+0x3e14])
03:59:17 [2020-03-02 19:59:03,576] Agent[1]: stderr: ---------------------------------------
03:59:17 [2020-03-02 19:59:03,576] Agent[1]: stderr: JVMDUMP039I Processing dump event "gpf", detail "" at 2020/03/02 19:59:03 - please wait.
03:59:17 [2020-03-02 19:59:03,576] Agent[1]: stderr: JVMDUMP032I JVM requested System dump using '/ramdisk0/build/workspace/Test_openjdk14_j9_sanity.openjdk_ppc64_aix/openjdk-tests/TKG/test_output_1583192345480/jdk_nio_0/work/scratch/core.20200302.195903.6029710.0001.dmp' in response to an event
03:59:17 [2020-03-02 19:59:03,598] Agent[1]: stderr: Note: "Enable full CORE dump" in smit is set to FALSE and as a result there will be limited threading information in core file.
03:59:17 [2020-03-02 19:59:03,938] Agent[1]: stderr: JVMDUMP010I System dump written to /ramdisk0/build/workspace/Test_openjdk14_j9_sanity.openjdk_ppc64_aix/openjdk-tests/TKG/test_output_1583192345480/jdk_nio_0/work/scratch/core.20200302.195903.6029710.0001.dmp
03:59:17 [2020-03-02 19:59:03,938] Agent[1]: stderr: JVMDUMP032I JVM requested Java dump using '/ramdisk0/build/workspace/Test_openjdk14_j9_sanity.openjdk_ppc64_aix/openjdk-tests/TKG/test_output_1583192345480/jdk_nio_0/work/scratch/javacore.20200302.195903.6029710.0002.txt' in response to an event
03:59:17 [2020-03-02 19:59:04,078] Agent[1]: stderr: JVMDUMP010I Java dump written to /ramdisk0/build/workspace/Test_openjdk14_j9_sanity.openjdk_ppc64_aix/openjdk-tests/TKG/test_output_1583192345480/jdk_nio_0/work/scratch/javacore.20200302.195903.6029710.0002.txt
03:59:17 [2020-03-02 19:59:04,079] Agent[1]: stderr: JVMDUMP032I JVM requested Snap dump using '/ramdisk0/build/workspace/Test_openjdk14_j9_sanity.openjdk_ppc64_aix/openjdk-tests/TKG/test_output_1583192345480/jdk_nio_0/work/scratch/Snap.20200302.195903.6029710.0003.trc' in response to an event
03:59:17 [2020-03-02 19:59:04,200] Agent[1]: stderr: JVMDUMP010I Snap dump written to /ramdisk0/build/workspace/Test_openjdk14_j9_sanity.openjdk_ppc64_aix/openjdk-tests/TKG/test_output_1583192345480/jdk_nio_0/work/scratch/Snap.20200302.195903.6029710.0003.trc
03:59:17 [2020-03-02 19:59:04,201] Agent[1]: stderr: JVMDUMP007I JVM Requesting JIT dump using '/ramdisk0/build/workspace/Test_openjdk14_j9_sanity.openjdk_ppc64_aix/openjdk-tests/TKG/test_output_1583192345480/jdk_nio_0/work/scratch/jitdump.20200302.195903.6029710.0004.dmp'
03:59:17 [2020-03-02 19:59:04,201] Agent[1]: stderr: JVMDUMP010I JIT dump written to /ramdisk0/build/workspace/Test_openjdk14_j9_sanity.openjdk_ppc64_aix/openjdk-tests/TKG/test_output_1583192345480/jdk_nio_0/work/scratch/jitdump.20200302.195903.6029710.0004.dmp
03:59:17 [2020-03-02 19:59:04,201] Agent[1]: stderr: JVMDUMP013I Processed dump event "gpf", detail "".
I stored results locally, so if somebody needs core files for previous or this one ask me
dmitripivkine
on 3 Mar 2020
Moving forward since I don't see any fix in hand and it's becoming too late to update the 0.19 release. Note the branch for the 0.20 release occurs on March 8.
pshipton
on 4 Mar 2020
@dmitripivkine you mentioned xlinux jdmpview couldn't find the java context in the core file from the Adopt build? I tried creating a core java -Xdump:system:events=vmstop from an Adopt jdk14 build, it's 3GB+, and the context is found running xlinux jdmpview. Various commands work as well. If there is a problem with the core, it's probably a machine issue as you suggested.
pshipton
on 4 Mar 2020
I stored results locally, so if somebody needs core files for previous or this one ask me
please note that system core from second failure can not be opened in jdmpview (*0 : PID: 8978446 : No JRE) @pshipton have tested ability of jdmpview to open file for core generated on AIX in Java 14 and seems it is not broken. I guess something is missed in machine configuration
dmitripivkine
on 5 Mar 2020
I'll see if I can't narrow down which AIX machines are affected
- https://ci.adoptopenjdk.net/view/Test_grinder/job/Grinder/2430/ JDK11-j9
test-ibm-ppc64-aix-71-1 - https://ci.adoptopenjdk.net/view/Test_grinder/job/Grinder/2431/ JDK11-j9
test-ibm-ppc64-aix-71-2 - https://ci.adoptopenjdk.net/view/Test_grinder/job/Grinder/2434/ JDK14-j9
build-osuosl-ppc64-aix-71-1
M-Davies
on 5 Mar 2020
Please confirm that fullcore attribute is set. lsattr -D -l sys0 | grep fullcore. You can enable with chdev -l sys0 -a fullcore=true.
I have access to both build-osuosl-ppc64-aix-71-1 and build-osuosl-ppc64-aix-71-2 and the attribute is set to True on both of them. I don't have access to the others to check.
jdekonin
on 5 Mar 2020
@jdekonin Raised https://github.com/AdoptOpenJDK/openjdk-infrastructure/issues/1189 for the fullcore enabling. Although it looks like all the grinders passed anyway
M-Davies
on 6 Mar 2020
I haven't seen this pop up in the nightly builds at adopt or in grinders so I'll close this as resolved for now. If it comes back, it can always be reopened
M-Davies
on 19 Mar 2020
I can not understand why this issue is closed without investigation. We know this is highly intermittent issue. Also I believe https://github.com/eclipse/openj9/issues/8619 might be a different issue (user raised - but we don't know). I would prefer to close https://github.com/eclipse/openj9/issues/8619 instead
dmitripivkine
on 19 Mar 2020
For failure https://ci.adoptopenjdk.net/view/Test_openjdk/job/Test_openjdk8_j9_sanity.openjdk_ppc64le_linux/148/ the crash occur in the same method as before J9Method_HT::onClassUnloading:
// onClassUnloading is executed when all threads are stopped
// so there are no synchronization issues
void J9Method_HT::onClassUnloading(J9ClassLoader *j9classLoader)
{
// Scan the entire DLT_HT and delete entries matching the given classloader
// Also free invalid entries that have j9method==NULL
for (size_t bucketID = 0; bucketID < HT_SIZE; bucketID++)
{
HT_Entry *entry = _spine[bucketID];
HT_Entry *prev = NULL;
for (; entry; prev = entry, entry = entry->_next)
{
if (NULL == entry->_j9method
|| J9_CLASS_FROM_METHOD(entry->_j9method)->classLoader == j9classLoader)
{
if (prev)
prev->_next = entry->_next;
else
_spine[bucketID] = entry->_next;
entry->_next = NULL; // for safety
jitPersistentFree(entry);
_numEntries--;
}
}
}
}
just from different hook, this time J9HOOK_VM_ANON_CLASSES_UNLOAD
The method was called with classloader 0x3FFF80098CC8 com/ibm/oti/vm/BootstrapClassLoader. I believe the exact reason for crash was an attempt to get J9_CLASS_FROM_METHOD(entry->_j9method)->classLoader (decoding garbage ?) and entry address was 0x3FFF805FDB30
0x3FFF805FDB00 : 00003fff805fdab0 0000000000059300 [ .._..?.......... ]
0x3FFF805FDB10 : 00003fff6f8d0ebc 0000000000000008 [ ...o.?.......... ]
0x3FFF805FDB20 : 0000000000000030 0000000000000000 [ 0............... ]
0x3FFF805FDB30 : 0000000000000000 00000000003cb108 [ ..........<..... ] <----
0x3FFF805FDB40 : 0000000000000000 000000000000194f [ ........O....... ]
0x3FFF805FDB50 : 0000000000000030 0000000000000000 [ 0............... ]
0x3FFF805FDB60 : 00003fff851fce68 0000000000000000 [ h....?.......... ]
0x3FFF805FDB70 : 00003fff805fdb90 0000000000000000 [ .._..?.......... ]
0x3FFF805FDB80 : 0000000000000040 0000000000000000 [ @............... ]
0x3FFF805FDB90 : 00003fff851fcf08 00003fff805ecde0 [ .....?....^..?.. ]
0x3FFF805FDBA0 : 00003fff805fdb60 00000000003cb108 [ `._..?....<..... ]
0x3FFF805FDBB0 : 00003fff805fd5f0 0000000000000008 [ .._..?.......... ]
0x3FFF805FDBC0 : 0000000000000040 0000000000000000 [ @............... ]
Just occurred again in a jdk14-j9-plinux run the other night (test-osuosl-centos74-ppc64le-1)
https://ci.adoptopenjdk.net/view/Test_openjdk/job/Test_openjdk14_j9_sanity.openjdk_ppc64le_linux/39/console
Diagnostic files: https://ibm.box.com/s/e0tvq7etp9o5rhp5dpul72qas8qil3tr
~Will try and run a few grinders on java/nio/file/WatchService/LotsOfEvents.java. See if I can't reproduce it.~ All passed, not sure if there is a specific way to reproduce this
M-Davies
on 25 Mar 2020
I believe this is just very intermittent issue.
There is the same stack:
#12 <signal handler called>
#13 0x00003fff7086fc68 in J9Method_HT::onClassUnloading(J9ClassLoader*) ()
from /team/Dmitri/8652/new2/jdk-14+36/lib/compressedrefs/libj9jit29.so
#14 0x00003fff708874a0 in jitHookAnonClassesUnload () from /team/Dmitri/8652/new2/jdk-14+36/lib/compressedrefs/libj9jit29.so
#15 0x00003fff77fd1840 in J9HookDispatch () from /team/Dmitri/8652/new2/jdk-14+36/lib/compressedrefs/libj9hookable29.so
#16 0x00003fff7065b114 in MM_ClassLoaderManager::cleanUpClassLoadersStart(MM_EnvironmentBase*, J9ClassLoader*, MM_HeapMap*, MM_ClassUnloadStats*) () from /team/Dmitri/8652/new2/jdk-14+36/lib/compressedrefs/libj9gc29.so
#17 0x00003fff705cf1c8 in MM_GlobalCollectorDelegate::unloadDeadClassLoaders(MM_EnvironmentBase*) ()
from /team/Dmitri/8652/new2/jdk-14+36/lib/compressedrefs/libj9gc29.so
#18 0x00003fff705cf448 in MM_GlobalCollectorDelegate::postMarkProcessing(MM_EnvironmentBase*) ()
from /team/Dmitri/8652/new2/jdk-14+36/lib/compressedrefs/libj9gc29.so
I believe this is just very intermittent issue.
That's correct. From my observations the failure rate is around 1/20.
AlenBadel
on 25 Mar 2020
This looks like a dup of this as well https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_sanity.openjdk_ppc64le_linux_Personal/4/
java/util/jar/JarFile/ScanSignedJar.java
17:06:38 [2020-03-24 17:06:38,421] Agent[1]: stderr: Unhandled exception
17:06:38 [2020-03-24 17:06:38,422] Agent[1]: stderr: Type=Segmentation error vmState=0x00020011
17:06:38 [2020-03-24 17:06:38,422] Agent[1]: stderr: J9Generic_Signal_Number=00000018 Signal_Number=0000000b Error_Value=00000000 Signal_Code=00000001
17:06:38 [2020-03-24 17:06:38,422] Agent[1]: stderr: Handler1=00003FFF9E707FF0 Handler2=00003FFF9E597180
17:06:38 [2020-03-24 17:06:38,422] Agent[1]: stderr: R0=00003FFF9D3649EC R1=00003FFF9F09CDB0 R2=00003FFF9DF19300 R3=00003FFF97EF6120
17:06:38 [2020-03-24 17:06:38,422] Agent[1]: stderr: R4=00003FFF9F09CE60 R5=00003FFF980EE660 R6=00003FFF980EE660 R7=00003FFF700FE7E0
17:06:38 [2020-03-24 17:06:38,423] Agent[1]: stderr: R8=00003FFF980D2548 R9=0000000000000000 R10=0000000000000000 R11=0000000100000000
17:06:38 [2020-03-24 17:06:38,423] Agent[1]: stderr: R12=00003FFF9F40D1D0 R13=00003FFF9F0A6900 R14=0000000000000007 R15=0000000000000004
17:06:38 [2020-03-24 17:06:38,423] Agent[1]: stderr: R16=00003FFF98048F40 R17=00003FFF9F09D57F R18=0000000000000006 R19=0000000000020019
17:06:38 [2020-03-24 17:06:38,423] Agent[1]: stderr: R20=0000000000000000 R21=00003FFF9E898330 R22=0005A1A020AA406B R23=00003FFF9D364878
17:06:38 [2020-03-24 17:06:38,423] Agent[1]: stderr: R24=00003FFF98012238 R25=00003FFF9DF4CDC0 R26=00003FFF97EF6120 R27=00003FFF97EF6318
17:06:38 [2020-03-24 17:06:38,423] Agent[1]: stderr: R28=0000000000000000 R29=00003FFF97EF6160 R30=00003FFF9F09CE60 R31=00003FFF480268C0
17:06:38 [2020-03-24 17:06:38,423] Agent[1]: stderr: NIP=00003FFF9D342574 MSR=800000010280F033 ORIG_GPR3=00000000000081C8 CTR=00003FFF9F40D1D0
17:06:38 [2020-03-24 17:06:38,423] Agent[1]: stderr: LINK=00003FFF9D3649EC XER=0000000000000000 CCR=0000000028004224 SOFTE=0000000000000001
17:06:38 [2020-03-24 17:06:38,423] Agent[1]: stderr: TRAP=0000000000000300 DAR=0000000000000000 dsisr=0000000040000000 RESULT=0000000000000000
17:06:38 [2020-03-24 17:06:38,423] Agent[1]: stderr: FPR0 00003fff9e896f08 (f: 2659806976.000000, d: 3.476597e-310)
17:06:38 [2020-03-24 17:06:38,423] Agent[1]: stderr: FPR1 4050111d20000000 (f: 536870912.000000, d: 6.426740e+01)
17:06:38 [2020-03-24 17:06:38,423] Agent[1]: stderr: FPR2 3f847ae147ae147b (f: 1202590848.000000, d: 1.000000e-02)
17:06:38 [2020-03-24 17:06:38,423] Agent[1]: stderr: FPR3 3fee666660000000 (f: 1610612736.000000, d: 9.500000e-01)
17:06:38 [2020-03-24 17:06:38,424] Agent[1]: stderr: FPR4 3f499a0000000000 (f: 0.000000, d: 7.812977e-04)
17:06:38 [2020-03-24 17:06:38,424] Agent[1]: stderr: FPR5 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,424] Agent[1]: stderr: FPR6 61656c43746f6f52 (f: 1953460096.000000, d: 1.505934e+161)
17:06:38 [2020-03-24 17:06:38,424] Agent[1]: stderr: FPR7 696b72614d2f6176 (f: 1294950784.000000, d: 6.565364e+199)
17:06:38 [2020-03-24 17:06:38,424] Agent[1]: stderr: FPR8 bfa0eec4c0000000 (f: 3221225472.000000, d: -3.307166e-02)
17:06:38 [2020-03-24 17:06:38,424] Agent[1]: stderr: FPR9 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,424] Agent[1]: stderr: FPR10 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,424] Agent[1]: stderr: FPR11 41cdcd6500000000 (f: 0.000000, d: 1.000000e+09)
17:06:38 [2020-03-24 17:06:38,424] Agent[1]: stderr: FPR12 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,425] Agent[1]: stderr: FPR13 bfb7440000000000 (f: 0.000000, d: -9.088135e-02)
17:06:38 [2020-03-24 17:06:38,425] Agent[1]: stderr: FPR14 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,425] Agent[1]: stderr: FPR15 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,425] Agent[1]: stderr: FPR16 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,425] Agent[1]: stderr: FPR17 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,425] Agent[1]: stderr: FPR18 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,425] Agent[1]: stderr: FPR19 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,425] Agent[1]: stderr: FPR20 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,425] Agent[1]: stderr: FPR21 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,425] Agent[1]: stderr: FPR22 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,426] Agent[1]: stderr: FPR23 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,426] Agent[1]: stderr: FPR24 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,427] Agent[1]: stderr: FPR25 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,427] Agent[1]: stderr: FPR26 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,427] Agent[1]: stderr: FPR27 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,428] Agent[1]: stderr: FPR28 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,428] Agent[1]: stderr: FPR29 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,429] Agent[1]: stderr: FPR30 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,429] Agent[1]: stderr: FPR31 0000000000000000 (f: 0.000000, d: 0.000000e+00)
17:06:38 [2020-03-24 17:06:38,429] Agent[1]: stderr: Module=/home/jenkins/workspace/Test_openjdk8_j9_sanity.openjdk_ppc64le_linux_Personal/openjdkbinary/j2sdk-image/jre/lib/ppc64le/compressedrefs/libj9jit29.so
17:06:38 [2020-03-24 17:06:38,429] Agent[1]: stderr: Module_base_address=00003FFF9D1F0000
17:06:38 [2020-03-24 17:06:38,430] Agent[1]: stderr: Target=2_90_20200324_768 (Linux 4.4.0-173-generic)
17:06:38 [2020-03-24 17:06:38,430] Agent[1]: stderr: CPU=ppc64le (16 logical CPUs) (0x1fe090000 RAM)
17:06:38 [2020-03-24 17:06:38,430] Agent[1]: stderr: ----------- Stack Backtrace -----------
17:06:38 [2020-03-24 17:06:38,430] Agent[1]: stderr: (0x00003FFF9D342574 [libj9jit29.so+0x152574])
17:06:38 [2020-03-24 17:06:38,430] Agent[1]: stderr: (0x00003FFF9F09CE00 [<unknown>+0x0])
17:06:38 [2020-03-24 17:06:38,431] Agent[1]: stderr: (0x00003FFF9D3649EC [libj9jit29.so+0x1749ec])
17:06:38 [2020-03-24 17:06:38,431] Agent[1]: stderr: (0x00003FFF9E611800 [libj9hookable29.so+0x1800])
17:06:38 [2020-03-24 17:06:38,431] Agent[1]: stderr: (0x00003FFF9D11B134 [libj9gc29.so+0x25b134])
17:06:38 [2020-03-24 17:06:38,431] Agent[1]: stderr: (0x00003FFF9D093AA8 [libj9gc29.so+0x1d3aa8])
17:06:38 [2020-03-24 17:06:38,431] Agent[1]: stderr: (0x00003FFF9D093D28 [libj9gc29.so+0x1d3d28])
17:06:38 [2020-03-24 17:06:38,431] Agent[1]: stderr: (0x00003FFF9D09FCAC [libj9gc29.so+0x1dfcac])
17:06:38 [2020-03-24 17:06:38,431] Agent[1]: stderr: (0x00003FFF9D0F9B2C [libj9gc29.so+0x239b2c])
17:06:38 [2020-03-24 17:06:38,431] Agent[1]: stderr: (0x00003FFF9D02956C [libj9gc29.so+0x16956c])
17:06:38 [2020-03-24 17:06:38,431] Agent[1]: stderr: (0x00003FFF9D0FFE30 [libj9gc29.so+0x23fe30])
17:06:38 [2020-03-24 17:06:38,431] Agent[1]: stderr: (0x00003FFF9D102608 [libj9gc29.so+0x242608])
17:06:38 [2020-03-24 17:06:38,431] Agent[1]: stderr: (0x00003FFF9D102C9C [libj9gc29.so+0x242c9c])
17:06:38 [2020-03-24 17:06:38,431] Agent[1]: stderr: (0x00003FFF9D03B2C4 [libj9gc29.so+0x17b2c4])
17:06:38 [2020-03-24 17:06:38,432] Agent[1]: stderr: (0x00003FFF9D097DAC [libj9gc29.so+0x1d7dac])
17:06:38 [2020-03-24 17:06:38,432] Agent[1]: stderr: (0x00003FFF9CF1AEDC [libj9gc29.so+0x5aedc])
17:06:38 [2020-03-24 17:06:38,432] Agent[1]: stderr: (0x00003FFF9DC52BC0 [libj9jit29.so+0xa62bc0])
17:06:38 [2020-03-24 17:06:38,432] Agent[1]: stderr: (0x00003FFF9DC6B890 [libj9jit29.so+0xa7b890])
17:06:38 [2020-03-24 17:06:38,432] Agent[1]: stderr: (0x00003FFF9E6F0468 [libj9vm29.so+0x90468])
17:06:38 [2020-03-24 17:06:38,432] Agent[1]: stderr: (0x00003FFF9E70CFC0 [libj9vm29.so+0xacfc0])
17:06:38 [2020-03-24 17:06:38,432] Agent[1]: stderr: (0x00003FFF9E76A1C8 [libj9vm29.so+0x10a1c8])
17:06:38 [2020-03-24 17:06:38,432] Agent[1]: stderr: (0x00003FFF9E598588 [libj9prt29.so+0x28588])
17:06:38 [2020-03-24 17:06:38,432] Agent[1]: stderr: (0x00003FFF9E76A29C [libj9vm29.so+0x10a29c])
17:06:38 [2020-03-24 17:06:38,432] Agent[1]: stderr: (0x00003FFF9E70F9A0 [libj9vm29.so+0xaf9a0])
17:06:38 [2020-03-24 17:06:38,432] Agent[1]: stderr: (0x00003FFF9E70C5D8 [libj9vm29.so+0xac5d8])
17:06:38 [2020-03-24 17:06:38,432] Agent[1]: stderr: (0x00003FFF9F3C9CA4 [libjli.so+0x9ca4])
17:06:38 [2020-03-24 17:06:38,432] Agent[1]: stderr: (0x00003FFF9F408040 [libpthread.so.0+0x8040])
17:06:38 [2020-03-24 17:06:38,433] Agent[1]: stderr: clone+0x98 (0x00003FFF9F2E3BB0 [libc.so.6+0x123bb0])
17:06:38 [2020-03-24 17:06:38,433] Agent[1]: stderr: ---------------------------------------
17:06:38 [2020-03-24 17:06:38,433] Agent[1]: stderr: JVMDUMP039I Processing dump event "gpf", detail "" at 2020/03/24 17:06:38 - please wait.
17:06:38 [2020-03-24 17:06:38,435] Agent[1]: stderr: JVMDUMP032I JVM requested System dump using '/home/jenkins/workspace/Test_openjdk8_j9_sanity.openjdk_ppc64le_linux_Personal/openjdk-tests/TKG/test_output_1585082508650/jdk_util_0/work/scratch/1/core.20200324.170638.1269.0001.dmp' in response to an event
17:06:40 [2020-03-24 17:06:40,544] Agent[1]: stderr: JVMPORT030W /proc/sys/kernel/core_pattern setting "|/usr/share/apport/apport %p %s %c %d %P" specifies that the core dump is to be piped to an external program. Attempting to rename either core or core.2505.
17:06:40 [2020-03-24 17:06:40,545] Agent[1]: stderr:
17:06:41 [2020-03-24 17:06:40,690] Agent[1]: stderr: JVMDUMP010I System dump written to /home/jenkins/workspace/Test_openjdk8_j9_sanity.openjdk_ppc64le_linux_Personal/openjdk-tests/TKG/test_output_1585082508650/jdk_util_0/work/scratch/1/core.20200324.170638.1269.0001.dmp
17:06:41 [2020-03-24 17:06:41,009] Agent[1]: stderr: JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Test_openjdk8_j9_sanity.openjdk_ppc64le_linux_Personal/openjdk-tests/TKG/test_output_1585082508650/jdk_util_0/work/scratch/1/javacore.20200324.170638.1269.0002.txt' in response to an event
17:06:44 [2020-03-24 17:06:43,887] Agent[1]: stderr: JVMDUMP010I Java dump written to /home/jenkins/workspace/Test_openjdk8_j9_sanity.openjdk_ppc64le_linux_Personal/openjdk-tests/TKG/test_output_1585082508650/jdk_util_0/work/scratch/1/javacore.20200324.170638.1269.0002.txt
17:06:44 [2020-03-24 17:06:43,887] Agent[1]: stderr: JVMDUMP032I JVM requested Snap dump using '/home/jenkins/workspace/Test_openjdk8_j9_sanity.openjdk_ppc64le_linux_Personal/openjdk-tests/TKG/test_output_1585082508650/jdk_util_0/work/scratch/1/Snap.20200324.170638.1269.0003.trc' in response to an event
17:06:44 [2020-03-24 17:06:43,988] Agent[1]: stderr: JVMDUMP010I Snap dump written to /home/jenkins/workspace/Test_openjdk8_j9_sanity.openjdk_ppc64le_linux_Personal/openjdk-tests/TKG/test_output_1585082508650/jdk_util_0/work/scratch/1/Snap.20200324.170638.1269.0003.trc
17:06:44 [2020-03-24 17:06:43,991] Agent[1]: stderr: JVMDUMP007I JVM Requesting JIT dump using '/home/jenkins/workspace/Test_openjdk8_j9_sanity.openjdk_ppc64le_linux_Personal/openjdk-tests/TKG/test_output_1585082508650/jdk_util_0/work/scratch/1/jitdump.20200324.170638.1269.0004.dmp'
17:06:44 [2020-03-24 17:06:43,991] Agent[1]: stderr: JVMDUMP010I JIT dump written to /home/jenkins/workspace/Test_openjdk8_j9_sanity.openjdk_ppc64le_linux_Personal/openjdk-tests/TKG/test_output_1585082508650/jdk_util_0/work/scratch/1/jitdump.20200324.170638.1269.0004.dmp
17:06:44 [2020-03-24 17:06:43,994] Agent[1]: stderr: JVMDUMP013I Processed dump event "gpf", detail "".
17:06:44 --------------------------------------------------
17:06:44 TEST: java/util/jar/JarFile/ScanSignedJar.java
17:06:44 TEST JDK: /home/jenkins/workspace/Test_openjdk8_j9_sanity.openjdk_ppc64le_linux_Personal/openjdkbinary/j2sdk-image
As you know Compilation Threads don't stop while GC takes Exclusive VM Access (known as Stop-The-World). However there are some limitations related with Class Unloading apply (controlled using Mutex). Is this table walkable at any moment of time? Is it possible this function got garbage if this table (for example) under modification?
dmitripivkine
on 25 Mar 2020
Got one on zlinux https://ci.eclipse.org/openj9/job/Grinder/719
java/nio/charset/coders/BashStreams.java.BashStreams
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: Unhandled exception
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: Type=Segmentation error vmState=0x00020011
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: J9Generic_Signal_Number=00000018 Signal_Number=0000000b Error_Value=00808ab8 Signal_Code=00000001
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: Handler1=000003FF898BBE30 Handler2=000003FF896A0DA8 InaccessibleAddress=FFFFFFFFFFFFF000
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: gpr0=0000000000000000 gpr1=0000000000000000 gpr2=FFFFFFFFFFFFFF40 gpr3=000003FF84089028
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: gpr4=0000000000000000 gpr5=0000000003E42700 gpr6=0005A1D73EDB1C67 gpr7=0000000000000028
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: gpr8=000003FF84089028 gpr9=000003FF882744E0 gpr10=000003FF88274420 gpr11=000003FF6B397AA0
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: gpr12=0000000000001FFD gpr13=0000000000000000 gpr14=000003FF833FD116 gpr15=000003FF88B7CD50
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: psw=000003FF833E89C0 mask=0705100180000000 fpc=00080000 bea=000003FF833E89EA
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: fpr0 000003ff842f24b8 (f: 2217682176.000000, d: 2.171897e-311)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: fpr1 3eccccd100000000 (f: 0.000000, d: 3.433235e-06)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: fpr2 000003ff00000000 (f: 0.000000, d: 2.170802e-311)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: fpr3 3e638e2e00000000 (f: 0.000000, d: 3.642475e-08)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: fpr4 402e000000000000 (f: 0.000000, d: 1.500000e+01)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: fpr5 4190000047ae147b (f: 1202590848.000000, d: 6.710888e+07)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: fpr6 bcdc87f800000000 (f: 0.000000, d: -1.583796e-15)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: fpr7 3f2aaaae00000000 (f: 0.000000, d: 2.034509e-04)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: fpr8 0000000000040000 (f: 262144.000000, d: 1.295163e-318)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: fpr9 000003ff84235008 (f: 2216906752.000000, d: 2.171897e-311)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: fpr10 000003ff88b40000 (f: 2293497856.000000, d: 2.171935e-311)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: fpr11 000000000047c280 (f: 4702848.000000, d: 2.323516e-317)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: fpr12 0000000003c1ce58 (f: 63032920.000000, d: 3.114240e-316)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: fpr13 000000000047c268 (f: 4702824.000000, d: 2.323504e-317)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: fpr14 000000000000002a (f: 42.000000, d: 2.075076e-322)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: fpr15 000000000047c270 (f: 4702832.000000, d: 2.323508e-317)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: Module=/home/jenkins/workspace/Grinder/openjdkbinary/j2sdk-image/lib/compressedrefs/libj9jit29.so
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: Module_base_address=000003FF83280000
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: Target=2_90_20200326_340 (Linux 4.4.0-170-generic)
10:52:22 [2020-03-27 14:52:08,141] Agent[3]: stderr: CPU=s390x (4 logical CPUs) (0x1f723a000 RAM)
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: ----------- Stack Backtrace -----------
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF833E89C0 [libj9jit29.so+0x1689c0])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF833FD116 [libj9jit29.so+0x17d116])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF89701590 [libj9hookable29.so+0x1590])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF898CF326 [libj9vm29.so+0xcf326])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF88987F3A [libj9gc29.so+0x207f3a])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF88908ED0 [libj9gc29.so+0x188ed0])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF8890909E [libj9gc29.so+0x18909e])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF88917662 [libj9gc29.so+0x197662])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF88963F0A [libj9gc29.so+0x1e3f0a])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF888C6AA6 [libj9gc29.so+0x146aa6])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF88969C0E [libj9gc29.so+0x1e9c0e])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF8896BE86 [libj9gc29.so+0x1ebe86])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF8896C3BA [libj9gc29.so+0x1ec3ba])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF888DDC44 [libj9gc29.so+0x15dc44])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF8891130A [libj9gc29.so+0x19130a])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF887CE032 [libj9gc29.so+0x4e032])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF83CBC17A [libj9jit29.so+0xa3c17a])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: (0x000003FF83CD2648 [libj9jit29.so+0xa52648])
10:52:22 [2020-03-27 14:52:08,142] Agent[3]: stderr: ---------------------------------------
https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_sanity.openjdk_s390x_linux_Nightly/13
java/nio/channels/SocketChannel/ShortWrite.java.ShortWrite
pshipton
on 28 Mar 2020
We're past Milestone 2 for the 0.20.0 release, moving this forward to the next release.
pshipton
on 30 Mar 2020
First of all let's list all the different places this failure can occur:
java/nio/charset/coders/BashStreams.java
java/nio/channels/FileChannel/TransferToChannel.java
java/nio/file/WatchService/LotsOfEvents.java
java/util/jar/JarFile/ScanSignedJar.java
java/nio/channels/SocketChannel/ShortWrite.java.ShortWrite
Firstly, the failure looks to be identical in each one of these cases. I've tried running these tests explicitly, without any luck reproducing the failure in the individual tests. However because the nio test suites runs many of these tests sequentially, I've been able to get the nio test suite to fail in about 1/20 iterations in one of the above listed test cases.
Specifically, let's take a look at the exact failure in this issue.
Looking into the assembly:
0x3fff7086fc34 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +10 f8ffa33b addi r29, r3, -8. —> r29 = 8 bytes above than *this loader.
0x3fff7086fc38 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +11 f0ffc1fb std r30, -0x10(r1)
0x3fff7086fc3c {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +12 78239e7c mr r30, r4
0x3fff7086fc40 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +13 100001f8 std r0, 0x10(r1)
0x3fff7086fc44 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +14 f8ffe1fb std r31, -8(r1)
0x3fff7086fc48 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +15 b1ff21f8 stdu r1, -0x50(r1)
0x3fff7086fc4c {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +16 > 0900fdeb ldu r31, 8(r29) <<< ^+50. —> r31 = Points to first element (spine)
0x3fff7086fc50 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +17 | 0000bf2f cmpdi cr7, r31, 0
0x3fff7086fc54 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +18 |* 7c009e41 beq cr7, 0x3fff7086fcd0 C>> +49
0x3fff7086fc58 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +19 || 00004039 li r10, 0
0x3fff7086fc5c {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +20 ||* 2c000048 b 0x3fff7086fc88 U>> +31
|||
0x3fff7086fc60 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +21 |||> 080029e9 ld r9, 8(r9) <<< ^+34. R9 = Constant pool
0x3fff7086fc64 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +22 |||| e4062979 rldicr r9, r9, 0, 0x3b
0x3fff7086fc68 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +23 |||| 000029e9 ld r9, 0(r9). <— Crash here
0x3fff7086fc6c {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +24 280029e9 ld r9, 0x28(r9).
0x3fff7086fc70 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +25 00f0a97f cmpd cr7, r9, r30
0x3fff7086fc74 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +26 * 24009e41 beq cr7, 0x3fff7086fc98 C>> +35
0x3fff7086fc78 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +27 | 78fbea7f mr r10, r31
0x3fff7086fc7c {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +28 | 0000ffeb ld r31, 0(r31)
0x3fff7086fc80 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +29 | 0000bf2f cmpdi cr7, r31, 0
0x3fff7086fc84 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +30 |* 4c009e41 beq cr7, 0x3fff7086fcd0 C>> +49
0x3fff7086fc88 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +31 ||> 08003fe9 ld r9, 8(r31) <<< +20 ^+48. —> r9 = entry->j9_method
0x3fff7086fc8c {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +32 ||| 0000aa2e cmpdi cr5, r10, 0
0x3fff7086fc90 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +33 ||| 0000a92f cmpdi cr7, r9, 0
0x3fff7086fc94 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} +34 ||| ccff9e40 bne cr7, 0x3fff7086fc60 C>> ^+21. <——
As Dmitri has pointed out, It became obvious that the seg fault happens at:
if (NULL == entry->_j9method
|| J9_CLASS_FROM_METHOD(entry->_j9method)->classLoader == j9classLoader)
Specifically the segfault happens while fetching:
J9_CLASS_FROM_METHOD(entry->_j9method)->classLoader
Expanding this further, we can see that it's trying to obtain the j9class using the constant pool address.
#define J9_CLASS_FROM_METHOD(method) J9_CLASS_FROM_CP(J9_CP_FROM_METHOD(method))
As we're iterating through the j9method entries in the HT, the entry that we see the segfault looks to be a valid j9method, however the constant pool address is invalid. The expected constant pool address within the j9method was actually just 0x0...01 in this case.
AlenBadel
on 14 Apr 2020
Taking a closer look the j9method we're referencing seems to have been deleted. Everything looks to be invalid, not just the constant pool address.
Running an experiment to verify if the HT was invalid upon classunloading verified that it was corrupted somewhere prior to entering the classunloading routine.
void J9Method_HT::validateHT()
{
for (size_t bucketID = 0; bucketID < HT_SIZE; bucketID++)
{
HT_Entry *entry = _spine[bucketID];
HT_Entry *prev = NULL;
for (; entry; prev = entry, entry = entry->_next)
{
if (NULL == entry->_j9method
|| NULL != J9_CLASS_FROM_METHOD(entry->_j9method)->classLoader)
{
// Debug: Should segfault here if CP address is invalid.
printf("Found valid match\n");
}
}
}
}
The addNewEntry method should also segfault if the j9method being inserted was also invalid upon entry. So, we can assume that the entry was valid upon entry.
To double check, I also added a check to only add the entry if it has a valid classloader. To obtain that classloader the j9method being inserted would need to have a valid constantpool address, otherwise that check would segfault itself. This wasn't a successful experiment since I wasn't able to reproduce the failure after adding this check, it might've changed timing.
Next Steps:
It looks like something deleted the j9method that we're trying to reference before it was removed from the HT.
Next steps include investigating:
-> The classunloading routine within the HT was never called, due to some missed path.
-> An invalid j9classloader was passed into the classunloading routine and the entry was never removed. I'll be trying to narrow down if we ever call the classunloading routine without removing anything.
AlenBadel
on 14 Apr 2020
Adding an assert if unloadClasses does not remove an entry has not triggered. Also, enabling sampling verbose options does not cause this to failure to be triggered. I suspect this is some sort of synchronization issue. Unless an experiment causes the failure, or triggers some sort of assert the experiment cannot be reliable.
What we've verified:
-> The J9Method_HT Entry was invalid prior to entering unloadClasses.
Assumptions:
-> unloadClasses can not happen at the same time as addNewEntry, since unloadClasses occurs ONLY during STW.
-> The Entry being loaded, during addNewEntry is always a valid j9method.
AlenBadel
on 15 Apr 2020
->
unloadClassescan not happen at the same time asaddNewEntry, sinceunloadClassesoccurs ONLY during STW.
Global GC STW does not stop compilation threads really but triggers J9HOOK_MM_INTERRUPT_COMPILATION and takes _javaVM->classUnloadMutex - see https://github.com/eclipse/openj9/blob/d493108cc5cc229002810c55b0ac86df1ca1fbc2/runtime/gc_base/ClassLoaderManager.cpp#L645
dmitripivkine
on 15 Apr 2020
In the whole stack it doesn't look like we ever call enterClassUnloadMutex.
It's only ever called during:
MM_IncrementalGenerationalGC::unloadDeadClassLoaders(MM_EnvironmentVLHGC *env)
MM_GlobalCollectorDelegate::masterThreadGarbageCollectStarted(MM_EnvironmentBase *env)
I suspect then it's missing that mutex.
Added the obtaining and releaseing that mutex before and after classloading to see if that makes a difference.
/* Take UnloadMutex */
U_64 quiesceTime = _extensions->classLoaderManager->enterClassUnloadMutex(env);
classUnloadStats->_classUnloadMutexQuiesceTime = quiesceTime;
/* Release UnloadMutex Back */
_extensions->classLoaderManager->exitClassUnloadMutex(env);
md5-ab7cf519e87e7a30e7b92d7ce6d623b2
0x00003fff7086fc68 {libj9jit29.so}{_ZN11J9Method_HT16onClassUnloadingEP13J9ClassLoader} [0x3fff7cacc010]
0x00003fff708874a0 {libj9jit29.so}{jitHookAnonClassesUnload} [0x3fff7cacc060]
0x00003fff77fd1840 {libj9hookable29.so}{J9HookDispatch} [0x3fff7cacc1e0]
0x00003fff7065b114 {libj9gc29.so}{_ZN21MM_ClassLoaderManager24cleanUpClassLoadersStartEP18MM_EnvironmentBaseP13J9ClassLoaderP10MM_HeapMapP19MM_ClassUnloadStats} [0x3fff7cacc2e0]
0x00003fff705cf1c8 {libj9gc29.so}{_ZN26MM_GlobalCollectorDelegate22unloadDeadClassLoadersEP18MM_EnvironmentBase} [0x3fff7cacc3e0]
0x00003fff705cf448 {libj9gc29.so}{_ZN26MM_GlobalCollectorDelegate18postMarkProcessingEP18MM_EnvironmentBase} [0x3fff7cacc490]
0x00003fff705df22c {libj9gc29.so}{_ZN19MM_ParallelGlobalGC26masterThreadGarbageCollectEP18MM_EnvironmentBaseP22MM_AllocateDescriptionbb} [0x3fff7cacc570]
0x00003fff70639fcc {libj9gc29.so}{_ZN15MM_ConcurrentGC22internalGarbageCollectEP18MM_EnvironmentBaseP17MM_MemorySubSpaceP22MM_AllocateDescription} [0x3fff7cacc630]
0x00003fff7058b50c {libj9gc29.so}{_ZN12MM_Collector14garbageCollectEP18MM_EnvironmentBaseP17MM_MemorySubSpaceP22MM_AllocateDescriptionjP28MM_ObjectAllocationInterfaceS3_P20MM_AllocationContext} [0x3fff7cacc660]
0x00003fff7067c5cc {libj9gc29.so}{_ZN29MM_MemorySubSpaceGenerational23allocationRequestFailedEP18MM_EnvironmentBaseP22MM_AllocateDescriptionN17MM_MemorySubSpace14AllocationTypeEP28MM_ObjectAllocationInterfacePS4_S8_} [0x3fff7cacc710]
0x00003fff7068acc4 {libj9gc29.so}{_ZN21MM_MemorySubSpaceFlat23allocationRequestFailedEP18MM_EnvironmentBaseP22MM_AllocateDescriptionN17MM_MemorySubSpace14AllocationTypeEP28MM_ObjectAllocationInterfacePS4_S8_} [0x3fff7cacc7f0]
0x00003fff7069172c {libj9gc29.so}{_ZN24MM_MemorySubSpaceGeneric14allocateObjectEP18MM_EnvironmentBaseP22MM_AllocateDescriptionP17MM_MemorySubSpaceS5_b} [0x3fff7cacc8d0]
0x00003fff705b3280 {libj9gc29.so}{_ZN25MM_TLHAllocationInterface14allocateObjectEP18MM_EnvironmentBaseP22MM_AllocateDescriptionP14MM_MemorySpaceb} [0x3fff7cacc9c0]
0x00003fff705d76f0 {libj9gc29.so}{_Z21OMR_GC_AllocateObjectP12OMR_VMThreadP25MM_AllocateInitialization} [0x3fff7cacca60]
0x00003fff70459c7c {libj9gc29.so}{J9AllocateObject} [0x3fff7caccb10]
0x00003fff7c0ec000 {libj9vm29.so}{internalCreateRAMClassFromROMClassImpl} [0x3fff7caccf20]
0x00003fff7c0ef6f8 {libj9vm29.so}{internalCreateRAMClassFromROMClass} [0x3fff7cacd640]
0x00003fff7c17dd1c {libj9vm29.so}{internalDefineClass} [0x3fff7cacd7f0]
0x00003fff6ffc6cfc {libjclse29.so}{defineClassCommon} [0x3fff7cacd980]
In the whole stack it doesn't look like we ever call
enterClassUnloadMutex
This function is called once at the beginning of Global GC. Why do you expect to see it in the current c-stack?!
dmitripivkine
on 16 Apr 2020
In the whole stack it doesn't look like we ever call
enterClassUnloadMutexThis function is called once at the beginning of Global GC. Why do you expect to see it in the current c-stack?!
The correct check would be: because GC enters monitor in RW mode you can see owning thread is stored in monitor. And this thread should be mutator thread initiated GC (and became GC Master Thread for this GC). This thread owns VM Exclusive access (0x20 in public flags). For example:
> !findvm
!j9javavm 0x00000100100D68B0
> !j9javavm 0x00000100100D68B0 | grep classUnloadMutex
0x4a98: struct RWMutex* classUnloadMutex = !rwmutex 0x000001001001B9B8
> !rwmutex 0x000001001001B9B8
RWMutex at 0x1001001b9b8 {
Fields for RWMutex:
0x0: struct J9ThreadMonitor* syncMon = !j9threadmonitor 0x0000010010066710
0x8: I64 status = 0xFFFFFFFFFFFFFFFF (-1)
0x10: struct J9Thread* writer = !j9thread 0x0000010022DCFFD0
}
> !threads | grep -i 10022DCFFD0
!stack 0x305c6f00 !j9vmthread 0x305c6f00 !j9thread 0x10022dcffd0 tid 0x58900df (92864735) // (AgentVMThread)
> !threads flags | grep -i 0x305c6f00
!j9vmthread 0x305c6f00 publicFlags=1020 privateFlags=100000 inNative=0 // AgentVMThread
This function is called once at the beginning of Global GC. Why do you expect to see it in the current c-stack?!
I was looking at the code executed prior to the crash. In some instances, such as the path that involves MM_IncrementalGenerationalGC::unloadDeadClassLoaders(MM_EnvironmentVLHGC *env) the GC reserves the mutex much later on, and closer to calling the hook.
I can see in your subsequent comment that the GC thread owns VM exclusive access during the event, so I suspect this was reserved much earlier on in the path.
AlenBadel
on 28 Apr 2020
This issue is fairly difficult to reproduce while enabling tracing. I've tried enabling either TR_VerboseSampling, or TR_VerboseHookDetailsClassUnloading causes the issue to disappear even with aggressive iterations.
Andrew mentioned that the issue could be due the class being unloaded before the classloader. We do have two such paths that unload classes without removing any owned methods from the MethodHT(jitHookClassUnload & jitHookClassesUnload).
As a related experiment, I attempted to print the classes being unloaded, and the contents of the Method HT. To effectively paint a picture if any method is still in the HT that belonged to an class that was previously unloaded. I tried variations of both of JIT, and VM class signature tracing mechanisms without any luck reproducing the issue when enabled.
Next steps would be to implement cleanup of the MethodHT in the two Hooks above where the class is separately unloaded from it's class-loader. Hope to have the results shortly.
AlenBadel
on 29 Apr 2020
@andrewcraik Similarly to MethodHT, the DLT Record table is also not being updated when classes are unloaded. I suspect then we need to clean up both tables since the method is tracked both in DLTTracking(J9Method_HT), and DLT_record.
AlenBadel
on 29 Apr 2020
A Summary of what I've picked up
As we've established, the failure occurs because we have an entry in the J9Method_HT, that carries a reference to a J9Method object that has been corrupted in some way. Below is what the J9Method reference points to at the point of the crash.
The crash happens here.
https://github.com/eclipse/openj9/blob/27e93e6cae493f2a3945528330adf5faacec3e4b/runtime/compiler/control/CompilationThread.cpp#L12597
https://github.com/eclipse/openj9/blob/27e93e6cae493f2a3945528330adf5faacec3e4b/runtime/compiler/control/CompilationThread.cpp#L12608
Method {ClassPath/Name.MethodName}: {???.???}
Signature: (null)
Access:
J9Class/J9Method: 0x0000000000000000 / 0x00000000002c9c68 .
Compiled Method Start: Not Compiled! (count=0)
ByteCode Start: 0x0000000000000001 (-1 bytes)
ROM Constant Pool: 0x0000000000000000 (0 entries)
Constant Pool: 0x0000000000000000 (0 entries)
J9Method_HT
This is a part of the DLT Optimization. The Dynamic Loop Transformation attempts to identify a selection of methods to be optimized.
Keeping in mind the structure of DLTTracking
https://github.com/eclipse/openj9/blob/27e93e6cae493f2a3945528330adf5faacec3e4b/runtime/compiler/control/CompilationRuntime.hpp#L316-L329
https://github.com/eclipse/openj9/blob/27e93e6cae493f2a3945528330adf5faacec3e4b/runtime/compiler/control/CompilationThread.cpp#L12653
https://github.com/eclipse/openj9/blob/27e93e6cae493f2a3945528330adf5faacec3e4b/runtime/compiler/control/CompilationThread.cpp#L12712
Any method added to the table has been requested a DLT. Any method that has been DLT compiled also has a DLTRecord added to the DLTRecord Table.
As an important note, the DLTRecord clean up can also suffer from the same issue. It's quite odd that we didn't crash during the clean-up of the DLTRecord table since that is done first. These two tables only have records removed during class unloading, and the fact that we didn't crash in the DLTRecord clean up routine means that the method most likely was not DLT compiled.
https://github.com/eclipse/openj9/blob/27e93e6cae493f2a3945528330adf5faacec3e4b/runtime/compiler/control/HookedByTheJit.cpp#L2001-L2005
https://github.com/eclipse/openj9/blob/27e93e6cae493f2a3945528330adf5faacec3e4b/runtime/compiler/control/CompilationThread.cpp#L3020
Class/Loader Unloading
As we know, this issue occurs during class unloading. Specifically when the GC invokes the jitHookAnonClassesUnload, and jitHookClassLoaderUnload, since this is where the JIT does the cleaning up of the J9Method_HT table.
GC Classloader unloading invokes the hooks.
https://github.com/eclipse/openj9/blob/64ec0ba89116cf222135206decd82e66b05c6a4a/runtime/gc_glue_java/GlobalCollectorDelegate.cpp#L458
Sequence of these hooks by the GC.
Respective Hooks handled by JIT:
https://github.com/eclipse/openj9/blob/27e93e6cae493f2a3945528330adf5faacec3e4b/runtime/compiler/control/HookedByTheJit.cpp#L6557-L6560
Given this sequence of hooks, it becomes unlikely that classes are unloaded before the classloader. We've conducted a small experiment to clean up the table during class unloading. That did cause the issue to disappear, however as we've expressed the lightest of changes causes this issue to disappear. I believe all this is doing is changing timing.
https://github.com/AlenBadel/openj9/commit/27e93e6cae493f2a3945528330adf5faacec3e4b
AlenBadel
on 1 May 2020
Most likely the J9Class that the J9Method belongs to was valid at some point, and since has been freed at some point. Meanwhile the entry was not removed from the table.
Unless proven, there is no guarantee that during the execution of each of these GC hooks that the the class, or it's methods will be alive until class unloading, where currently the tables are being cleaned up. Hence, the proposed solution of cleaning up the table after each class unloading hook is still valid.
@dmitripivkine Do you have any objections to this theory?
AlenBadel
on 5 May 2020
Most likely the J9Class that the J9Method belongs to was valid at some point, and since has been freed at some point. Meanwhile the entry was not removed from the table.
Unless proven, there is no guarantee that during the execution of each of these GC hooks that the the class, or it's methods will be alive until class unloading, where currently the tables are being cleaned up. Hence, the proposed solution of cleaning up the table after each class unloading hook is still valid.
@dmitripivkine Do you have any objections to this theory?
Sorry, I do not follow. Please explain
dmitripivkine
on 5 May 2020
Currently, there are four VM hooks that are used for class unloading, these hooks are invoked by the GC. (See https://github.com/eclipse/openj9/issues/8652#issuecomment-622437805).
The J9Method table, as well as the DLTRecordTable are only cleaned during the classloader unloading, and anonclasses unloading phases. These tables are not cleaned upon class unloading, or classes unloading.
The JIT should remove all entries inside DLTRecord, and J9MethodHT at the end of all four of the specified hooks rather than waiting for classloader unloading. This is done because there is not a guarantee that the unloaded class(es) and their respective methods will still be alive by the time that the classloader is unloaded.
AlenBadel
on 5 May 2020
This is done because there is not a guarantee that the unloaded class(es) and their respective methods will still be alive by the time that the classloader is unloaded.
I do not understand what "not alive class" means.
When GC discovered that non of classes from classloader have instances in object heap the decision of unloading this classloader is taken.
GC walks all classes of this classloader and for each one
- set "unloaded" flag to j9class
- replace pointer to class object to -1
- remove class from active classes list (and re-assign
previousandnextto itself) - issue a hook "class unloading"
When this loop is complete GC calls cleanUpClassLoader() and first thing this function triggers "classloader unload" hook.
All operation above done under VM Exclusive Access and _javaVM->classUnloadMutex entered for write.
I understand that Compilation threads are still running while VM Exclusive Access is taken by GC as well as I would not pretend I understand how JIT maintain tables but your explanation does not convince me.
dmitripivkine
on 5 May 2020
I do not understand what "not alive class" means.
As the class unloading hook is called, the JIT currently doesn't clean up the table entries whose methods belong to the unloaded class.
The JIT waits until the GC issues the class loader unload hook to do any clean up.
Both the entries of J9Method_HT, as well as the DLTRecordTable contains references to J9Methods that are either candidates to be DLT compiled, or DLT compiled methods respectively.
Therefore the clean up process entails, iterating through all entries in the table. Dereferncing the j9method reference stored within the entry, and using it to obtain the J9Class. We compare the classloader and remove the entry if it corresponds to the classloader we're unloading.
The concern is that if there's a guarantee that the Class, or respective Methods are still accessible after the class unloading, and during classloader unloading. Ultimately, we're trying to dereference something that has been deleted somewhere after the class unload hook is called, and when the class unloader hook is answered.
The idea is that the clean-up should be done during class unloading, rather waiting for class unloading where the objects may not be alive by then.
AlenBadel
on 5 May 2020
The concern is that if there's a guarantee that the Class, or respective Methods are still accessible after the class unloading, and during classloader unloading. Ultimately, we're trying to dereference something that has been deleted somewhere after the class unload hook is called, and when the class unloader hook is answered.
The idea is that the clean-up should be done during class unloading, rather waiting for class unloading where the objects may not be alive by then.
This sounds as fundamental problem missing respect for _javaVM->classUnloadMutex when tables are modified. There should not be any logical difference which hook handler serves this. If there is a difference so there is a race between hook handler and table modification (which is wrong to fix by switching from one hook to another because of just reducing time window for race condition).
An alternate possibility it is collision between "class unload" and "classloader unload" hook handlers itself. If this a case hook handlers should be fixed.
dmitripivkine
on 5 May 2020
We could have many theories why this is happening, or perhaps do we have a proper expectation to keep these objects alive after the class unloading hook is serviced.
is wrong to fix by switching from one hook to another because of just reducing time window for race condition
The proposed solution is that unless we have an explicit expectation, the JIT needs to clean up the table entries during the respective hooks.
https://github.com/AlenBadel/openj9/commit/27e93e6cae493f2a3945528330adf5faacec3e4b
AlenBadel
on 5 May 2020
We could have many theories why this is happening, or perhaps do we have a proper expectation to keep these objects alive after the class unloading hook is serviced.
is wrong to fix by switching from one hook to another because of just reducing time window for race condition
The proposed solution is that unless we have an explicit expectation, the JIT needs to clean up the table entries during the respective hooks.
AlenBadel@27e93e6
I would like to see detailed explanation of mechanism how this problem occur as well of how proposed change help to fix the problem.
dmitripivkine
on 5 May 2020
@dmitripivkine maybe it's a very basic question but we would like to get the following out of the way first:
Our current assumption (why the segm fault happens) is that at the time when Class Loader unloading JIT hook is called, J9Method of some class (not necessarily belonging to that Class Loader) was already freed (and possibly corrupted by somebody reusing its memory). To confirm that assumption we need to know:
1) Is the following true: J9Method's memory can be freed iff its class is unloaded ?
2) Is the following true: class can be unloaded without its Class Loader being unloaded or, more precisely, before Class Loader unloading JIT hook is called for its class loader?
Note that we currently remove all the references to J9Method on corresponding Class Loader unloading but no on its Class unloading.
gita-omr
on 5 May 2020
Please note that all the questions above are from GC prospective, eg. seen by GC and not by some other thread.
gita-omr
on 5 May 2020
Just wanted to put it out there that there is an assumption that compilation threads would not be running during STW.
https://github.com/eclipse/openj9/blob/2a27ccf888c7f58edb5c3bd96bc0f29d0a103b31/runtime/compiler/control/CompilationThread.cpp#L12601-L12603
The failure that we're seeing could occur if the mutex is not being used properly. There is a possibility in this case that we could be removing an object from the HT while another thread is adding an entry. Hence we could be removing a entry other than the one we were intending. Leaving the intended entry in the HT as it's j9method reference becomes invalid.
AlenBadel
on 5 May 2020
Could we get rid of the mutex? How much perf would it cost to flush the compilation queue and any active compilations on class unload (marking anything queued for immediate compilation on the next invocation)?
gacholio
on 6 May 2020
@dmitripivkine maybe it's a very basic question but we would like to get the following out of the way first:
Our current assumption is that at the time when Class Loader unloading JIT hook is called, J9Method of some class (not necessarily belonging to that Class Loader) was already freed (and possibly corrupted by somebody reusing its memory). We need to know:
- Is the following true: J9Method's memory can be freed iff its class is unloaded ?
- Is the following true: class can be unloaded without its Class Loader being unloaded or, more precisely, before Class Loader unloading JIT hook is called for its class loader?
Note that we currently remove all the references to J9Method on corresponding Class Loader unloading but no on its Class unloading.
@gita-omr
There is a number of fundamental facts about classes:
- j9class or any it's part must be valid if class is a member of active (not unloaded) Classloader (with exception of partially initialized classes at class loading time)
- GC unloads classes single threaded (at least at the moment) under VM Exclusive Access and mutex
_javaVM->classUnloadMutexacquired for Write (exclusively) - GC unloading classes on Classloader basis. It means that class can be unloaded if it or any other class in this Classloader have no instances (objects) in the heap
- If GC makes a decision to unload Classloader(s) it is done in three phases:
1) GC walks all RAM (j9class) classes and do preparation to it's unloading for each one:
* set "unloaded" flag to j9class
* replace pointer to class object to -1
* remove class from active classes list (and re-assign "previous" and "next" to itself)
* issues a hook "class unloading" about each class about to be unloaded
At the end of the walk issues "classes unloaded" summary hook with list of classes about to be unloaded
2) Classloader unloading logical changes. At the very beginning of this phase "classloader unloading" hook is issued. From the point of correctness it is not safe to use any data related with this classloader after exiting from this hook handler.
3) Walk through Classloader structures and release unnecessary native memory
All above is correct with an exception for Anonymous classes which:
- always owned be special Anonymous Classloader (but class parent Classloader might be different)
- Anonymous Classloader can not be unloaded
- can be unloaded on individual basis
- special hook "anonymous classes unloaded" is issued at phase 1 end with attached list of anonymous classes about to be unloaded
So answers on your questions if I understand them correctly:
- Is the following true: J9Method's memory can be freed iff its class is unloaded ?
Any memory reachable from Classloader would not be freed until "classloader unloaded" hook is exited
- Is the following true: class can be unloaded without its Class Loader being unloaded or, more precisely, before Class Loader unloading JIT hook is called for its class loader?
No. Class and Classloader always unloaded together (with exception of Anonymous Class but it's Classloader is never unloaded, so it is out of context of your question)
Now, if you believe that some action is not correct for "classloader unloaded" hook but it is for "classes unloaded" your code has fundamental problem. Either it does not respect mutex (but must) and code with missed mutex check interfere with hook handler or handlers of different hooks interfere each other. I afraid that modifying code without understanding of the problem source can make situation worse. For example change time window for possible race to make it much harder to reproduce.
There are two notes @andrewcraik:
- Just friendly reminder that "classes unloading" and "anonymous classes unloading" hooks passed list of classes to be unloaded attached to the hook as parameter ("classes" list included "anonymous classes" as well). I should admit passing of the list use to be broken but I fixed it about eight years ago. I believe using of this list is more effective then iterate all classes in the system and look for "unloaded" flag.
- There is known performance issue related with handling of class unloading related hooks in JIT (particular that one walks tables for each element and create N**2 behaviour). I would be very accurate with table walks in hooks handlers
Could we get rid of the mutex? How much perf would it cost to flush the compilation queue and any active compilations on class unload (marking anything queued for immediate compilation on the next invocation)?
@gacholio I would love to! I believe we have more problems with fake Exclusive then benefits from it. Well it is not my call obviously
dmitripivkine
on 6 May 2020
@dmitripivkine thanks for the excellent response! This is exactly the reason we wanted to check with you first, before applying a fix.
So let's consider our next assumption: https://github.com/eclipse/openj9/issues/8652#issuecomment-624327598
But from what I understand, compilation thread is blocked during class unloading. Why do we think it's not?
gita-omr
on 6 May 2020
Just wanted to put it out there that there is an assumption that compilation threads would not be running during STW.
That's not true; the compilation threads can still run during a STW phase; it will only block if it needs to acquire VM Access and some other thread holds exclusive VM Access. It's at this point that the JIT releases the class unload mutex; if class unloading then happens, it will abort the current compilation. Class unloading will also cause all compilation requests of unloaded classes to be removed from the queue.
Could we get rid of the mutex?
I'm assuming you mean the class unload mutex right? I believe the history behind that mutex is that the JIT used to acquire VMAccess for the entirety of the compilation. However this meant that no GC could happen during a compilation. The reason the JIT acquired VMAccess is because it needs to know that the class hierarchy did not change during a compilation. The class unload mutex is a compromise to allow GC to occur but also prevent class unloading during a compilation.
How much perf would it cost to flush the compilation queue
I don't know about perf, but I don't think the JIT would be functionally correct if class unloading happened during the compilation. The reason is because the JIT can hold on to various J9Class & J9Method pointers in various structures. Purging the queue requires setting the flag to interrupt the compilation, which is only checked by the comp thread at specific points. If those J9Class/J9Method pointers were to stop being valid before we reached that check point, we could do an invalid access and seg fault.
We also can't just create a JNI ref for the class of the method being compiled, because when inlining or peeking or looking at statics or anything like that, the JIT would need to create JNI refs for every single class it wants to look at, which could be a massive set.
dsouzai
on 6 May 2020
Just friendly reminder that "classes unloading" and "anonymous classes unloading" hooks passed list of classes to be unloaded attached to the hook as parameter ("classes" list included "anonymous classes" as well). I should admit passing of the list use to be broken but I fixed it about eight years ago. I believe using of this list is more effective then iterate all classes in the system and look for "unloaded" flag.
It is on the list of things to look at
There is known performance issue related with handling of class unloading related hooks in JIT (particular that one walks tables for each element and create N**2 behaviour). I would be very accurate with table walks in hooks handlers
If you are referring to the runtime assumption table this N**2 behavior has been fixed. The work is amortized and is now linear on average.
andrewcraik
on 6 May 2020
@dmitripivkine in regards to:
An alternate possibility it is collision between "class unload" and "classloader unload" hook handlers itself. If this a case hook handlers should be fixed.
The issue here is not the tables being corrupted - the j9method pointer is pointing to unaccessible memory (the table is intact) - that pointer is not modified as part of clean-up so unless there is some kind of double free issue happening the issue is the pointer is stale and the clean-up was not done correctly. The fundamentally weird thing we are doing is derefing the j9method pointer to get to the classloader to see if we need to clean up the entry
I do not think this is a race between hooks - this clean up is currently in one place. The issue seems to be the j9method* is not valid. If that memory CANNOT be deallocated before the code runs to unload the unloader then quite how the j9method went stale is a mystery. Could someone suggest some hooks to trace j9methods so we can see what that address was allocated to and when it was freed by the VM? That way we can try to reconcile what the JIT is seeing with what the VM is seeing.
andrewcraik
on 6 May 2020
At a glance, the hooks are definitely invoked before any memory segments are freed, but the GC team will need to confirm this is always true.
gacholio
on 6 May 2020
At a glance, the hooks are definitely invoked before any memory segments are freed, but the GC team will need to confirm this is always true.
As I stated before non of memory accessible from j9class/j9classloader is released before hooks are triggered. I also double check that any subscriber of "class unloading" and "classes unloading" hooks don't do this.
dmitripivkine
on 6 May 2020
The mystery deepens - @gacholio is there a way for us to get a log of the memory addresses of j9methods in a JVM run? I'm trying to think if we can verify if the pointer was ever valid or not...
andrewcraik
on 6 May 2020
The tracepoint here may be of use:
https://github.com/eclipse/openj9/blob/fcb6d3f438eedd4c13116b4a04e13b246162070f/runtime/vm/createramclass.cpp#L2557-L2558
gacholio
on 6 May 2020
I guess may be it is does not matter what triggered table walk (hook for class unloading) but just asynchronous nature of event? Is it possible table just not walkable some short periods of time (like list under modification for example). In this case triggering event content might be irrelevant
dmitripivkine
on 6 May 2020
If it helps, here's some more dumps from last night's https://ci.adoptopenjdk.net/view/Test_openjdk/job/Test_openjdk8_j9_sanity.openjdk_ppc64le_linux/194/console run
https://ibm.box.com/shared/static/ttcnd9cp0y1wvp0n8snoiydymdlgo4oh.gz
M-Davies
on 7 May 2020
As an experiment I've added a post-removal verification routine which runs after onClassUnloading. It is to assert if it finds an entry with the same unloaded classloader, which was to be removed during the onClassUnloading routine.
https://github.com/AlenBadel/openj9/commit/2ee9e7aca4aa4bb85501a3f6d59e695a98a118ad
The result was that we've hit the assert. Which means most likely we're experiencing a race condition. Perhaps again this is the most likely scenario.
There is a possibility in this case that we could be removing an object from the HT while another thread is adding an entry. Hence we could be removing a entry other than the one we were intending. Leaving the intended entry in the HT as it's j9method reference becomes invalid.
I'm trying to get a core file which has more than one thread's context. I suspect that the compilation threads are somewhere executing DLT related logic. I've tried -Xrs but that has prevented the failure from occurring.
AlenBadel
on 7 May 2020
Looking at the java core looks like the mutex is unowned.
2LKREGMON JIT/GC class unload mutex lock (0x00003FFFB0006108): <unowned>
To Note where the mutex is reserved:
MM_GlobalCollectorDelegate::masterThreadGarbageCollectStarted(MM_EnvironmentBase *env)
https://github.com/eclipse/openj9/blob/64ec0ba89116cf222135206decd82e66b05c6a4a/runtime/gc_glue_java/GlobalCollectorDelegate.cpp#L172-L176
This occurs right before the postMarkProcessing, which calls the unloading hooks.
MM_ParallelGlobalGC::masterThreadGarbageCollect(MM_EnvironmentBase *env, MM_AllocateDescription *allocDescription, bool initMarkMap, bool rebuildMarkBits)
Looking through the classunload monitors on the JIT side to see where they're reserved.
AlenBadel
on 7 May 2020
@dmitripivkine @dsouzai @mpirvu could you confirm that the monitor above is the right one (used for class unloading by GC and compilation thread) ? Do you know where compilation threads reserves it?
gita-omr
on 7 May 2020
Precisely looks this is the owner of the Monitor.
> !j9javavm 0x00003FFFB000F6D0 | grep classUnloadMutex
0x4b28: struct RWMutex* classUnloadMutex = !rwmutex 0x00003FFFB003B0C8
> !rwmutex 0x00003FFFB003B0C8
RWMutex at 0x3fffb003b0c8 {
Fields for RWMutex:
0x0: struct J9ThreadMonitor* syncMon = !j9threadmonitor 0x00003FFFB0006108
0x8: I64 status = 0xFFFFFFFFFFFFFFFF (-1)
0x10: struct J9Thread* writer = !j9thread 0x00003FFF240DFCC0
}
> !threads | grep -i 3FFF240DFCC0
!stack 0x003c4300 !j9vmthread 0x003c4300 !j9thread 0x3fff240dfcc0 tid 0x24f9 (9465) // (AgentVMThread)
> !threads flags | grep -i 0x003c4300
!j9vmthread 0x3c4300 publicFlags=1020 privateFlags=100000 inNative=0 // AgentVMThread
Same as: https://github.com/eclipse/openj9/issues/8652#issuecomment-614666959
this thread should be mutator thread initiated GC (and became GC Master Thread for this GC).
AlenBadel
on 7 May 2020
@dmitripivkine @dsouzai @mpirvu could you confirm that the monitor above is the right one (used for class unloading by GC and compilation thread) ? Do you know where compilation threads reserves it?
Probably. Should be _javaVM->classUnloadMutex
dmitripivkine
on 7 May 2020
Do you know where compilation threads reserves it?
It is not unexpected that at a STW phase, the comp thread might not be the owner of the classunload mutext. The reason is because of this code:
dsouzai
on 7 May 2020
Sounds like we wanted this problem to be bigger than it actually was.
Submitted a PR that resolves this. See: https://github.com/eclipse/openj9/pull/9515
AlenBadel
on 11 May 2020
I've confirmed internally that commit resolves the issue by running the jdk_nio test suite about 60 times on ppc64le (JDK8). (Prior failure rate was 1/20).
I don't think the merged commit has made it's way to an adoptopenjdk nightly.
@M-Davies feel free to run jdk_nio when there's an available build to confirm.
AlenBadel
on 13 May 2020
@AlenBadel Kicked off https://ci.adoptopenjdk.net/view/Test_grinder/job/Grinder/3055/
M-Davies
on 14 May 2020
@AlenBadel Kicked off https://ci.adoptopenjdk.net/view/Test_grinder/job/Grinder/3055/
I'm not sure why selecting nightly on a grinder hasn't really been pulling the latest nightly. The build you're using is from a week ago, I think you need to explicitly specify the link to the nightly.
AlenBadel
on 15 May 2020
Tried again with a customized link https://ci.adoptopenjdk.net/view/Test_grinder/job/Grinder/3064/
M-Davies
on 15 May 2020
Looks good to me. Thanks for all the work on this
M-Davies
on 17 May 2020
Related issues
hrstoyanov
·
4Comments
Mesbah-Alam
·
5Comments
pwagland
·
3Comments
JasonFengJ9
·
5Comments
DanHeidinga
·
4Comments