search

eclipse-openj9 / openj9

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

segfaults running cmdLineTester_jvmtitests_hcr_OSRG_nongold rc021 #14115

Open pshipton opened 2 years ago

pshipton commented 2 years ago

See also https://github.com/eclipse-openj9/openj9/issues/14014#issuecomment-988963294 rc021 is a new test introduced by https://github.com/eclipse-openj9/openj9/pull/14063

Dec 6: https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_aarch64_linux_Nightly_testList_1/44 cmdLineTester_jvmtitests_hcr_OSRG_nongold_SE80_2 -Xcompressedrefs -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation

https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_ppc64le_linux_Nightly_testList_0/156 cmdLineTester_jvmtitests_hcr_OSRG_nongold_SE80_0 -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation -Xnocompressedrefs

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_aarch64_linux_Nightly_testList_1/48 cmdLineTester_jvmtitests_hcr_OSRG_nongold_0 -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation cmdLineTester_jvmtitests_hcr_OSRG_nongold_2 -Xcompressedrefs -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_aarch64_linux_Nightly_testList_0/49 cmdLineTester_jvmtitests_hcr_OSRG_nongold_2

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_aarch64_linux_Nightly_testList_1/49 cmdLineTester_jvmtitests_hcr_OSRG_nongold_0

Dec 7: https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_aarch64_linux_Nightly_testList_1/46 cmdLineTester_jvmtitests_hcr_OSRG_nongold_SE80_0

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_aarch64_linux_Nightly_testList_0/50 cmdLineTester_jvmtitests_hcr_OSRG_nongold_2

Dec 8: https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_aarch64_linux_Nightly_testList_0/47 cmdLineTester_jvmtitests_hcr_OSRG_nongold_SE80_2

Dec 9: https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_aarch64_linux_Nightly_testList_1/48 cmdLineTester_jvmtitests_hcr_OSRG_nongold_SE80_2

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_aarch64_linux_Nightly_testList_1/52 cmdLineTester_jvmtitests_hcr_OSRG_nongold_0 cmdLineTester_jvmtitests_hcr_OSRG_nongold_2

Dec 10: https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_aarch64_linux_Nightly_testList_1/49 cmdLineTester_jvmtitests_hcr_OSRG_nongold_SE80_0 cmdLineTester_jvmtitests_hcr_OSRG_nongold_SE80_2

Dec 11: https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_aarch64_linux_Release_testList_0/5/ https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_aarch64_linux_Release_testList_1/5/ https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_aarch64_linux_Release_testList_1/5/

Dec 13: https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_aarch64_linux_Nightly_testList_0/51/ https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_aarch64_linux_Nightly_testList_1/51/ https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_aarch64_linux_Nightly_testList_0/55/ https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_aarch64_linux_Nightly_testList_1/55/

Dec 14: https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_aarch64_linux_Nightly_testList_1/52/ https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_aarch64_linux_Nightly_testList_0/56/

Dec 15: https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_aarch64_linux_Nightly_testList_1/53/

These aarch64 failures happen every day, I'm not going to keep reporting them.

I'll just note one on AIX Dec 16 https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_ppc64_aix_Nightly_testList_0/168/

pshipton commented 2 years ago

Set as a blocker due to the frequent failures. This does not necessarily indicate the problem needs to be fixed with blocking priority. Whether the problem is fixed or the test removed until it can be fixed is TBD.

pshipton commented 2 years ago

I've tentatively set this to the 0.30 milestone as we don't know if the problem is an existing problem exposed by the new test, or a problem introduced by the new changes https://github.com/eclipse-openj9/openj9/pull/14063.

tajila commented 2 years ago

Here is the Java stacktrace:

<31ba00> *** BEGIN STACK WALK, flags = 00400001 walkThread = 0x000000000031BA00 ***
<31ba00>    ITERATE_O_SLOTS
<31ba00>    RECORD_BYTECODE_PC_OFFSET
<31ba00> Initial values: walkSP = 0x0000000000451D80, PC = 0x0000FFFF49463173, literals = 0x000000000002F558, A0 = 0x0000000000451DD8, j2iFrame = 0x0000000000451E78, ELS = 0x0000FFFF791875D0, decomp = 0x0000FFFEB800BD40
<31ba00> Bytecode frame: bp = 0x0000000000451D98, sp = 0x0000000000451D80, pc = 0x0000FFFF49463173, cp = 0x000000000002BF90, arg0EA = 0x0000000000451DD8, flags = 0x0000000000000000
<31ba00>    Method: java/lang/Class.buildAnnotations(Ljava/util/LinkedHashMap;)Ljava/util/LinkedHashMap; !j9method 0x000000000002F558
<31ba00>    Bytecode index = 27
<31ba00>    Using debug local mapper
<31ba00>    Locals starting at 0x0000000000451DD8 for 0x0000000000000008 slots
<31ba00>        O-Slot: a0[0x0000000000451DD8] = 0x000000008378B498
<31ba00>        O-Slot: a1[0x0000000000451DD0] = 0x0000000083ADC138
<31ba00>        O-Slot: t2[0x0000000000451DC8] = 0x00000000836802A0
<31ba00>        O-Slot: t3[0x0000000000451DC0] = 0x000000000000FFFF
<31ba00>        O-Slot: t4[0x0000000000451DB8] = 0x0000000000000000
<31ba00>        I-Slot: t5[0x0000000000451DB0] = 0x0000000000000000
<31ba00>        I-Slot: t6[0x0000000000451DA8] = 0x0000000000000000
<31ba00>        I-Slot: t7[0x0000000000451DA0] = 0x0000000000000000
<31ba00>    Pending stack starting at 0x0000000000451D80 for UDATA(0x0000000000000001) slots
<31ba00>        O-Slot: p0[0x0000000000451D80] = 0x000000000000FFFF
<31ba00> J2I frame: bp = 0x0000000000451E78, sp = 0x0000000000451DE0, pc = 0x0000FFFF4946333F, cp = 0x000000000002BF90, arg0EA = 0x0000000000451EF0, flags = 0x0000000010000000
<31ba00>    Method: java/lang/Class.getAnnotationCache()Ljava/lang/Class$AnnotationCache; !j9method 0x000000000002F578
<31ba00>    Bytecode index = 191
<31ba00>    Using debug local mapper
<31ba00>    Locals starting at 0x0000000000451EF0 for 0x000000000000000F slots
<31ba00>        O-Slot: a0[0x0000000000451EF0] = 0x000000008378B498
<31ba00>        O-Slot: t1[0x0000000000451EE8] = 0x0000000000000000
<31ba00>        O-Slot: t2[0x0000000000451EE0] = 0x0000000083A938B0
<31ba00>        I-Slot: t3[0x0000000000451ED8] = 0x0000000000000000
<31ba00>        I-Slot: t4[0x0000000000451ED0] = 0x000000000000001E
<31ba00>        I-Slot: t5[0x0000000000451EC8] = 0x0000000000000000
<31ba00>        I-Slot: t6[0x0000000000451EC0] = 0x000000000043FF60
<31ba00>        O-Slot: t7[0x0000000000451EB8] = 0x0000000083A938D8
<31ba00>        O-Slot: t8[0x0000000000451EB0] = 0x0000000083ADC0F8
<31ba00>        O-Slot: t9[0x0000000000451EA8] = 0x0000000083ADC138
<31ba00>        O-Slot: t10[0x0000000000451EA0] = 0x0000000083ADC0F8
<31ba00>        I-Slot: t11[0x0000000000451E98] = 0x0000000000000003
<31ba00>        I-Slot: t12[0x0000000000451E90] = 0x0000000000000003
<31ba00>        I-Slot: t13[0x0000000000451E88] = 0x0000000083ADC0B8
<31ba00>        I-Slot: t14[0x0000000000451E80] = 0x0000000083752290
<31ba00>    Pending stack starting at 0x0000000000451DF0 for UDATA(0x0000000000000003) slots
<31ba00>        O-Slot: p0[0x0000000000451DF0] = 0x0000000083ADC1F0
<31ba00>        O-Slot: p1[0x0000000000451DE8] = 0x0000000083ADC1F0
<31ba00>        O-Slot: p2[0x0000000000451DE0] = 0x0000000083ADC138
<31ba00>    JIT-J2I-RegisterMap[0x0000000000451E20] = UDATA(0x0000000083A5A858) (jit_r21)
<31ba00>    JIT-J2I-RegisterMap[0x0000000000451E28] = UDATA(0x0000000000543600) (jit_r22)
<31ba00>    JIT-J2I-RegisterMap[0x0000000000451E30] = UDATA(0x0000000083A37570) (jit_r23)
<31ba00>    JIT-J2I-RegisterMap[0x0000000000451E38] = UDATA(0x0000000000000000) (jit_r24)
<31ba00>    JIT-J2I-RegisterMap[0x0000000000451E40] = UDATA(0x0000000083A37540) (jit_r25)
<31ba00>    JIT-J2I-RegisterMap[0x0000000000451E48] = UDATA(0x0000000000000000) (jit_r26)
<31ba00>    JIT-J2I-RegisterMap[0x0000000000451E50] = UDATA(0x0000000083E11E78) (jit_r27)
<31ba00>    JIT-J2I-RegisterMap[0x0000000000451E58] = UDATA(0x0000000083A375A0) (jit_r28)
<31ba00> (ws pcaddr = 0x0000000000451E70, dc tos = 0x0000FFFEB800BD40, pcaddr = 0x0000000000451E70, pc = 0x0000FFFF8C352AE0)
<31ba00> JIT frame: bp = 0x0000000000451FD8, pc = 0x0000FFFF8C352AE0, unwindSP = 0x0000000000451EF0, cp = 0x000000000002BF90, arg0EA = 0x0000000000451FE0, jitInfo = 0x0000FFFE71F72738
<31ba00>    Method: java/lang/Class.getDeclaredAnnotations()[Ljava/lang/annotation/Annotation; !j9method 0x000000000002F378
<31ba00>    Bytecode index = 1, inlineDepth = 0, PC offset = 0x0000FFFF8C352ADD
<31ba00>    stackMap=0x0000FFFE71F72868, slots=I16(0x0001) parmBaseOffset=I16(0x0008), parmSlots=U16(0x0001), localBaseOffset=I16(0xFF90)
<31ba00>    Described JIT args starting at 0x0000000000451FE0 for U16(0x0001) slots
<31ba00>        O-Slot: : a0[0x0000000000451FE0] = 0x000000008378B498
<31ba00>    Described JIT temps starting at 0x0000000000451F68 for IDATA(0x000000000000000E) slots
<31ba00> Address 0x0000FFFE71F72B60
<31ba00> Num internal ptr map bytes U8(0x07)
<31ba00> Address 0x0000FFFE71F72B61
<31ba00> Index of first internal ptr I16(0x000B)
<31ba00> Address 0x0000FFFE71F72B63
<31ba00> Offset of first internal ptr I16(0xFFE0)
<31ba00> Address 0x0000FFFE71F72B65
<31ba00> Num distinct pinning arrays U8(0x02)
<31ba00> Before object slot walk &address : 0x0000000000451FC0 address : 0x0000000000000000 bp 0x0000000000451FD8 offset of first internal ptr I16(0xFFE0)
<31ba00> After object slot walk for pinning array with &address : 0x0000000000451FC0 old address 0x0000000000000000 new address 0x0000000000000000 displacement IDATA(0x0000000000000000)
<31ba00> For pinning array U8(0x01) num internal pointer stack slots U8(0x01)
<31ba00> Before object slot walk &address : 0x0000000000451FB8 address : 0x0000000000000000 bp 0x0000000000451FD8 offset of first internal ptr I16(0xFFE0)
<31ba00> After object slot walk for pinning array with &address : 0x0000000000451FB8 old address 0x0000000000000000 new address 0x0000000000000000 displacement IDATA(0x0000000000000000)
<31ba00> For pinning array U8(0x00) num internal pointer stack slots U8(0x01)
<31ba00>        O-Slot: : t13[0x0000000000451F68] = 0x0000000000000000
<31ba00>        O-Slot: : t12[0x0000000000451F70] = 0x0000000000000000
<31ba00>        O-Slot: : t11[0x0000000000451F78] = 0x0000000000000000
<31ba00>        O-Slot: : t10[0x0000000000451F80] = 0x0000000000000000
<31ba00>        O-Slot: : t9[0x0000000000451F88] = 0x0000000000000000
<31ba00>        O-Slot: : t8[0x0000000000451F90] = 0x0000000000000000
<31ba00>        I-Slot: : t7[0x0000000000451F98] = 0x0000FFFF4945B67A
<31ba00>        I-Slot: : t6[0x0000000000451FA0] = 0x000000000000000D
<31ba00>        I-Slot: : t5[0x0000000000451FA8] = 0x0000000000000000
<31ba00>        I-Slot: : t4[0x0000000000451FB0] = 0x0000000083680000
<31ba00>        I-Slot: : t3[0x0000000000451FB8] = 0x0000000000000000
<31ba00>        I-Slot: : t2[0x0000000000451FC0] = 0x0000000000000000
<31ba00>        I-Slot: : t1[0x0000000000451FC8] = 0x0000000000000000
<31ba00>        I-Slot: : t0[0x0000000000451FD0] = 0x0000000000000000
<31ba00>    JIT-RegisterMap = UDATA(0x0000000000000000)
<31ba00>    JIT-OSRBuffer = 0x0000FFFEB800BD78, numberOfFrames = 1
<31ba00>    JIT-OSRFrame = 0x0000FFFEB800BD88, bytecodePC = 0x0000FFFF49462B21, numberOfLocals = UDATA(0x0000000000000003), maxStack = UDATA(0x0000000000000002), pendingStackHeight = UDATA(0x0000000000000000)
<31ba00>    Method: java/lang/Class.getDeclaredAnnotations()[Ljava/lang/annotation/Annotation; !j9method 0x000000000002F378
<31ba00>    Bytecode index = 1
<31ba00>    Using debug local mapper
<31ba00>    Locals starting at 0x0000FFFEB800BDE0 for 0x0000000000000003 slots
<31ba00>        O-Slot: a0[0x0000FFFEB800BDE0] = 0x0000000000000000
<31ba00>        I-Slot: t1[0x0000FFFEB800BDD8] = 0x0000000000000000
<31ba00>        I-Slot: t2[0x0000FFFEB800BDD0] = 0x0000000000000000
<31ba00>    JIT-Frame-RegisterMap[0x0000000000451F20] = UDATA(0x0000000083A5A858) (jit_r21)
<31ba00>    JIT-Frame-RegisterMap[0x0000000000451F28] = UDATA(0x0000000000543600) (jit_r22)
<31ba00>    JIT-Frame-RegisterMap[0x0000000000451E30] = UDATA(0x0000000083A37570) (jit_r23)
<31ba00>    JIT-Frame-RegisterMap[0x0000000000451F30] = UDATA(0x0000000000000000) (jit_r24)
<31ba00>    JIT-Frame-RegisterMap[0x0000000000451F38] = UDATA(0x0000000083A37540) (jit_r25)
<31ba00>    JIT-Frame-RegisterMap[0x0000000000451F40] = UDATA(0x0000000000000000) (jit_r26)
<31ba00>    JIT-Frame-RegisterMap[0x0000000000451E50] = UDATA(0x0000000083E11E78) (jit_r27)
<31ba00>    JIT-Frame-RegisterMap[0x0000000000451E58] = UDATA(0x0000000083A375A0) (jit_r28)
<31ba00> (ws pcaddr = 0x0000000000451FD8, dc tos = 0x0000FFFEB8004320, pcaddr = 0x0000000000452060, pc = 0x0000FFFF8C3509C4)
<31ba00> I2J values: PC = 0x0000FFFF9C274EB8, A0 = 0x0000000000452080, walkSP = 0x0000000000451FE8, literals = 0x0000000000543948, JIT PC = 0x0000FFFFA093C684, pcAddress = 0x0000000000451E10, decomp = 0x0000FFFEB8004320
<31ba00> J2I frame: bp = 0x0000000000452068, sp = 0x0000000000451FE8, pc = 0x0000FFFF9C274EB8, cp = 0x00000000005437C0, arg0EA = 0x0000000000452080, flags = 0x0000000010000000
<31ba00>    Method: com/ibm/jvmti/tests/redefineClasses/rc021$1AnnotationFetch.run()V !j9method 0x0000000000543948
<31ba00>    Bytecode index = 4
<31ba00>    Using debug local mapper
<31ba00>    Locals starting at 0x0000000000452080 for 0x0000000000000003 slots
<31ba00>        O-Slot: a0[0x0000000000452080] = 0x0000000083A5A828
<31ba00>        O-Slot: t1[0x0000000000452078] = 0x000000008378B498
<31ba00>        I-Slot: t2[0x0000000000452070] = 0x0000000000000000
tajila commented 2 years ago

The crash occurs on an invokeVirtual with O-Slot: p0[0x0000000000451D80] = 0x000000000000FFFF receiver

tajila commented 2 years ago

Method and bytecodes

> !j9method 0x000000000002F558
J9Method at 0x2f558 {
  Fields for J9Method:
    0x0: U8* bytecodes = !j9x 0x0000FFFF49463158 // "*�L"
    0x8: struct J9ConstantPool* constantPool = !j9constantpool 0x000000000002BF90 (flags = 0x0)
    0x10: void* methodRunAddress = !j9x 0x0000000000000006
    0x18: volatile void* extra = !j9x 0x0000000000000003
}
Signature: java/lang/Class.buildAnnotations(Ljava/util/LinkedHashMap;)Ljava/util/LinkedHashMap; !bytecodes 0x000000000002F558
ROM Method: !j9rommethod 0x0000FFFF49463144
Next Method: !j9method 0x000000000002F578
> !bytecodes 0x000000000002F558
  Name: buildAnnotations
  Signature: (Ljava/util/LinkedHashMap;)Ljava/util/LinkedHashMap;
  Access Flags (12240002): private
  Max Stack: 4
  Argument Count: 2
  Temp Count: 6

    0 aload0
    1 invokevirtual 76 java/lang/Class.getSuperclass()Ljava/lang/Class;
    4 astore2
    5 aload2
    6 ifnonnull 11
    9 aload1
   10 return1
   11 aload2
   12 invokespecial 328 java/lang/Class.getAnnotationCache()Ljava/lang/Class$AnnotationCache;
   15 getfield 329 java/lang/Class$AnnotationCache.annotationMap Ljava/util/LinkedHashMap;
   18 astore3
   19 aconstnull
   20 astore 4
   22 aload3
   23 ifnull 135
   26 aload3
   27 invokevirtual 348 java/util/LinkedHashMap.entrySet()Ljava/util/Set; //<-crash here
tajila commented 2 years ago

There is a c_jitDecompileOnReturn on the thread right before the crash.

A new bytecode frame is built a 0x451d88, this would mean that the java/lang/Class.buildAnnotations bytecode frame is the frame that was just built.

The method being decompiled is java/lang/Class.getSuperclass()

Looking at the bytecodes the result of this call is used in:

12 invokespecial 328 java/lang/Class.getAnnotationCache()Ljava/lang/Class$AnnotationCache;

then

15 getfield 329 java/lang/Class$AnnotationCache.annotationMap Ljava/util/LinkedHashMap;

then it becomes the receiver for

27 invokevirtual 348 java/util/LinkedHashMap.entrySet()Ljava/util/Set;

tajila commented 2 years ago

clone() doesn't seem to be involved here, but the rest looks similar to #14014

I will try to get more diagnostics, but right now it looks like there was a bad return value from c_jitDecompileOnReturn which is identical to the problem we had in #14014

tajila commented 2 years ago

The receiver that java/lang/Class.getSuperclass() is called on is com/ibm/jvmti/tests/redefineClasses/rc021_testAnnotationCache_O, thats the class that is being redefined.

The jitDecompileOnReturn registered on java/lang/Class.getSuperclass()Ljava/lang/Class; which has the following bytecodes:

> !bytecodes 0x000000000002F018
  Name: getSuperclass
  Signature: ()Ljava/lang/Class;
  Access Flags (2050001): public
  Max Stack: 1
  Argument Count: 1
  Temp Count: 0

    0 aload0
    1 invokestatic 290 java/lang/J9VMInternals.getSuperclass(Ljava/lang/Class;)Ljava/lang/Class;
    4 return1

The return value from the JIT is 

> !j9object 0x836802a0
!J9Object 0x00000000836802A0 {
    struct J9Class* clazz = !j9class 0x38300 // com/ibm/jit/JITHelpers
    Object flags = 0x00000000;
    I lockword = 0x00000000 (offset = 0) (java/lang/Object) <hidden>
}

which is incorrect.

It does look like we have a JITHelpers::getSuperclass(Class<?> clazz) helper. @0xdaryl @jdmpapin Are there optimizations that replace java/lang/J9VMInternals.getSuperclass with JITHelpers::getSuperclass(Class<?> clazz) JITHelpers::getSuperclass(Class<?> clazz) ?

0xdaryl commented 2 years ago

Are there optimizations that replace java/lang/J9VMInternals.getSuperclass with JITHelpers::getSuperclass(Class<?> clazz) ?

Yes, this is done unconditionally early during IL generation. I'm not familiar with this particular transformation just yet to say whether it should be correct or not, but this could be another one that we bar from occurring under involuntary OSR.

https://github.com/eclipse-openj9/openj9/blob/95691ded2b58e145270e084e66647ab5f148c2a8/runtime/compiler/env/VMJ9.cpp#L8034

The JIT will investigate this angle.

JasonFengJ9 commented 2 years ago

Also seen in an internal build job_output.php?id=22227520 (win10x64vs2)

Testing: rc021
Running command: "w:\builds\bld_18036/sdk/wa6480\bin\java"  -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation -Xnocompressedrefs  -Xdump    -agentlib:jvmtitest=test:rc021 -cp "w:\builds\bld_18036/jvmtest/test/SE80\functional\cmdLineTests\jvmtitests\jvmtitest.jar;w:\builds\bld_18036/jvmtest/test/SE80\TKG\lib\asm-all.jar" com.ibm.jvmti.tests.util.TestRunner

Output from test:
 [OUT] *** Testing [1/2]:testAnnotatedTypes

 [OUT] OK

 [OUT] *** Testing [2/2]:testAnnotationCacheAfterRedefine

 [ERR] Unhandled exception
 [ERR] Type=Segmentation error vmState=0x00000000
 [ERR] Windows_ExceptionCode=c0000005 J9Generic_Signal=00000004 ExceptionAddress=00007FF99317D736 ContextFlags=0010005f
 [ERR] Handler1=00007FF9931A76A0 Handler2=00007FF99462BD40 InaccessibleReadAddress=000000000000000E
 [ERR] RDI=0000000681FFF3B8 RSI=0000000000000000 RAX=0000000000000000 RBX=000001347EF1AB40
 [ERR] RCX=0000000000000006 RDX=00007FF413322980 R8=00007FF9A0153180 R9=0000000000000006
 [ERR] R10=00000134003BE88E R11=0000000681FFEBD0 R12=00007FF413322980 R13=0000000000000006
 [ERR] R14=000001340178DA48 R15=0000000681FFF3A0
 [ERR] RIP=00007FF99317D736 RSP=0000000681FFED00 RBP=0000013401545200 EFLAGS=0000000000010206
 [ERR] FS=0053 ES=002B DS=002B

 [ERR] Module=w:\builds\bld_18036\sdk\wa6480\jre\bin\default\j9vm29.dll
 [ERR] Module_base_address=00007FF993120000 Offset_in_DLL=000000000005d736
 [ERR] Target=2_90_20211208_18036 (Windows 10 10.0 build 18363)
 [ERR] CPU=amd64 (4 logical CPUs) (0x1fff08000 RAM)
 [ERR] ----------- Stack Backtrace -----------
 [ERR] hashClassTableAtString+0x6 (keyhashtable.c:653, 0x00007FF99317D736 [j9vm29+0x5d736])
 [ERR] internalFindClassString+0x66 (classsupport.c:301, 0x00007FF993192306 [j9vm29+0x72306])
 [ERR] ?run@VM_DebugBytecodeInterpreterFull@@QEAA_KPEAUJ9VMThread@@@Z+0x11093 (0x00007FF993150BC3 [j9vm29+0x30bc3])
 [ERR] (0x0000000681FFF3C8)
 [ERR] (0x0000013401545200)
 [ERR] (0x0000000681FFF3A8)
 [ERR] (0x0000000681FFF3B8)
 [ERR] (0x0000000000000008)
 [ERR] (0x0000000000000001)
 [ERR] (0x0000000600000000)
 [ERR] (0x0000000681FFF3A8)
 [ERR] (0x0000000681FFF3B8)
 [ERR] (0x0000000681FFF3A0)
 [ERR] (0x0000000681FFF3B0)
 [ERR] (0x0000000681FFF3C8)
 [ERR] (0x0000000681FFF3D0)
 [ERR] (0x000001340178DAD0)
 [ERR] (0x0000000000000020)
 [ERR] (0x0000000681FFF3F8)
 [ERR] (0x0000000681FFF3D8)
 [ERR] (0x000000000002AB02)
 [ERR] rasinfoNames+0x1a4c (0x00007FF99329513C [j9vm29+0x17513c])
 [ERR] RtlGetCurrentServiceSessionId+0xb8d (0x00007FF9A8C0130D [ntdll+0x4130d])
 [ERR] RtlFreeHeap+0x51 (0x00007FF9A8C006E1 [ntdll+0x406e1])
 [ERR] omrmem_free_memory+0x5f (omrmemtag.c:208, 0x00007FF9946227EF [j9prt29+0x127ef])
 [ERR] jitDecompileMethod+0xf1 (decomp.cpp:508, 0x00007FF98C1ADE71 [j9jit29+0x6cde71])
 [ERR] (0x0000000000000001)
 [ERR] (0x0000000000000001)
 [ERR] (0x0000000000000008)
 [ERR] ---------------------------------------
 [ERR] JVMDUMP039I Processing dump event "gpf", detail "" at 2021/12/09 00:51:42 - please wait.

 [ERR] JVMDUMP051I JIT dump occurred in 'pool-2-thread-30' thread 0x0000013401545200
 [ERR] JVMDUMP053I JIT dump is recompiling java/util/concurrent/ThreadPoolExecutor.runWorker(Ljava/util/concurrent/ThreadPoolExecutor$Worker;)V
 [ERR] 0000013401545200: Object neither in heap nor stack-allocated in thread pool-2-thread-30
 [ERR] 0000013401545200:O-Slot=000001340178DA70
 [ERR] 0000013401545200:O-Slot value=000001340017CEA0
 [ERR] 0000013401545200:PC=0000000000000003
 [ERR] 0000013401545200:framesWalked=0
 [ERR] 0000013401545200:arg0EA=000001340178DA78
 [ERR] 0000013401545200:walkSP=000001340178DA40
 [ERR] 0000013401545200:literals=0000000000000008
 [ERR] 0000013401545200:jitInfo=0000000000000000
 [ERR] 0000013401545200:method=00000134003DB970 (java/lang/VMAccess.findClassOrNull(Ljava/lang/String;Ljava/lang/ClassLoader;)Ljava/lang/Class;) (Interpreted)
 [ERR] 0000013401545200:stack=0000013401786E30-000001340178DE80
 [ERR] 0000013401545200: Object neither in heap nor stack-allocated in thread pool-2-thread-30
 [ERR] 0000013401545200:O-Slot=000001340178DA98
 [ERR] 0000013401545200:O-Slot value=000001340017CEA0
 [ERR] 0000013401545200:PC=00000134003BE88E
 [ERR] 0000013401545200:framesWalked=1
 [ERR] 0000013401545200:arg0EA=000001340178DAA8
 [ERR] 0000013401545200:walkSP=000001340178DA80
 [ERR] 0000013401545200:literals=00000134003DB990
 [ERR] 0000013401545200:jitInfo=0000000000000000
 [ERR] 0000013401545200:method=00000134003DB990 (java/lang/VMAccess.findClassOrNullHelper(Ljava/lang/String;Ljava/lang/ClassLoader;)Ljava/lang/Class;) (Interpreted)
 [ERR] 0000013401545200:stack=0000013401786E30-000001340178DE80
 [ERR] 0000013401545200: Object neither in heap nor stack-allocated in thread pool-2-thread-30
 [ERR] 0000013401545200:O-Slot=000001340178DAD8
 [ERR] 0000013401545200:O-Slot value=000001340017CEA0
 [ERR] 0000013401545200:PC=00000134007C9633
 [ERR] 0000013401545200:framesWalked=2
 [ERR] 0000013401545200:arg0EA=000001340178DAD8
 [ERR] 0000013401545200:walkSP=000001340178DAB0
 [ERR] 0000013401545200:literals=00000134007E14B8
 [ERR] 0000013401545200:jitInfo=0000000000000000
 [ERR] 0000013401545200:method=00000134007E14B8 (com/ibm/oti/vm/BootstrapClassLoader.loadClass(Ljava/lang/String;)Ljava/lang/Class;) (Interpreted)
 [ERR] 0000013401545200:stack=0000013401786E30-000001340178DE80
 [ERR] Unhandled exception
 [ERR] Type=Segmentation error vmState=0x00020002
 [ERR] Windows_ExceptionCode=c0000005 J9Generic_Signal=00000004 ExceptionAddress=00007FF993201CEB ContextFlags=0010005f
 [ERR] Handler1=00007FF9931A76A0 Handler2=00007FF99462BD40 InaccessibleReadAddress=FFFFFFFFFFFFFFFF
 [ERR] RDI=00000006827FD9F0 RSI=0000000000000098 RAX=07FFFFFFFFFFFFFF RBX=0000000000000001
 [ERR] RCX=FFFFFFFFFFFFFFFE RDX=00000006827FDA38 R8=FFFFFFFFFFFFFFFE R9=00000134017CD080
 [ERR] R10=0000000000000000 R11=00000006827FD9F0 R12=0000000000000000 R13=0000000000000006
 [ERR] R14=00007FF9953B6350 R15=0000000000000000
 [ERR] RIP=00007FF993201CEB RSP=00000006827FD950 RBP=0000013400162060 EFLAGS=0000000000010A07
 [ERR] FS=0053 ES=002B DS=002B

 [ERR] Module=w:\builds\bld_18036\sdk\wa6480\jre\bin\default\j9vm29.dll
 [ERR] Module_base_address=00007FF993120000 Offset_in_DLL=00000000000e1ceb
 [ERR] Target=2_90_20211208_18036 (Windows 10 10.0 build 18363)
 [ERR] CPU=amd64 (4 logical CPUs) (0x1fff08000 RAM)
 [ERR] ----------- Stack Backtrace -----------
 [ERR] j9stackmap_StackBitsForPC+0x1eb (stackmap.c:136, 0x00007FF993201CEB [j9vm29+0xe1ceb])
 [ERR] walkBytecodeFrameSlots+0x322 (swalk.c:894, 0x00007FF9931DD4B2 [j9vm29+0xbd4b2])
 [ERR] walkBytecodeFrame+0x1ba (swalk.c:1002, 0x00007FF9931DDE1A [j9vm29+0xbde1a])
 [ERR] walkStackFrames+0x4fe (swalk.c:328, 0x00007FF9931DCF5E [j9vm29+0xbcf5e])
 [ERR] GC_VMThreadStackSlotIterator::scanSlots+0xa5 (vmthreadstackslotiterator.cpp:115, 0x00007FF98EB06785 [j9gc29+0x16785])
 [ERR] MM_RootScanner::scanOneThread+0x10e (rootscanner.cpp:521, 0x00007FF98EB0356E [j9gc29+0x1356e])
 [ERR] MM_RootScanner::scanThreads+0xb3 (rootscanner.cpp:488, 0x00007FF98EB03873 [j9gc29+0x13873])
 [ERR] MM_RootScanner::scanRoots+0x7d (rootscanner.cpp:921, 0x00007FF98EB026FD [j9gc29+0x126fd])
 [ERR] MM_MarkingDelegate::scanRoots+0x20a (markingdelegate.cpp:255, 0x00007FF98EC2371A [j9gc29+0x13371a])
 [ERR] MM_ParallelMarkTask::run+0x11b (parallelmarktask.cpp:53, 0x00007FF98ECA4AEB [j9gc29+0x1b4aeb])
 [ERR] MM_ParallelDispatcher::run+0x5f (paralleldispatcher.cpp:589, 0x00007FF98EBEE3AF [j9gc29+0xfe3af])
 [ERR] MM_ParallelGlobalGC::markAll+0x1ce (parallelglobalgc.cpp:958, 0x00007FF98EC4C5CE [j9gc29+0x15c5ce])
 [ERR] MM_ParallelGlobalGC::mainThreadGarbageCollect+0x22f (parallelglobalgc.cpp:463, 0x00007FF98EC4D06F [j9gc29+0x15d06f])
 [ERR] MM_ParallelGlobalGC::internalGarbageCollect+0x73 (parallelglobalgc.cpp:1238, 0x00007FF98EC4D673 [j9gc29+0x15d673])
 [ERR] MM_Collector::garbageCollect+0x327 (collector.cpp:502, 0x00007FF98EBF1207 [j9gc29+0x101207])
 [ERR] MM_MemorySubSpaceFlat::allocationRequestFailed+0x797 (memorysubspaceflat.cpp:154, 0x00007FF98EC9E417 [j9gc29+0x1ae417])
 [ERR] MM_MemorySubSpaceGeneric::allocateTLH+0x207 (memorysubspacegeneric.cpp:379, 0x00007FF98EC9FA57 [j9gc29+0x1afa57])
 [ERR] MM_TLHAllocationSupport::refresh+0x3aa (tlhallocationsupport.cpp:242, 0x00007FF98EC0D7CA [j9gc29+0x11d7ca])
 [ERR] MM_TLHAllocationSupport::allocateFromTLH+0x118 (tlhallocationsupport.cpp:310, 0x00007FF98EC0DA48 [j9gc29+0x11da48])
 [ERR] MM_TLHAllocationInterface::allocateObject+0x258 (tlhallocationinterface.cpp:194, 0x00007FF98EC07E68 [j9gc29+0x117e68])
 [ERR] OMR_GC_AllocateObject+0x251 (omrgcalloc.cpp:39, 0x00007FF98EC294B1 [j9gc29+0x1394b1])
 [ERR] J9AllocateObject+0x290 (mgcalloc.cpp:414, 0x00007FF98EB12590 [j9gc29+0x22590])
 [ERR] ?run@VM_DebugBytecodeInterpreterFull@@QEAA_KPEAUJ9VMThread@@@Z+0x29499 (0x00007FF993168FC9 [j9vm29+0x48fc9])
 [ERR] ---------------------------------------
 [ERR] JVMDUMP039I Processing dump event "gpf", detail "" at 2021/12/09 00:51:44 - please wait.
Time spent executing: 240189 milliseconds
Test result: FAILED

Also at job/Test_openjdk8_j9_extended.functional_aarch64_linux_testList_1/73/, job/Test_openjdk8_j9_extended.functional_aarch64_linux_testList_4/9/.

JasonFengJ9 commented 2 years ago

Another manifestation at JDK11 Windows. win16x64rt2-4 - job/Test_openjdk11_j9_extended.functional_x86-64_windows_testList_0/115/

[2021-12-11T06:01:56.221Z] variation: Mode607-OSRG
[2021-12-11T06:01:56.221Z] JVM_OPTIONS:  -Xcompressedrefs -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation 

[2021-12-11T06:03:34.897Z] Testing: rc021
[2021-12-11T06:03:34.897Z] Test start time: 2021/12/10 22:03:27 Pacific Standard Time
[2021-12-11T06:03:34.897Z] Running command: "C:/Users/jenkins/workspace/Test_openjdk11_j9_extended.functional_x86-64_windows_testList_0/openjdkbinary/j2sdk-image\\bin\\java"  -Xcompressedrefs -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation  -Xdump    -agentlib:jvmtitest=test:rc021 -cp "C:/Users/jenkins/workspace/Test_openjdk11_j9_extended.functional_x86-64_windows_testList_0/aqa-tests///..//jvmtest\functional\cmdLineTests\jvmtitests\jvmtitest.jar;C:/Users/jenkins/workspace/Test_openjdk11_j9_extended.functional_x86-64_windows_testList_0/aqa-tests/\TKG\lib\asm-all.jar" com.ibm.jvmti.tests.util.TestRunner
[2021-12-11T06:03:34.897Z] Time spent starting: 63 milliseconds
[2021-12-11T06:03:57.908Z] Time spent executing: 21103 milliseconds
[2021-12-11T06:03:57.908Z] Test result: FAILED
[2021-12-11T06:03:57.908Z] Output from test:
[2021-12-11T06:03:57.908Z]  [OUT] *** Testing [1/2]:    testAnnotatedTypes
[2021-12-11T06:03:57.908Z]  [OUT] Exception during annotation fetch:
[2021-12-11T06:03:57.908Z]  [OUT] java.lang.NullPointerException
[2021-12-11T06:03:57.908Z]  [OUT]   at java.base/java.util.Objects.requireNonNull(Objects.java:221)
[2021-12-11T06:03:57.908Z]  [OUT]   at java.base/java.lang.reflect.Proxy.<init>(Proxy.java:322)
[2021-12-11T06:03:57.908Z]  [OUT]   at com.sun.proxy.$Proxy0.<init>(Unknown Source)
[2021-12-11T06:03:57.909Z]  [OUT]   at jdk.internal.reflect.GeneratedConstructorAccessor5.newInstance(Unknown Source)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/java.lang.reflect.Proxy.newProxyInstance(Proxy.java:1022)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/java.lang.reflect.Proxy.newProxyInstance(Proxy.java:1008)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/sun.reflect.annotation.AnnotationParser$1.run(AnnotationParser.java:306)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/sun.reflect.annotation.AnnotationParser$1.run(AnnotationParser.java:304)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/java.security.AccessController.doPrivileged(AccessController.java:682)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/sun.reflect.annotation.AnnotationParser.annotationForMap(AnnotationParser.java:304)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/sun.reflect.annotation.AnnotationParser.parseAnnotation2(AnnotationParser.java:294)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/sun.reflect.annotation.AnnotationParser.parseAnnotations2(AnnotationParser.java:121)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/sun.reflect.annotation.AnnotationParser.parseSelectAnnotations(AnnotationParser.java:102)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/sun.reflect.annotation.AnnotationType.<init>(AnnotationType.java:145)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/sun.reflect.annotation.AnnotationType.getInstance(AnnotationType.java:85)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/sun.reflect.annotation.AnnotationParser.parseAnnotation2(AnnotationParser.java:267)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/sun.reflect.annotation.AnnotationParser.parseAnnotation(AnnotationParser.java:227)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/sun.reflect.annotation.TypeAnnotationParser.parseTypeAnnotation(TypeAnnotationParser.java:421)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/sun.reflect.annotation.TypeAnnotationParser.parseTypeAnnotations(TypeAnnotationParser.java:360)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/sun.reflect.annotation.TypeAnnotationParser.buildAnnotatedTypes(TypeAnnotationParser.java:110)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/sun.reflect.annotation.TypeAnnotationParser.buildAnnotatedInterfaces(TypeAnnotationParser.java:205)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/com.ibm.oti.reflect.TypeAnnotationParser.buildAnnotatedInterfaces(TypeAnnotationParser.java:113)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/java.lang.Class.getAnnotatedInterfaces(Class.java:2741)
[2021-12-11T06:03:57.909Z]  [OUT]   at com.ibm.jvmti.tests.redefineClasses.rc021$2AnnotationFetch.run(rc021.java:134)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[2021-12-11T06:03:57.909Z]  [OUT]   at java.base/java.lang.Thread.run(Thread.java:866)

[2021-12-11T06:03:57.918Z] >> Success condition was not found: [Return code: 0]
pshipton commented 2 years ago

One on AIX https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_ppc64_aix_Nightly_testList_0/168

pshipton commented 2 years ago

@0xdaryl Either this isn't fixed by https://github.com/eclipse-openj9/openj9/pull/14163 or there is more than one problem. There was a plinux failure in the nightly last night but https://github.com/eclipse-openj9/openj9/pull/14163 is included in the build. aarch64 did run clean last night.

https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_ppc64le_linux_Nightly_testList_0/167

pshipton commented 2 years ago

Also https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_x86-64_windows_Nightly_testList_1/174

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_x86-64_windows_Nightly_testList_1/176 https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_ppc64_aix_Release_testList_0/16/

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_x86-64_mac_Nightly_testList_1/166/

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_s390x_linux_Nightly_testList_0/180/

babsingh commented 2 years ago

can you please take a look at this?

Yes. I have a few existing tasks from last year. So, I will take a look at this sometime next week.

tajila commented 2 years ago

My mistake @babsingh I didnt mean this one, I meant https://github.com/eclipse-openj9/openj9/issues/14166

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_ppc64le_linux_Release_testList_0/18/ https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_x86-64_mac_Nightly_testList_1/179/ https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_ppc64le_linux_Nightly_testList_0/176/

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_aarch64_linux_Nightly_testList_1/66

DanHeidinga commented 2 years ago

@0xdaryl can you update this with the current state for the 0.30 release? We have about a week till the release date

0xdaryl commented 2 years ago

On x86 Linux I'm seeing a failure rate of 1/50 (2 NPEs out of 100 runs) (EDIT: actually 2/200 == 1/100). I'm trying to get failure artifacts now, and also verifying whether the fix is somehow being subverted or whether this is a different problem altogether.

The AArch64 failures referenced above is actually a crash during GVP, albeit in the same test. It isn't clear whether (or how) this is related to the original problem.

knn-k commented 2 years ago

The SEGV on AArch64 in https://github.com/eclipse-openj9/openj9/issues/14115#issuecomment-1009956805 seems to have occurred in the following location, where javaLangClass in x21 is 0x100000, and the result of offsetOfObjectVftField() in x0 is 0: https://github.com/eclipse-openj9/openj9/blob/684717766630da76ef64c0fedb269e3965900ede/runtime/compiler/env/VMJ9.cpp#L8391

0xdaryl commented 2 years ago

I ran the failing test overnight with -Xdump options and saw two failures that produced NPEs. Unfortunately, there is an issue with core file generation such that cores weren't produced, but javacores were. I'm looking into how to fix the core file generation.

0xdaryl commented 2 years ago

It took several hundred runs overnight, but I have a corefile produced on the NPE. Hopefully it will be useable.

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_ppc64le_linux_Nightly_testList_0/179/ https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_x86-64_linux_Nightly_testList_0/173/

0xdaryl commented 2 years ago

The current problem is a different problem than the one originally uncovered by this issue and fixed in 14163. The NPE has still been seen after disabling all native inlining, newInstanceImpl opt, and method inlining. It can also be reproduced with noopt (but not with -Xint). Reproduction rate is about 1/50.

This problem does tend to go into remission when diagnostic options are applied, but I've made some progress getting an OSR log and vlog when the failure occurs. Investigation continues.

The failure has only been seen with the stress JIT options to force particular OSR behaviour. It has not been seen in default mode through hundreds of runs. Given this fact and its reproduction rate suggests this isn't a blocker.

pshipton commented 2 years ago

This fails often in the nightly builds and should be fixed with high priority. Given the previous information, plus the test is new and the failure is not a regression, I agree this problem should not block the release. I'm moving it forward.

pshipton commented 2 years ago

From the weekend: https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_x86-32_windows_Nightly_testList_0/184 https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_ppc64le_linux_Nightly_testList_0/182

From last night: https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_aarch64_linux_Nightly_testList_1/72 https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_ppc64le_linux_Nightly_testList_0/183

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_aarch64_linux_Nightly_testList_1/77/

knn-k commented 2 years ago

I see some NullPointerExceptions in rc021 in https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_aarch64_linux_Nightly_testList_1/77/ above. No failures in the next nightly run: https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_aarch64_linux_Nightly/78/

knn-k commented 2 years ago

10x Grinder on AArch64 Linux: No failures https://openj9-jenkins.osuosl.org/job/Grinder/542/

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_aarch64_linux_Nightly_testList_0/75/ https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_aarch64_linux_Nightly_testList_0/76/ https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_x86-64_windows_aot_Personal_testList_1/29

knn-k commented 2 years ago

AArch64 Linux JDK 8 tests above:

knn-k commented 2 years ago

1 failure during GC in 20x Grinder jobs on AArch64 Linux JDK 8: https://openj9-jenkins.osuosl.org/job/Grinder/555/

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_aarch64_linux_Nightly_testList_1/79/

JasonFengJ9 commented 2 years ago

cmdLineTester_jvmtitests_hcr_OSRG_nongold_2_FAILED at job/Test_openjdk11_j9_extended.functional_x86-64_windows_testList_2/137/(win16x64rt2-10)

openjdk version "11.0.14" 2022-01-18
IBM Semeru Runtime Open Edition 11.0.14.0-rc1 (build 11.0.14+9)
Eclipse OpenJ9 VM 11.0.14.0-rc1 (build openj9-0.30.0-m3a, JRE 11 Windows Server 2016 amd64-64-Bit Compressed References 20220126_292 (JIT enabled, AOT enabled)
OpenJ9   - bebfe6842
OMR      - dac962a28
JCL      - 3e0def07d2 based on jdk-11.0.14+9)

[2022-01-26T14:39:56.854Z] Running test cmdLineTester_jvmtitests_hcr_OSRG_nongold_2 ...
[2022-01-26T14:39:57.275Z] ===============================================

[2022-01-26T14:40:00.125Z] variation: Mode607-OSRG
[2022-01-26T14:40:00.593Z] JVM_OPTIONS:  -Xcompressedrefs -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation 

[2022-01-26T14:41:49.653Z] Testing: rc021
[2022-01-26T14:41:49.653Z] Test start time: 2022/01/26 09:41:49 Eastern Standard Time
[2022-01-26T14:41:49.653Z] Running command: "C:/Users/jenkins/workspace/Test_openjdk11_j9_extended.functional_x86-64_windows_testList_2/openjdkbinary/j2sdk-image\\bin\\java"  -Xcompressedrefs -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation  -Xdump    -agentlib:jvmtitest=test:rc021 -cp "C:/Users/jenkins/workspace/Test_openjdk11_j9_extended.functional_x86-64_windows_testList_2/aqa-tests///..//jvmtest\functional\cmdLineTests\jvmtitests\jvmtitest.jar;C:/Users/jenkins/workspace/Test_openjdk11_j9_extended.functional_x86-64_windows_testList_2/aqa-tests/\TKG\lib\asm-all.jar" com.ibm.jvmti.tests.util.TestRunner
[2022-01-26T14:41:49.653Z] Time spent starting: 47 milliseconds
[2022-01-26T14:42:19.574Z] Time spent executing: 26060 milliseconds
[2022-01-26T14:42:19.574Z] Test result: FAILED
[2022-01-26T14:42:19.574Z] Output from test:

[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/java.lang.reflect.Proxy.<init>(Proxy.java:322)
[2022-01-26T14:42:19.578Z]  [OUT]   at com.ibm.jvmti.tests.redefineClasses.$Proxy8.<init>(Unknown Source)
[2022-01-26T14:42:19.578Z]  [OUT]   at jdk.internal.reflect.GeneratedConstructorAccessor268.newInstance(Unknown Source)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/java.lang.reflect.Proxy.newProxyInstance(Proxy.java:1022)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/java.lang.reflect.Proxy.newProxyInstance(Proxy.java:1008)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/sun.reflect.annotation.AnnotationParser$1.run(AnnotationParser.java:306)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/sun.reflect.annotation.AnnotationParser$1.run(AnnotationParser.java:304)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/java.security.AccessController.doPrivileged(AccessController.java:682)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/sun.reflect.annotation.AnnotationParser.annotationForMap(AnnotationParser.java:304)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/sun.reflect.annotation.AnnotationParser.parseAnnotation2(AnnotationParser.java:294)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/sun.reflect.annotation.AnnotationParser.parseAnnotations2(AnnotationParser.java:121)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/sun.reflect.annotation.AnnotationParser.parseAnnotations(AnnotationParser.java:73)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/java.lang.Class.getAnnotationCache(Class.java:3116)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/java.lang.Class.getDeclaredAnnotations(Class.java:2789)
[2022-01-26T14:42:19.578Z]  [OUT]   at com.ibm.jvmti.tests.redefineClasses.rc021$1AnnotationFetch.run(rc021.java:73)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[2022-01-26T14:42:19.578Z]  [OUT]   at java.base/java.lang.Thread.run(Thread.java:866)
[2022-01-26T14:42:19.578Z]  [OUT] *** Test took 8608 milliseconds
[2022-01-26T14:42:19.578Z]  [OUT] FAILED
[2022-01-26T14:42:19.578Z]  [OUT] 
[2022-01-26T14:42:19.578Z] >> Success condition was not found: [Return code: 0]

[2022-01-26T14:42:35.678Z] cmdLineTester_jvmtitests_hcr_OSRG_nongold_2_FAILED
pshipton commented 2 years ago

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

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_ppc64le_linux_Nightly_testList_1/192/ https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_x86-64_linux_Nightly_testList_1/187/ https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_ppc64le_linux_Nightly_testList_1/193/ https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_aarch64_linux_Nightly_testList_0/84/

pshipton commented 2 years ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_ppc64le_linux_Nightly_testList_1/194/

This failure continues to happen regularly. I'm not going to keep reporting them. Look at the nightly builds for the latest failures, or ask me.

0xdaryl commented 2 years ago

I'm still trying to narrow this down into something manageable. A few observations:

0xdaryl commented 2 years ago

TL;DR

The NPE is thrown because of a null sun/reflect/annotation/AnnotationInvocationHandler object during a java/lang/reflect/Constructor.newInstance call. We have a valid AnnotationInvocationHandler object early in this dispatch sequence, but this object appears to have been "lost" passing through two generated reflection methods which are both interpreted, leading to the NPE.

I would like some VM assistance understanding what happens to this object during those methods. Please see guided commentary below. @tajila

As an aside, I have not observed this problem when running without the JIT OSR stress options, and in fact the failure is reproducible at noopt (which often suggests either a timing issue or a problem with the JIT runtime). At the moment I am not sure if there is a connection with OSR or not, but I'd like the mystery with this null parameter cleared up first.

This problem occurs consistently with the same backtrace, and I was able to use Xdump to create a core and javacore when the NPE was thrown. All artifacts are available here -> https://ibm.box.com/s/gxrvkpseeq2u6vuc4sk67y3umwszrdhi

From the core file:

<370b00> !j9method 0x0000000000084010   java/util/Objects.requireNonNull(Ljava/lang/Object;)Ljava/lang/Object;
<370b00> !j9method 0x00000000003D9FE8   java/lang/reflect/Proxy.<init>(Ljava/lang/reflect/InvocationHandler;)V
<370b00> !j9method 0x000000000076D838   com/sun/proxy/$Proxy8.<init>(Ljava/lang/reflect/InvocationHandler;)V
<370b00> !j9method 0x00000000003BFDE8   jdk/internal/reflect/GeneratedConstructorAccessor210.newInstance([Ljava/lang/Object;)Ljava/lang/Object;
<370b00> !j9method 0x00000000001C1258   jdk/internal/reflect/DelegatingConstructorAccessorImpl.newInstance([Ljava/lang/Object;)Ljava/lang/Object;
<370b00> !j9method 0x00000000000AD1A0   java/lang/reflect/Constructor.newInstance([Ljava/lang/Object;)Ljava/lang/Object;
<370b00> !j9method 0x00000000003DA088   java/lang/reflect/Proxy.newProxyInstance(Ljava/lang/Class;Ljava/lang/reflect/Constructor;Ljava/lang/reflect/InvocationHandler;)Ljava/lang/Object;
<370b00> !j9method 0x00000000003DA068   java/lang/reflect/Proxy.newProxyInstance(Ljava/lang/ClassLoader;[Ljava/lang/Class;Ljava/lang/reflect/InvocationHandler;)Ljava/lang/Object;
<370b00> !j9method 0x00000000003D7DE8   sun/reflect/annotation/AnnotationParser$1.run()Ljava/lang/annotation/Annotation;
<370b00> !j9method 0x00000000003D7E08   sun/reflect/annotation/AnnotationParser$1.run()Ljava/lang/Object;
<370b00> !j9method 0x00000000000E2EC0   java/security/AccessController.doPrivileged(Ljava/security/PrivilegedAction;)Ljava/lang/Object;
<370b00> !j9method 0x00000000001BC7D0   sun/reflect/annotation/AnnotationParser.annotationForMap(Ljava/lang/Class;Ljava/util/Map;)Ljava/lang/annotation/Annotation;
<370b00> !j9method 0x00000000001BC7B0   sun/reflect/annotation/AnnotationParser.parseAnnotation2(Ljava/nio/ByteBuffer;Ljdk/internal/reflect/ConstantPool;Ljava/lang/Class;Z[Ljava/lang/Class;)Ljava/lang/annotation/Annotation;
<370b00> !j9method 0x00000000001BC730   sun/reflect/annotation/AnnotationParser.parseAnnotations2([BLjdk/internal/reflect/ConstantPool;Ljava/lang/Class;[Ljava/lang/Class;)Ljava/util/Map;
<370b00> !j9method 0x00000000001BC6F0   sun/reflect/annotation/AnnotationParser.parseAnnotations([BLjdk/internal/reflect/ConstantPool;Ljava/lang/Class;)Ljava/util/Map;
<370b00> !j9method 0x000000000007AB78   java/lang/Class.getAnnotationCache()Ljava/lang/Class$AnnotationCache;
<370b00> !j9method 0x000000000007A978   java/lang/Class.getDeclaredAnnotations()[Ljava/lang/annotation/Annotation;
<370b00> !j9method 0x000000000075EFF8   com/ibm/jvmti/tests/redefineClasses/rc021$1AnnotationFetch.run()V
<370b00> !j9method 0x000000000033DFE8   java/util/concurrent/Executors$RunnableAdapter.call()Ljava/lang/Object;
<370b00> !j9method 0x000000000033D680   java/util/concurrent/FutureTask.run()V
<370b00> !j9method 0x0000000000337330   java/util/concurrent/ThreadPoolExecutor.runWorker(Ljava/util/concurrent/ThreadPoolExecutor$Worker;)V
<370b00> !j9method 0x000000000033E6D0   java/util/concurrent/ThreadPoolExecutor$Worker.run()V
<370b00> !j9method 0x0000000000094B18   java/lang/Thread.run()V

The NPE is being thrown because the java/lang/reflect/InvocationHandler parameter to the Proxy constructor is null. From a stack trace, we can track the origin of that parameter as the next few methods on the stack are fairly simple.

Numerical annotations with <<<< [#] are mine for discussion below.

> !stackslots 0x0000000000370B00
<370b00> *** BEGIN STACK WALK, flags = 00400001 walkThread = 0x0000000000370B00 ***
<370b00>        ITERATE_O_SLOTS
<370b00>        RECORD_BYTECODE_PC_OFFSET
<370b00> Initial values: walkSP = 0x0000000000435128, PC = 0x0000000000000005, literals = 0x0000000000000000, A0 = 0x0000000000435148, j2iFrame = 0x0000000000435268, ELS = 0x00007FDEDD276B90, decomp = 0x00007FDC80007B90
=====================
<370b00> JIT resolve frame: bp = 0x0000000000435148, sp = 0x0000000000435128, pc = 0x0000000000000005, cp = 0x0000000000000000, arg0EA = 0x0000000000435148, flags = 0x0000000000080000
<370b00>        Object push (savedJITException)
<370b00>                O-Slot[0x0000000000435128] = 0x0000000000000000  <<<< null
<370b00>        Generic resolve
<370b00>        unwindSP initialized to 0x0000000000435150
<370b00>        JIT-Resolve-RegisterMap[0x00007FDEDD276280] = UDATA(0x00000001C02D21C0) (jit_rax)
<370b00>        JIT-Resolve-RegisterMap[0x00007FDEDD276288] = UDATA(0x0000000000000000) (jit_rbx)
<370b00>        JIT-Resolve-RegisterMap[0x00007FDEDD276290] = UDATA(0x00007FDF1616354D) (jit_rcx)
<370b00>        JIT-Resolve-RegisterMap[0x00007FDEDD276298] = UDATA(0x0000000000370B00) (jit_rdx)
<370b00>        JIT-Resolve-RegisterMap[0x00007FDEDD2762A0] = UDATA(0x0000000000000009) (jit_rdi)
<370b00>        JIT-Resolve-RegisterMap[0x00007FDEDD2762A8] = UDATA(0x00007FDEDD276280) (jit_rsi)
<370b00>        JIT-Resolve-RegisterMap[0x00007FDEDD2762B0] = UDATA(0x00000001C0401398) (jit_rbp)
<370b00>        JIT-Resolve-RegisterMap[0x00007FDEDD2762B8] = UDATA(0x0000000000000000) (jit_rsp)
<370b00>        JIT-Resolve-RegisterMap[0x00007FDEDD2762C0] = UDATA(0x0000000000000020) (jit_r8)
<370b00>        JIT-Resolve-RegisterMap[0x00007FDEDD2762C8] = UDATA(0x0000000000000020) (jit_r9)
<370b00>        JIT-Resolve-RegisterMap[0x00007FDEDD2762D0] = UDATA(0x0000000000000000) (jit_r10)
<370b00>        JIT-Resolve-RegisterMap[0x00007FDEDD2762D8] = UDATA(0x0000000000000000) (jit_r11)
<370b00>        JIT-Resolve-RegisterMap[0x00007FDEDD2762E0] = UDATA(0x0000000000000000) (jit_r12)
<370b00>        JIT-Resolve-RegisterMap[0x00007FDEDD2762E8] = UDATA(0x0000000000000020) (jit_r13)
<370b00>        JIT-Resolve-RegisterMap[0x00007FDEDD2762F0] = UDATA(0x0000000000000004) (jit_r14)
<370b00>        JIT-Resolve-RegisterMap[0x00007FDEDD2762F8] = UDATA(0x0000000085815B62) (jit_r15)
=====================
<370b00> JIT frame: bp = 0x0000000000435178, pc = 0x00007FDF16163560, unwindSP = 0x0000000000435150, cp = 0x000000000007C290, arg0EA = 0x0000000000435180, jitInfo = 0x00007FDEDC17A938
<370b00>        Method: java/util/Objects.requireNonNull(Ljava/lang/Object;)Ljava/lang/Object; !j9method 0x0000000000084010
<370b00>        Bytecode index = 11, inlineDepth = 0, PC offset = 0x0000000000000070
<370b00>        stackMap=0x00007FDEDC17AA4F, slots=I16(0x0001) parmBaseOffset=I16(0x0008), parmSlots=U16(0x0001), localBaseOffset=I16(0xFFF8)
<370b00>        Described JIT args starting at 0x0000000000435180 for U16(0x0001) slots
<370b00>                O-Slot: : a0[0x0000000000435180] = 0x0000000000000000  <<<< null
<370b00>        Described JIT temps starting at 0x0000000000435170 for IDATA(0x0000000000000001) slots
<370b00>                O-Slot: : t0[0x0000000000435170] = 0x00000001C02D21C0
<370b00>        JIT-RegisterMap = UDATA(0x0000000000000001)
<370b00>                JIT-RegisterMap-O-Slot[0x00007FDEDD276280] = 0x00000001C02D21C0 (jit_rax)
<370b00>                JIT-RegisterMap-I-Slot[0x00007FDEDD276288] = UDATA(0x0000000000000000) (jit_rbx)
<370b00>                JIT-RegisterMap-I-Slot[0x00007FDEDD276290] = UDATA(0x00007FDF1616354D) (jit_rcx)
<370b00>                JIT-RegisterMap-I-Slot[0x00007FDEDD276298] = UDATA(0x0000000000370B00) (jit_rdx)
<370b00>                JIT-RegisterMap-I-Slot[0x00007FDEDD2762A0] = UDATA(0x0000000000000009) (jit_rdi)
<370b00>                JIT-RegisterMap-I-Slot[0x00007FDEDD2762A8] = UDATA(0x00007FDEDD276280) (jit_rsi)
<370b00>                JIT-RegisterMap-I-Slot[0x00007FDEDD2762B0] = UDATA(0x00000001C0401398) (jit_rbp)
<370b00>                JIT-RegisterMap-I-Slot[0x00007FDEDD2762B8] = UDATA(0x0000000000000000) (jit_rsp)
<370b00>                JIT-RegisterMap-I-Slot[0x00007FDEDD2762C0] = UDATA(0x0000000000000020) (jit_r8)
<370b00>                JIT-RegisterMap-I-Slot[0x00007FDEDD2762C8] = UDATA(0x0000000000000020) (jit_r9)
<370b00>                JIT-RegisterMap-I-Slot[0x00007FDEDD2762D0] = UDATA(0x0000000000000000) (jit_r10)
<370b00>                JIT-RegisterMap-I-Slot[0x00007FDEDD2762D8] = UDATA(0x0000000000000000) (jit_r11)
<370b00>                JIT-RegisterMap-I-Slot[0x00007FDEDD2762E0] = UDATA(0x0000000000000000) (jit_r12)
<370b00>                JIT-RegisterMap-I-Slot[0x00007FDEDD2762E8] = UDATA(0x0000000000000020) (jit_r13)
<370b00>                JIT-RegisterMap-I-Slot[0x00007FDEDD2762F0] = UDATA(0x0000000000000004) (jit_r14)
<370b00>                JIT-RegisterMap-I-Slot[0x00007FDEDD2762F8] = UDATA(0x0000000085815B62) (jit_r15)
<370b00>        JIT-Frame-RegisterMap[0x00007FDEDD276288] = UDATA(0x0000000000000000) (jit_rbx)
<370b00>        JIT-Frame-RegisterMap[0x0000000000435168] = UDATA(0x0000000000000010) (jit_r9)
<370b00>        JIT-Frame-RegisterMap[0x00007FDEDD2762D0] = UDATA(0x0000000000000000) (jit_r10)
<370b00>        JIT-Frame-RegisterMap[0x00007FDEDD2762D8] = UDATA(0x0000000000000000) (jit_r11)
<370b00>        JIT-Frame-RegisterMap[0x00007FDEDD2762E0] = UDATA(0x0000000000000000) (jit_r12)
<370b00>        JIT-Frame-RegisterMap[0x00007FDEDD2762E8] = UDATA(0x0000000000000020) (jit_r13)
<370b00>        JIT-Frame-RegisterMap[0x00007FDEDD2762F0] = UDATA(0x0000000000000004) (jit_r14)
<370b00>        JIT-Frame-RegisterMap[0x00007FDEDD2762F8] = UDATA(0x0000000085815B62) (jit_r15)
=====================
<370b00> JIT frame: bp = 0x0000000000435198, pc = 0x00007FDF161636AF, unwindSP = 0x0000000000435180, cp = 0x00000000003D96C0, arg0EA = 0x00000000004351A8, jitInfo = 0x00007FDEDC17AB38
<370b00>        Method: java/lang/reflect/Proxy.<init>(Ljava/lang/reflect/InvocationHandler;)V !j9method 0x00000000003D9FE8
<370b00>        Bytecode index = 5, inlineDepth = 0, PC offset = 0x0000000000000037
<370b00>        stackMap=0x00007FDEDC17AC40, slots=I16(0x0002) parmBaseOffset=I16(0x0008), parmSlots=U16(0x0002), localBaseOffset=I16(0x0000)
<370b00>        Described JIT args starting at 0x00000000004351A0 for U16(0x0002) slots
<370b00>                O-Slot: : a1[0x00000000004351A0] = 0x0000000000000000  <<<< null
<370b00>                O-Slot: : a0[0x00000000004351A8] = 0x00000001C02AF748
<370b00>        Described JIT temps starting at 0x0000000000435198 for IDATA(0x0000000000000000) slots
<370b00>        JIT-RegisterMap = UDATA(0x0000000000000000)
<370b00>        JIT-Frame-RegisterMap[0x0000000000435190] = UDATA(0x00000000003D7B00) (jit_rbx)
<370b00>        JIT-Frame-RegisterMap[0x0000000000435168] = UDATA(0x0000000000000010) (jit_r9)
<370b00>        JIT-Frame-RegisterMap[0x00007FDEDD2762D0] = UDATA(0x0000000000000000) (jit_r10)
<370b00>        JIT-Frame-RegisterMap[0x00007FDEDD2762D8] = UDATA(0x0000000000000000) (jit_r11)
<370b00>        JIT-Frame-RegisterMap[0x00007FDEDD2762E0] = UDATA(0x0000000000000000) (jit_r12)
<370b00>        JIT-Frame-RegisterMap[0x00007FDEDD2762E8] = UDATA(0x0000000000000020) (jit_r13)
<370b00>        JIT-Frame-RegisterMap[0x00007FDEDD2762F0] = UDATA(0x0000000000000004) (jit_r14)
<370b00>        JIT-Frame-RegisterMap[0x00007FDEDD2762F8] = UDATA(0x0000000085815B62) (jit_r15)
<370b00> (ws pcaddr = 0x0000000000435198, dc tos = 0x00007FDC80007B90, pcaddr = 0x0000000000435260, pc = 0x00007FDF1615E3F5)
<370b00> I2J values: PC = 0x00007FDEDD712C82, A0 = 0x00000000004351D8, walkSP = 0x00000000004351B8, literals = 0x000000000076D838, JIT PC = 0x00007FDF43E03F40, pcAddress = 0x00007FDEDD276BB8, decomp = 0x00007FDC80007B90
=====================
<370b00> Bytecode frame: bp = 0x00000000004351C8, sp = 0x00000000004351B8, pc = 0x00007FDEDD712C82, cp = 0x000000000076D590, arg0EA = 0x00000000004351D8, flags = 0x0000000000000000
<370b00>        Method: com/sun/proxy/$Proxy8.<init>(Ljava/lang/reflect/InvocationHandler;)V !j9method 0x000000000076D838
<370b00>        Bytecode index = 2
<370b00>        Using debug local mapper
<370b00>        Locals starting at 0x00000000004351D8 for 0x0000000000000002 slots
<370b00>                O-Slot: a0[0x00000000004351D8] = 0x00000001C02AF748
<370b00>                O-Slot: a1[0x00000000004351D0] = 0x0000000000000000  <<<< [4]
=====================
<370b00> J2I frame: bp = 0x0000000000435268, sp = 0x00000000004351E0, pc = 0x00007FDC780038BC, cp = 0x00000000003BFCC0, arg0EA = 0x0000000000435278, flags = 0x0000000010000000
<370b00>        Method: jdk/internal/reflect/GeneratedConstructorAccessor210.newInstance([Ljava/lang/Object;)Ljava/lang/Object; !j9method 0x00000000003BFDE8
<370b00>        Bytecode index = 28
<370b00>        Using debug local mapper
<370b00>        Locals starting at 0x0000000000435278 for 0x0000000000000002 slots
<370b00>                O-Slot: a0[0x0000000000435278] = 0x00000001C0175DE0
<370b00>                O-Slot: a1[0x0000000000435270] = 0x00000001C02AF730  <<<< [3]
<370b00>        Pending stack starting at 0x00000000004351E0 for UDATA(0x0000000000000001) slots
<370b00>                O-Slot: p0[0x00000000004351E0] = 0x00000001C02AF748
<370b00>        JIT-J2I-RegisterMap[0x0000000000435210] = UDATA(0x00000000003D7B00) (jit_rbx)
<370b00>        JIT-J2I-RegisterMap[0x0000000000435248] = UDATA(0x00000000001C2D00) (jit_r9)
<370b00>        JIT-J2I-RegisterMap[0x0000000000435240] = UDATA(0x0000000000000000) (jit_r10)
<370b00>        JIT-J2I-RegisterMap[0x0000000000435238] = UDATA(0x0001309481DB6706) (jit_r11)
<370b00>        JIT-J2I-RegisterMap[0x0000000000435230] = UDATA(0x00000001C02AF730) (jit_r12)
<370b00>        JIT-J2I-RegisterMap[0x0000000000435228] = UDATA(0x00000001C02AF748) (jit_r13)
<370b00>        JIT-J2I-RegisterMap[0x0000000000435220] = UDATA(0x0000000000000004) (jit_r14)
<370b00>        JIT-J2I-RegisterMap[0x0000000000435218] = UDATA(0x0000000085815B62) (jit_r15)
<370b00> (ws pcaddr = 0x0000000000435260, dc tos = 0x00007FDC80007B90, pcaddr = 0x0000000000435260, pc = 0x00007FDF1615E3F5)
=====================
<370b00> JIT frame: bp = 0x0000000000435288, pc = 0x00007FDF1615E3F5, unwindSP = 0x0000000000435270, cp = 0x00000000001C2C30, arg0EA = 0x0000000000435298, jitInfo = 0x00007FDEDC1736B8
<370b00>        Method: jdk/internal/reflect/DelegatingConstructorAccessorImpl.newInstance([Ljava/lang/Object;)Ljava/lang/Object; !j9method 0x00000000001C1258
<370b00>        Bytecode index = 5, inlineDepth = 0, PC offset = 0x00007FDF1615E3F2
<370b00>        stackMap=0x00007FDEDC1737C0, slots=I16(0x0002) parmBaseOffset=I16(0x0008), parmSlots=U16(0x0002), localBaseOffset=I16(0x0000)
<370b00>        Described JIT args starting at 0x0000000000435290 for U16(0x0002) slots
<370b00>                O-Slot: : a1[0x0000000000435290] = 0x00000001C02AF730  <<<< [2]
<370b00>                O-Slot: : a0[0x0000000000435298] = 0x00000001C0380128  <<<< [1]
<370b00>        Described JIT temps starting at 0x0000000000435288 for IDATA(0x0000000000000000) slots
<370b00>        JIT-RegisterMap = UDATA(0x0000000000000000)
<370b00>        JIT-OSRBuffer = 0x00007FDC80007BC8, numberOfFrames = 1
<370b00>        JIT-OSRFrame = 0x00007FDC80007BD8, bytecodePC = 0x00007FDEDD719281, numberOfLocals = UDATA(0x0000000000000002), maxStack = UDATA(0x0000000000000002), pendingStackHeight = UDATA(0x0000000000000000)
<370b00>        Method: jdk/internal/reflect/DelegatingConstructorAccessorImpl.newInstance([Ljava/lang/Object;)Ljava/lang/Object; !j9method 0x00000000001C1258
<370b00>        Bytecode index = 5
<370b00>        Using debug local mapper
<370b00>        Locals starting at 0x00007FDC80007C28 for 0x0000000000000002 slots
<370b00>                O-Slot: a0[0x00007FDC80007C28] = 0x00000001C0380128
<370b00>                O-Slot: a1[0x00007FDC80007C20] = 0x00000001C02AF730
<370b00>        JIT-Frame-RegisterMap[0x0000000000435210] = UDATA(0x00000000003D7B00) (jit_rbx)
<370b00>        JIT-Frame-RegisterMap[0x0000000000435248] = UDATA(0x00000000001C2D00) (jit_r9)
<370b00>        JIT-Frame-RegisterMap[0x0000000000435240] = UDATA(0x0000000000000000) (jit_r10)
<370b00>        JIT-Frame-RegisterMap[0x0000000000435238] = UDATA(0x0001309481DB6706) (jit_r11)
<370b00>        JIT-Frame-RegisterMap[0x0000000000435230] = UDATA(0x00000001C02AF730) (jit_r12)
<370b00>        JIT-Frame-RegisterMap[0x0000000000435228] = UDATA(0x00000001C02AF748) (jit_r13)
<370b00>        JIT-Frame-RegisterMap[0x0000000000435220] = UDATA(0x0000000000000004) (jit_r14)
<370b00>        JIT-Frame-RegisterMap[0x0000000000435218] = UDATA(0x0000000085815B62) (jit_r15)
<370b00> (ws pcaddr = 0x0000000000435288, dc tos = 0x00007FDC80007C80, pcaddr = 0x0000000000435288, pc = 0x00007FDF1615C9F4)

  ...

Starting with interface jdk/internal/reflect/DelegatingConstructorAccessorImpl.newInstance([Ljava/lang/Object;)Ljava/lang/Object;, it accepts 2 parameters [1] and [2]. The non-receiver argument [2] is an array of Objects. In this case 0x00000001C02AF730:

> !j9object 0x1c02af730
!J9IndexableObject 0x00000001C02AF730 {
    struct J9Class* clazz = !j9arrayclass 0x8C600   // [L
    Object flags = 0x00000000;
    U_32 size = 0x00000001;
        [0] = !fj9object 0x38055ede = !j9object 0x1c02af6f0
}

and its only element:

> !j9object 0x1c02af6f0
!J9Object 0x00000001C02AF6F0 {
        struct J9Class* clazz = !j9class 0x3D9500 // sun/reflect/annotation/AnnotationInvocationHandler
        Object flags = 0x00000000;
        I lockword = 0x00000000 (offset = 0) (java/lang/Object) <hidden>
        Ljava/lang/Class; type = !fj9object 0x3801fb75 (offset = 4) (sun/reflect/annotation/AnnotationInvocationHandler)
        Ljava/util/Map; memberValues = !fj9object 0x38055ec2 (offset = 8) (sun/reflect/annotation/AnnotationInvocationHandler)
        [Ljava/lang/reflect/Method; memberMethods = !fj9object 0x0 (offset = 12) (sun/reflect/annotation/AnnotationInvocationHandler)
}

This object array is further passed into the interpreted, generated constructor method jdk/internal/reflect/GeneratedConstructorAccessor210.newInstance([Ljava/lang/Object;)Ljava/lang/Object; [3]. This method should pull the AnnotationInvocationHandler object from the array and pass it into com/sun/proxy/$Proxy8.<init>(Ljava/lang/reflect/InvocationHandler;)V but null is passed instead [4]. This null value is then passed along further, leading the the NPE.

I looked at the bytecodes for GeneratedConstructorAccessor210.newInstance and based on the inputs to this method in this stack trace and manually inspecting the bytecode and logic at [5] we should be pulling the invocation handler from the array and passing that as a parameter, but it appears we aren't and I'm not sure why.

[5] https://github.com/ibmruntimes/openj9-openjdk-jdk11/blob/43e18bf7442c76713eef3ed82ce108c1edf21ecb/src/java.base/share/classes/jdk/internal/reflect/MethodAccessorGenerator.java#L433

tajila commented 2 years ago

@babsingh can you take a look at Daryl's comment above

babsingh commented 2 years ago

All artifacts are available here -> https://ibm.box.com/s/gxrvkpseeq2u6vuc4sk67y3umwszrdhi

@0xdaryl The above link does not work: This shared file or folder link has been removed or is unavailable to you. Is there a newer one?

0xdaryl commented 2 years ago

Please try this: https://ibm.box.com/s/ggb0m0tfoygb559gu66irqulhnnyew68

babsingh commented 2 years ago

Please try this: https://ibm.box.com/s/ggb0m0tfoygb559gu66irqulhnnyew68

Works; can download it.

babsingh commented 2 years ago

re https://github.com/eclipse-openj9/openj9/issues/14115#issuecomment-1078604220:

  1. decompileOuterFrame: creates the J2I frame with the correct O-slots.
  2. Bytecode frame for invokespecial created after from the J2I frame propogates NULL instead of InvocationHandler.
  3. There is a checkcast before and requireNonNull after the invokspecial for InvocationHandler. So, the O-slot is always expected to have a valid InvocationHandler.
  4. There is reflection involved and constructors are being invoked. There are write barriers associated to constructors.
  5. Are we missing a write barrier during the J2I transition or during creation of the bytecode frame after J2I?
  6. During performDecompile, new SP = 0x4351d0. This is the location where NULL is found instead of a InvocationHandler. Can operations in performDecompile lead to a NULL O-slot in the bytecode frame?
  7. I tried to reproduce the failure locally just by running the rc021 testcase in the cmdLineTester_jvmtitests_hcr_OSRG_nongold_2. No failures were seen in 250 runs. I was hoping to profile and observe the changes to the O-slots during the failure.

Bytecodes

<370b00>    !j9method 0x0000000000084010   java/util/Objects.requireNonNull(Ljava/lang/Object;)Ljava/lang/Object;
        [JIT Frame] 8 invokespecial 16 java/lang/NullPointerException.<init>()V
<370b00>    !j9method 0x00000000003D9FE8   java/lang/reflect/Proxy.<init>(Ljava/lang/reflect/InvocationHandler;)V
        [JIT Frame] 4 aload1
                    5 invokestatic 7 java/util/Objects.requireNonNull(Ljava/lang/Object;)Ljava/lang/Object;
<370b00>    !j9method 0x000000000076D838   com/sun/proxy/$Proxy8.<init>(Ljava/lang/reflect/InvocationHandler;)V
        [BC Frame]  0 aload0
                    1 aload1
                    2 invokespecial 10 java/lang/reflect/Proxy.<init>(Ljava/lang/reflect/InvocationHandler;)V
<370b00>    !j9method 0x00000000003BFDE8   jdk/internal/reflect/GeneratedConstructorAccessor210.newInstance([Ljava/lang/Object;)Ljava/lang/Object;
        [J2I Frame] 24 aaload
                    25 checkcast 4 java/lang/reflect/InvocationHandler
                    28 invokespecial 3 com/sun/proxy/$Proxy8.<init>(Ljava/lang/reflect/InvocationHandler;)V
<370b00>    !j9method 0x00000000001C1258   jdk/internal/reflect/DelegatingConstructorAccessorImpl.newInstance([Ljava/lang/Object;)Ljava/lang/Object;
        [JIT Frame] 5 invokevirtual 4 jdk/internal/reflect/ConstructorAccessorImpl.newInstance([Ljava/lang/Object;)Ljava/lang/Object;
<370b00>    !j9method 0x00000000000AD1A0   java/lang/reflect/Constructor.newInstance([Ljava/lang/Object;)Ljava/lang/Object;
        [JIT Frame] 66 aload2
                    67 aload1
                    68 invokeinterface2
                    70 invokeinterface 68 jdk/internal/reflect/ConstructorAccessor.newInstance([Ljava/lang/Object;)Ljava/lang/Object;

JIT operations before creation of the bytecode frame

20:34:24.600039000  0x370B00 j9codertvm(j9jit).57 Entry      >decompileMethodFrameIterator
20:34:24.600039000  0x370B00 j9codertvm(j9jit).58 Event       outgoing arg count is 0
20:34:24.600039000  0x370B00 j9codertvm(j9jit).63 Exit       <decompileMethodFrameIterator
20:34:24.600039000  0x370B00 j9codertvm(j9jit).57 Entry      >decompileMethodFrameIterator
20:34:24.600040000  0x370B00 j9codertvm(j9jit).61 Exit       <decompileMethodFrameIterator - finish: previous is JIT - copy preserved register values
20:34:24.600040000  0x370B00 j9vm.683             Exit       <WalkStackFrames - walkThread=0x370b00, rc=0
20:34:24.600040000  0x370B00 j9codertvm(j9jit).71 Entry      >performDecompile
20:34:24.600040000  0x370B00 j9codertvm(j9jit).75 Event       building J2I frame at 0x4351e8
20:34:24.600040000  0x370B00 j9codertvm(j9jit).76 Event       fixing top of decomp stack (0x7fdc80007b90) from 0x435268 to 0x435260 (pc = 0x7fdf1615e3f5)
20:34:24.600040000  0x370B00 j9codertvm(j9jit).114 Exit       <performDecompile - new SP = 0x4351d0, literals = 0x3bfde8, pc = 0x7fdc780038b9
20:34:24.600042000  0x370B00 j9vm.682             Entry      >WalkStackFrames - walkThread=0x370b00 flags=0x41c0000 sp=0x435198 a0=0x4351b0 pc=0x1 literals=0x0 els=0x7fdedd276b90 j2i=0x435268
20:34:24.600042000  0x370B00 j9vm.683             Exit       <WalkStackFrames - walkThread=0x370b00, rc=0
20:34:24.602693000  0x370B00 j9vm.682             Entry      >WalkStackFrames - walkThread=0x370b00 flags=0x1c0c0100 sp=0x435038 a0=0x435060 pc=0x3 literals=0x0 els=0x7fdedd276b90 j2i=0x435148
20:34:24.602697000  0x370B00 j9vm.683             Exit       <WalkStackFrames - walkThread=0x370b00, rc=0
pshipton commented 2 years ago

FYI the last recreation was https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_extended.functional_ppc64le_linux_Nightly_testList_1/247/

It doesn't happen in the builds all that often but it does still happen. I can list them for a while if it's helpful.

0xdaryl commented 2 years ago

I gave Babneet access to a x86 machine that can reproduce this problem 1/50 runs. I don't think you need to keep reporting failures here.