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.27k stars 720 forks source link

Can not load Minecraft snapshot #10356

Closed 1a2s3d4f1 closed 4 years ago

1a2s3d4f1 commented 4 years ago

Java -version output

openjdk version "1.8.0_265"
OpenJDK Runtime Environment (build 1.8.0_265-b01)
Eclipse OpenJ9 VM (build openj9-0.21.0, JRE 1.8.0 Windows 7 amd64-64-Bit Compres
sed References 20200728_776 (JIT enabled, AOT enabled)
OpenJ9   - 34cf4c075
OMR      - 113e54219
JCL      - c82ff0c20f based on jdk8u265-b01)

Summary of problem

Minecraft 1.16.2-rc2 or Minecraft 1.16.2 client can not load on openj9. These version can load on hotspot.

https://bugs.mojang.com/browse/MC-197271 (server)

Diagnostic files

Only instead prints a stack trace.

Exception in thread "main" java.lang.BootstrapMethodError: java.lang.ExceptionInInitializerError
    at hk.<clinit>(SourceFile:50)
    at gm.<clinit>(SourceFile:237)
    at vm.a(SourceFile:42)
    at net.minecraft.client.main.Main.main(SourceFile:137)
Caused by: java.lang.ExceptionInInitializerError
    at java.lang.J9VMInternals.ensureError(J9VMInternals.java:147)
    at java.lang.J9VMInternals.recordInitializationFailure(J9VMInternals.java:136)
    at java.lang.invoke.MethodHandle.getCPMethodHandleAt(Native Method)
    at java.lang.invoke.MethodHandle.getAdditionalBsmArg(MethodHandle.java:869)
    at java.lang.invoke.MethodHandle.resolveInvokeDynamic(MethodHandle.java:948)
    ... 4 more
Caused by: java.lang.NullPointerException
    at hk.a(SourceFile:88)
    at kk.a(SourceFile:20)
    at kk.<clinit>(SourceFile:13)
    ... 7 more
Camotoy commented 4 years ago

I can confirm this. Happens on Linux as well as Windows. 

openjdk version "1.8.0_252"
OpenJDK Runtime Environment (build 1.8.0_252-b09)
Eclipse OpenJ9 VM (build openj9-0.20.0, JRE 1.8.0 Linux amd64-64-Bit Compressed References 20200416_608 (JIT enabled, AOT enabled)
OpenJ9 - 05fa2d361
OMR - d4365f371
JCL - cfa47e66cd5 based on jdk8u252-b09)
openjdk version "11.0.7" 2020-04-14
OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.7+10)
Eclipse OpenJ9 VM AdoptOpenJDK (build openj9-0.20.0, JRE 11 Linux amd64-64-Bit Compressed References 20200416_574 (JIT enabled, AOT enabled)
OpenJ9 - 05fa2d361
OMR - d4365f371
JCL - 838028fc9d based on jdk-11.0.7+10)

Output of uname -a:

Linux [computername] 5.6.19-158.current #1 SMP PREEMPT Sun Jul 26 14:17:01 UTC 2020 x86_64 GNU/Linux

openjdk version "1.8.0_252"
OpenJDK Runtime Environment (build 1.8.0_252-b09)
Eclipse OpenJ9 VM (build openj9-0.20.0, JRE 1.8.0 Windows 10 amd64-64-Bit Compressed References 20200422_667 (JIT enabled, AOT enabled)
OpenJ9 - 05fa2d361
OMR - d4365f371
JCL - 5e623848e9 based on jdk8u252-b09)
syserr0r commented 4 years ago

Same for me, details in case it helps (Debian Buster with latest apt updates):

$ java -version
openjdk version "1.8.0_265"
OpenJDK Runtime Environment (build 1.8.0_265-b01)
Eclipse OpenJ9 VM (build openj9-0.21.0, JRE 1.8.0 Linux amd64-64-Bit Compressed References 20200728_727 (JIT enabled, AOT enabled)
OpenJ9   - 34cf4c075
OMR      - 113e54219
JCL      - c82ff0c20f based on jdk8u265-b01)
$ uname -a
Linux amp-02 4.19.0-9-amd64 #1 SMP Debian 4.19.118-2+deb10u1 (2020-06-07) x86_64 GNU/Linux
ChengJin01 commented 4 years ago

Let me do an initial investigation to see what happened as it was more or less related to MethodHandle.

ChengJin01 commented 4 years ago

@1a2s3d4f1, could you provide the downloading link for the Minecraft (java edition) or share the jar file with us (e.g. via Google Drive). It seems the software is not free for downloading.

Camotoy commented 4 years ago

@ChengJin01 The server software is free to download and the stack trace is printed on there.

Here is the Minecraft version before any errors happened (1.16.2pre1): https://launcher.mojang.com/v1/objects/d4434bf4f2f0572a4eb54b3da1b1b3069a4e9ef2/server.jar

Here is the server jar where the errors start to occur (1.16.2pre2): https://launcher.mojang.com/v1/objects/d2cae287324631b2b4bfa609dd01c63cd6d4b78d/server.jar

ChengJin01 commented 4 years ago

I reproduced the issue on 1.16.2pre2 (1.16.2pre1 works fine with OpenJ9) with the latest nightly build on JDK11 with the following command to trigger dumps:

$ ../jdk11_openj9/bin/java -Xint -Xdump:java+system+snap:events=throw,filter=*NullPointerException   -Xmx1024M -Xms1024M   -jar server.jar
JVMDUMP039I Processing dump event "throw", detail "java/lang/NullPointerException" at 2020/08/12 17:39:14 - please wait.
...
JVMDUMP013I Processed dump event "throw", detail "java/lang/NullPointerException".
Exception in thread "main" java.lang.ExceptionInInitializerError
    at java.base/java.lang.J9VMInternals.ensureError(J9VMInternals.java:186)
    at java.base/java.lang.J9VMInternals.recordInitializationFailure(J9VMInternals.java:175)
    at java.base/java.lang.invoke.MethodHandle.getCPMethodHandleAt(Native Method)
    at java.base/java.lang.invoke.MethodHandle.getAdditionalBsmArg(MethodHandle.java:935)
    at java.base/java.lang.invoke.MethodHandle.resolveInvokeDynamic(MethodHandle.java:1084)
    at hk.<clinit>(SourceFile:50)
    at gm.<clinit>(SourceFile:237)
    at vm.a(SourceFile:42)
    at net.minecraft.server.Main.main(SourceFile:88)
Caused by: java.lang.NullPointerException <-------
    at hk.a(SourceFile:88)
    at kk.a(SourceFile:20)
    at kk.<clinit>(SourceFile:13)
    ... 7 more

Looking at the java core:

1XMCURTHDINFO  Current thread
3XMTHREADINFO      "main" J9VMThread:0x0000000000016700, omrthread_t:0x00007F44B001C690, java/lang/Thread:0x00000000F8004000, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x1, isDaemon:false)
3XMTHREADINFO1            (native thread ID:0x1E3A, native priority:0x5, native policy:UNKNOWN, vmstate:R, vm thread flags:0x00001020)
3XMTHREADINFO2            (native stack address range from:0x00007F44B51AE000, to:0x00007F44B59AF000, size:0x801000)
3XMCPUTIME               CPU usage total: 3.824697809 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=41066240 (0x2729F00)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at hk.a(SourceFile:88)
4XESTACKTRACE                at kk.a(SourceFile:20)
4XESTACKTRACE                at kk.<clinit>(SourceFile:13)
4XESTACKTRACE                at java/lang/invoke/MethodHandle.getCPMethodHandleAt(Native Method)
4XESTACKTRACE                at java/lang/invoke/MethodHandle.getAdditionalBsmArg(MethodHandle.java:935)
4XESTACKTRACE                at java/lang/invoke/MethodHandle.resolveInvokeDynamic(MethodHandle.java:1084)
4XESTACKTRACE                at hk.<clinit>(SourceFile:50)
4XESTACKTRACE                at gm.<clinit>(SourceFile:237)
4XESTACKTRACE                at vm.a(SourceFile:42)
4XESTACKTRACE                at net/minecraft/server/Main.main(SourceFile:88)

against the system core in DDR:

> !threads
    !stack 0x00016700   !j9vmthread 0x00016700  !j9thread 0x7f44b001c690    tid 0x1e3a (7738) // (main)
...
> !stack 0x00016700
<16700>                             Generic special frame
<16700>     !j9method 0x000000000053D018   hk.a(Lgm;Lvk;Ljava/lang/Object;)Ljava/lang/Object; <-----
<16700>     !j9method 0x0000000000543668   kk.a(Lcoh;)Lcoh;
<16700>     !j9method 0x00000000005436A8   kk.<clinit>()V
<16700>                             JNI call-in frame
<16700>     !j9method 0x000000000002D020   java/lang/invoke/MethodHandle.getCPMethodHandleAt(Ljava/lang/Object;I)Ljava/lang/invoke/MethodHandle;
<16700>     !j9method 0x000000000002D080   java/lang/invoke/MethodHandle.getAdditionalBsmArg(Lcom/ibm/oti/vm/VMLangAccess;Ljava/lang/Object;Ljava/lang/Class;Ljava/lang/invoke/MethodHandle;JII)Ljava/lang/Object;
<16700>     !j9method 0x000000000002D100   java/lang/invoke/MethodHandle.resolveInvokeDynamic(JLjava/lang/String;Ljava/lang/String;J)Ljava/lang/invoke/MethodHandle;
...

> !stackslots 0x00016700
<16700> *** BEGIN STACK WALK, flags = 00400001 walkThread = 0x0000000000016700 ***
<16700>     ITERATE_O_SLOTS
<16700>     RECORD_BYTECODE_PC_OFFSET
<16700> Initial values: walkSP = 0x00000000000CEAE8, PC = 0x0000000000000001, literals = 0x0000000000000000, A0 = 0x00000000000CEB00, j2iFrame = 0x0000000000000000, ELS = 0x00007F44B59ABB70, decomp = 0x0000000000000000
<16700> Generic special frame: bp = 0x00000000000CEB00, sp = 0x00000000000CEAE8, pc = 0x0000000000000001, cp = 0x0000000000000000, arg0EA = 0x00000000000CEB00, flags = 0x0000000000000000

<16700> Bytecode frame: bp = 0x00000000000CEB18, sp = 0x00000000000CEB08, pc = 0x00007F44B0654539, cp = 0x0000000000541090, arg0EA = 0x00000000000CEB30, flags = 0x0000000000000000
<16700>     Method: hk.a(Lgm;Lvk;Ljava/lang/Object;)Ljava/lang/Object; !j9method 0x000000000053D018 <---
<16700>     Bytecode index = 5 <----------------
<16700>     Using local mapper
<16700>     Locals starting at 0x00000000000CEB30 for 0x0000000000000003 slots
<16700>         I-Slot: a0[0x00000000000CEB30] = 0x0000000000000000 <----- the passed-in gm was NULL
<16700>         O-Slot: a1[0x00000000000CEB28] = 0x00000000FA4C3338 <---- vk
<16700>         O-Slot: a2[0x00000000000CEB20] = 0x00000000FA575828  <---- coh

> !j9object  0x00000000FA4C3338
!J9Object 0x00000000FA4C3338 {
    struct J9Class* clazz = !j9class 0x453900 // vk
    Object flags = 0x00000000;
    I lockword = 0x00000000 (offset = 0) (java/lang/Object) <hidden>
    Ljava/lang/String; b = !fj9object 0xc00b4fe8 (offset = 4) (vk)
    Ljava/lang/String; c = !fj9object 0xc00ce408 (offset = 8) (vk)
}
> !j9object  0x00000000FA575828
!J9Object 0x00000000FA575828 {
    struct J9Class* clazz = !j9class 0x544000 // coh
    Object flags = 0x00000000;
    I lockword = 0x00000000 (offset = 0) (java/lang/Object) <hidden>
    Lvk; d = !fj9object 0xfa4c3338 (offset = 4) (coh)
    Ljava/util/List; e = !fj9object 0xfa623918 (offset = 8) (coh)
    Ljava/util/List; f = !fj9object 0xfa623930 (offset = 12) (coh)
    Lvk; g = !fj9object 0xfa4c3338 (offset = 16) (coh)
    I h = 0x80000000 (offset = 20) (coh)

> !bytecodes 0x000000000053D018
  Name: a
  Signature: (Lgm;Lvk;Ljava/lang/Object;)Ljava/lang/Object;
  Access Flags (3040009): public static 
  Max Stack: 4
  Argument Count: 3
  Temp Count: 0

    0 aload0 
    1 checkcast 16 gs
    4 aload0 
    5 invokevirtual 22 gm.f()Lvj;    <------- the null point exception was thrown out here due to the NULL value of gm
    8 aload1 
    9 invokestatic 23 vj.a(Lvj;Lvk;)Lvj;
   12 aload2 
   13 invokestatic 5 com/mojang/serialization/Lifecycle.stable()Lcom/mojang/serialization/Lifecycle;
   16 invokevirtual 17 gs.a(Lvj;Ljava/lang/Object;Lcom/mojang/serialization/Lifecycle;)Ljava/lang/Object;
   19 return1 

<16700> Bytecode frame: bp = 0x00000000000CEB48, sp = 0x00000000000CEB38, pc = 0x00007F44B0656F70, cp = 0x0000000000543480, arg0EA = 0x00000000000CEB50, flags = 0x0000000000000000
<16700>     Method: kk.a(Lcoh;)Lcoh; !j9method 0x0000000000543668
<16700>     Bytecode index = 8
<16700>     Using local mapper
<16700>     Locals starting at 0x00000000000CEB50 for 0x0000000000000001 slots
<16700>         I-Slot: a0[0x00000000000CEB50] = 0x00000000FA575828

> !bytecodes 0x0000000000543668
  Name: a
  Signature: (Lcoh;)Lcoh;
  Access Flags (1040009): public static 
  Max Stack: 3
  Argument Count: 1
  Temp Count: 0

    0 getstatic 6 hk.h Lgm; <-----  gm was set to NULL here before calling hk.a()
    3 aload0 
    4 invokevirtual 7 coh.b()Lvk;
    7 aload0 
    8 invokestatic 8 hk.a(Lgm;Lvk;Ljava/lang/Object;)Ljava/lang/Object;
   11 checkcast 4 coh
   14 return1

Based on the investigation above, the NullPointerException issue with hk.a(Lgm;Lvk;Ljava/lang/Object;)Ljava/lang/Object; was triggered by a passed-in NULL value for gm, in which case there is nothing more we can do in OpenJ9 given that the source code involved above come from Minecraft.

So I think Minecraft developers need to get involved to double-check their code there to see why a NULL value for gm was passed in hk.a() at this point.

iczero commented 4 years ago

I believe it is an OpenJ9 issue. The affected code (mappings from FabricMC/yarn) is located within the static initializer (<clinit>) of net.minecraft.util.registry.BuiltinRegistry. 

      STRUCTURE_POOL = addRegistry(Registry.TEMPLATE_POOL_WORLDGEN, StructurePools::initDefaultPools);
      BIOME = addRegistry(Registry.BIOME_KEY, () -> {
         return Biomes.PLAINS;
      });
      CHUNK_GENERATOR_SETTINGS = addRegistry(Registry.NOISE_SETTINGS_WORLDGEN, ChunkGeneratorSettings::getInstance);
      DEFAULT_VALUE_SUPPLIERS.forEach((identifier, supplier) -> {
         if (supplier.get() == null) {
            LOGGER.error("Unable to bootstrap registry '{}'", identifier);
         }
      });

The OpenJ9 VM will run the static initializer for the StructurePools and ChunkGeneratorSettings classes due to the method references, but those classes depend on BuiltinRegistry to have already run its static initializer. This in turn causes a NullPointerException. The HotSpot VM will not run the static initializers until the method references are actually called later on in the forEach loop, which prevents the exception from occurring.

Edit: wrote a fabric mod that seems to fix it: https://github.com/iczero/fabric-openj9compat

ChengJin01 commented 4 years ago

@iczero, considering the difference of triggering the static initialization in implementation between OpenJ9 and Hotspot, I don't think we support the lazy static initialization in the existing code of OpenJ9.

The static initialization is triggered for the the specified class immediately if it has <clinit> in our code. If we have to match Hotspot's behaviour in such case, technically we might need to move sendClinit from initializeImpl() to somewhere in the interpreter which might break the original design of OpenJ9 in such case:

/runtime/vm/ClassInitialization.cpp
void
initializeImpl(J9VMThread *currentThread, J9Class *clazz)
{
...
    if (J9ROMCLASS_HAS_CLINIT(clazz->romClass)) {
        sendClinit(currentThread, clazz); <-------
}

@gacholio & @DanHeidinga, any input at this point in case of something I am unaware of?

ishland commented 4 years ago

Edit: wrote a fabric mod that seems to fix it: https://github.com/iczero/fabric-openj9compat

It works just fine with the mod. But this is a temporary solution and fixes should be worked on.

ChengJin01 commented 4 years ago

@iczero, is there any simple test code for us (or similar to the code in Minecraft) to demonstrate your findings in OpenJ9 as compared to Hotspot?

Based on JVM Spec, <clinit> is called whenever a static field or method is accessed, or when an instance is created, in which case we follow the JVM Spec to trigger <clinit>. So we'd like to have a simple test to see what really happened to our code.

iczero commented 4 years ago

This seems to work:

public class Test {
    public static class Class1 {
        public static void dummyMethod() {
            System.out.println("Class1.dummyMethod: Class2.a is " + Class2.a);
        }

        static {
            System.out.println("Class1.<clinit>: Class2.a is " + Class2.a);
        }
    }

    public static class Class2 {
        public static float a = 0;
        public static Runnable runnable; 

        // dummy method to trigger <clinit>
        public static void init() {}

        static {
            System.out.println("Class2.<clinit> called");
            System.out.println("obtaining method reference to Class1.dummyMethod");
            runnable = Class1::dummyMethod;
            System.out.println("incrementing Class2.a");
            a++;
            System.out.println("running Class1.dummyMethod via method reference");
            runnable.run();
        }
    }

    public static void main(String[] args) {
        Class2.init();
    }
}

Output on HotSpot:

Class2.<clinit> called
obtaining method reference to Class1.dummyMethod
incrementing Class2.a
running Class1.dummyMethod via method reference
Class1.<clinit>: Class2.a is 1.0
Class1.dummyMethod: Class2.a is 1.0

Output on OpenJ9:

Class2.<clinit> called
obtaining method reference to Class1.dummyMethod
Class1.<clinit>: Class2.a is 0.0
incrementing Class2.a
running Class1.dummyMethod via method reference
Class1.dummyMethod: Class2.a is 1.0
gacholio commented 4 years ago

The Class1::dummyMethod produces this:

   20 JBinvokedynamic 0 run()Ljava/lang/Runnable; bsm 0 java/lang/invoke/LambdaMetafactory.metafactory(Ljava/lang/invoke/MethodHandles$Lookup;Ljava/lang/String;Ljava/lang/invoke/MethodType;Ljava/lang/invoke/MethodType;Ljava/lang/invoke/MethodHandle;Ljava/lang/invoke/MethodType;)Ljava/lang/invoke/CallSite;
gacholio commented 4 years ago

We may well be initializing the class too early in the MethodHandle code.

@DanHeidinga - you may recall exactly where this is done.

ChengJin01 commented 4 years ago

If so, it might be related to the code as follows:

/runtime/vm/MHInterpreter.cpp
VM_MHInterpreter::dispatchLoop(j9object_t methodHandle)
{
...
        case J9_METHOD_HANDLE_KIND_STATIC: {
            methodHandle = initializeClassIfNeeded(methodHandle); <-------
            /* fall through */
        }

    VMINLINE j9object_t
    initializeClassIfNeeded(j9object_t methodHandle)
    {
        J9Class *defc = getPrimitiveHandleDefc(methodHandle);
        if (VM_VMHelpers::classRequiresInitialization(_currentThread, defc)) { <------------
            /* Build frame, make pointers A0-relative offsets, and save methodHandle */
            UDATA *spPriorToFrameBuild = _currentThread->sp;
            J9SFMethodTypeFrame *frame = buildMethodTypeFrame(_currentThread, getMethodHandleMethodType(methodHandle));
            IDATA spOffset = spPriorToFrameBuild - _currentThread->arg0EA;
            IDATA frameOffset = (UDATA*)frame - _currentThread->arg0EA;
            VM_VMHelpers::pushObjectInSpecialFrame(_currentThread, methodHandle);

            /* Call defc.<clinit> */
            initializeClass(_currentThread, defc); <------

    /**
     * Checks whether the class must be initialized before using it.
     *
     * Classes which have been successfully initialized or are in the process
     * of being initialized by the current thread do not need to be initialized.
     *
     * @param currentThread[in] the current J9VMThread
     * @param j9clazz[in] the J9Class to query
     *
     * @returns true if the class requires initialization, false if not
     */
    static VMINLINE bool
    classRequiresInitialization(J9VMThread *currentThread, J9Class *j9clazz) <---------
    {
        bool requiresInitialization = true;
        UDATA initStatus = j9clazz->initializeStatus;
        if ((J9ClassInitSucceeded == initStatus) || (((UDATA)currentThread) == initStatus)) { <------
            requiresInitialization = false;
        }
        return requiresInitialization;
    }
gacholio commented 4 years ago

Please start investigating moving the initialization to the point of static method invoke, static field read/write and instantiation (if there is such a thing in the MH code).

Handles should operate like the bytecodes they replace - until the actual point of access, the class should remain uninitialized.

It's probably also worth investigating the old reflection behaviour - I don't recall if it's specced to initalize the class on lookup or access.

DanHeidinga commented 4 years ago

The MH code should be doing the right thing for initializing classes when static methods / static fields / etc are invoked.

Based on the output from the <clinit> printfs, I'd check the sendResolveMethodHandle and sendResolveInvokeDynamic paths as well the code that cracks a MethodHandle into a MethodHandleInfo. It's something in that path that's forcing the init - maybe a class lookup as part of building a MethodTyoe?

gacholio commented 4 years ago

@cheng Any update here?

ChengJin01 commented 4 years ago

@gacholio,

I went through the stacktrace on the calling path to Test$Class1.<clinit>:

Thread 2 "main" hit Breakpoint 1, VM_MHInterpreter::dispatchLoop (this=0x7ffff7d443d0, methodHandle=0x7fff827b8)
    at MHInterpreter.cpp:148
148             methodHandle = initializeClassIfNeeded(methodHandle);
(gdb) bt
#0  VM_MHInterpreter::dispatchLoop (this=0x7ffff7d443d0, methodHandle=0x7fff827b8) at MHInterpreter.cpp:148
#1  0x00007ffff72a5b7e in VM_BytecodeInterpreterCompressed::interpretMethodHandle (this=0x7ffff7d449d0, 
    _sp=@0x7ffff7d44940: 0xceba8, _pc=@0x7ffff7d44948: 0x7fffd19d5122 <incomplete sequence \351\251>, methodHandle=0x7fff91c78)
    at BytecodeInterpreter.hpp:169
#2  0x00007ffff72c78a7 in VM_BytecodeInterpreterCompressed::run (this=0x7ffff7d449d0, vmThread=0x16700)
    at BytecodeInterpreter.hpp:9554
#3  0x00007ffff729c0e5 in bytecodeLoopCompressed (currentThread=0x16700) at BytecodeInterpreter.inc:110
#4  0x00007ffff73dddd2 in c_cInterpreter () at xcinterp.s:160
#5  0x00007ffff7364c15 in sendResolveInvokeDynamic (currentThread=0x16700, ramCP=0x13e220, callSiteIndex=1, 
    nameAndSig=0x7ffff4129670, bsmData=0x7ffff4129746) at callin.cpp:1029
#6  0x00007ffff73c2a5a in resolveInvokeDynamic (vmThread=0x16700, ramCP=0x13e220, callSiteIndex=1, resolveFlags=0)
    at resolvesupport.cpp:2127
#7  0x00007ffff72ba8e9 in VM_BytecodeInterpreterCompressed::invokedynamic (this=0x7ffff7d45320, _sp=@0x7ffff7d45290: 0xcecf0, 
    _pc=@0x7ffff7d45298: 0x1 <error: Cannot access memory at address 0x1>) at BytecodeInterpreter.hpp:8030
#8  0x00007ffff72dbc57 in VM_BytecodeInterpreterCompressed::run (this=0x7ffff7d45320, vmThread=0x16700)
    at BytecodeInterpreter.hpp:10295
#9  0x00007ffff729c0e5 in bytecodeLoopCompressed (currentThread=0x16700) at BytecodeInterpreter.inc:110
#10 0x00007ffff73dddd2 in c_cInterpreter () at xcinterp.s:160
#11 0x00007ffff7361d17 in sendClinit (currentThread=0x16700, clazz=0x13e300) at callin.cpp:419
#12 0x00007ffff72de5d2 in initializeImpl (currentThread=0x16700, clazz=0x13e300) at ClassInitialization.cpp:120
#13 0x00007ffff72e0aeb in classInitStateMachine (currentThread=0x16700, clazz=0x13e300, desiredState=J9_CLASS_INIT_INITIALIZED)
    at ClassInitialization.cpp:763
#14 0x00007ffff72df420 in initializeClass (currentThread=0x16700, clazz=0x13e300) at ClassInitialization.cpp:335
#15 0x00007ffff73bda71 in resolveStaticMethodRefInto (vmStruct=0x16700, ramCP=0x13e0b0, cpIndex=20, resolveFlags=0, 
    ramCPEntry=0x167f8) at resolvesupport.cpp:533 <--------------------
#16 0x00007ffff73bdb7a in resolveStaticMethodRef (vmStruct=0x16700, ramCP=0x13e0b0, cpIndex=20, resolveFlags=0)
    at resolvesupport.cpp:568
#17 0x00007ffff73c1d08 in resolveMethodHandleRefInto (vmThread=0x16700, ramCP=0x13e0b0, cpIndex=17, resolveFlags=0, 
    ramCPEntry=0x13e1c0) at resolvesupport.cpp:1904
#18 0x00007ffff73c1ff7 in resolveMethodHandleRef (vmThread=0x16700, ramCP=0x13e0b0, cpIndex=17, resolveFlags=0)
    at resolvesupport.cpp:1976
#19 0x00007ffff618a049 in Java_java_lang_invoke_MethodHandle_getCPMethodHandleAt (env=0x16700, unusedClass=0x2d630, 
    constantPoolOop=0xced98, cpIndex=17) at common/sun_reflect_ConstantPool.c:755
#20 0x00007ffff7475fe8 in ffi_call_unix64 () at x86/unix64.S:76
#21 0x00007ffff74755d0 in ffi_call (cif=0x7ffff7d45ab0, fn=0x7ffff6189f14 <Java_java_lang_invoke_MethodHandle_getCPMethodHandleAt>, 
    rvalue=0x16818, avalue=0x7ffff7d45b50) at x86/ffi64.c:525
#22 0x00007ffff72ab60a in VM_BytecodeInterpreterCompressed::cJNICallout (this=0x7ffff7d46400, _sp=@0x7ffff7d46370: 0xced68, 
    _pc=@0x7ffff7d46378: 0x7 <error: Cannot access memory at address 0x7>, receiverAddress=0x2d630, javaArgs=0xceda0, 
    returnType=0x7ffff7d45d43 "\t", returnStorage=0x16818, 
    function=0x7ffff6189f14 <Java_java_lang_invoke_MethodHandle_getCPMethodHandleAt>, isStatic=true) at BytecodeInterpreter.hpp:2436
#23 0x00007ffff72ab011 in VM_BytecodeInterpreterCompressed::callCFunction (this=0x7ffff7d46400, _sp=@0x7ffff7d46370: 0xced68, 
    _pc=@0x7ffff7d46378: 0x7 <error: Cannot access memory at address 0x7>, 
    jniMethodStartAddress=0x7ffff6189f14 <Java_java_lang_invoke_MethodHandle_getCPMethodHandleAt>, receiverAddress=0x2d630, 
    javaArgs=0xced98, bp=0x7ffff7d45d50, isStatic=true, returnType=0x7ffff7d45d43 "\t") at BytecodeInterpreter.hpp:2276
#24 0x00007ffff72aa85e in VM_BytecodeInterpreterCompressed::runJNINative (this=0x7ffff7d46400, _sp=@0x7ffff7d46370: 0xced68, 
    _pc=@0x7ffff7d46378: 0x7 <error: Cannot access memory at address 0x7>) at BytecodeInterpreter.hpp:2168
#25 0x00007ffff72c76aa in VM_BytecodeInterpreterCompressed::run (this=0x7ffff7d46400, vmThread=0x16700)
    at BytecodeInterpreter.hpp:9537
#26 0x00007ffff729c0e5 in bytecodeLoopCompressed (currentThread=0x16700) at BytecodeInterpreter.inc:110
#27 0x00007ffff73dddd2 in c_cInterpreter () at xcinterp.s:160
#28 0x00007ffff7364c15 in sendResolveInvokeDynamic (currentThread=0x16700, ramCP=0x13e0b0, callSiteIndex=0, 
    nameAndSig=0x7ffff4129358, bsmData=0x7ffff4129466) at callin.cpp:1029
#29 0x00007ffff73c2a5a in resolveInvokeDynamic (vmThread=0x16700, ramCP=0x13e0b0, callSiteIndex=0, resolveFlags=0)
    at resolvesupport.cpp:2127
#30 0x00007ffff72ba8e9 in VM_BytecodeInterpreterCompressed::invokedynamic (this=0x7ffff7d46d50, _sp=@0x7ffff7d46cc0: 0xcef38, 
    _pc=@0x7ffff7d46cc8: 0x1 <error: Cannot access memory at address 0x1>) at BytecodeInterpreter.hpp:8030
#31 0x00007ffff72dbc57 in VM_BytecodeInterpreterCompressed::run (this=0x7ffff7d46d50, vmThread=0x16700)
    at BytecodeInterpreter.hpp:10295
#32 0x00007ffff729c0e5 in bytecodeLoopCompressed (currentThread=0x16700) at BytecodeInterpreter.inc:110
#33 0x00007ffff73dddd2 in c_cInterpreter () at xcinterp.s:160
#34 0x00007ffff7361d17 in sendClinit (currentThread=0x16700, clazz=0x13df00) at callin.cpp:419
#35 0x00007ffff72de5d2 in initializeImpl (currentThread=0x16700, clazz=0x13df00) at ClassInitialization.cpp:120
#36 0x00007ffff72e0aeb in classInitStateMachine (currentThread=0x16700, clazz=0x13df00, desiredState=J9_CLASS_INIT_INITIALIZED)
    at ClassInitialization.cpp:763
#37 0x00007ffff72df420 in initializeClass (currentThread=0x16700, clazz=0x13df00) at ClassInitialization.cpp:335
#38 0x00007ffff73bda71 in resolveStaticMethodRefInto (vmStruct=0x16700, ramCP=0x13ddb0, cpIndex=2, resolveFlags=32, 
    ramCPEntry=0x167f8) at resolvesupport.cpp:533  <------ Test$Class2.<clinit>()V
#39 0x00007ffff73bdb7a in resolveStaticMethodRef (vmStruct=0x16700, ramCP=0x13ddb0, cpIndex=2, resolveFlags=32)
    at resolvesupport.cpp:568
#40 0x00007ffff72a9c04 in VM_BytecodeInterpreterCompressed::initialStaticMethod (this=0x7ffff7d47810, _sp=@0x7ffff7d47780: 0xcefa0, 
    _pc=@0x7ffff7d47788: 0x1 <error: Cannot access memory at address 0x1>) at BytecodeInterpreter.hpp:1927
#41 0x00007ffff72be4d7 in VM_BytecodeInterpreterCompressed::run (this=0x7ffff7d47810, vmThread=0x16700)
--Type <RET> for more, q to quit, c to continue without paging--
    at BytecodeInterpreter.hpp:9242
#42 0x00007ffff729c0e5 in bytecodeLoopCompressed (currentThread=0x16700) at BytecodeInterpreter.inc:110
#43 0x00007ffff73dddd2 in c_cInterpreter () at xcinterp.s:160
#44 0x00007ffff7365002 in runCallInMethod (env=0x16700, receiver=0x0, clazz=0xcf020, methodID=0x7ffff0201508, args=0x7ffff7d47d78)
    at callin.cpp:1083
#45 0x00007ffff7387f44 in gpProtectedRunCallInMethod (entryArg=0x7ffff7d47d10) at jnicsup.cpp:259
#46 0x00007ffff73edc2e in signalProtectAndRunGlue (portLibrary=0x7ffff7544e00 <j9portLibrary>, userData=0x7ffff7d47cc0)
    at jniprotect.c:45
#47 0x00007ffff70ac647 in omrsig_protect (portLibrary=0x7ffff7544e00 <j9portLibrary>, fn=0x7ffff73edbfe <signalProtectAndRunGlue>, 
    fn_arg=0x7ffff7d47cc0, handler=0x7ffff73804f8 <structuredSignalHandler>, handler_arg=0x16700, flags=506, result=0x7ffff7d47ca8)
    at ../../omr/port/unix/omrsignal.c:425
#48 0x00007ffff73edd97 in gpProtectAndRun (function=0x7ffff7387ee3 <gpProtectedRunCallInMethod(void*)>, env=0x16700, 
    args=0x7ffff7d47d10) at jniprotect.c:78
#49 0x00007ffff73884eb in gpCheckCallin (env=0x16700, receiver=0x0, cls=0xcf020, methodID=0x7ffff0201508, args=0x7ffff7d47d78)
    at jnicsup.cpp:447
#50 0x00007ffff7387238 in callStaticVoidMethod (env=0x16700, cls=0xcf020, methodID=0x7ffff0201508) at jnicgen.c:288
                          <----- Test.main([Ljava/lang/String;)V
#51 0x00007ffff7fb8016 in JavaMain (_args=0x7fffffffab90)
    at /home/jincheng/X86_64_OPENJ9/openj9-openjdk-jdk11/src/java.base/share/native/libjli/java.c:549
#52 0x00007ffff7d70609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#53 0x00007ffff7ece103 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(gdb) frame 15
#15 0x00007ffff73bda71 in resolveStaticMethodRefInto (vmStruct=0x16700, ramCP=0x13e0b0, cpIndex=20, resolveFlags=0, 
    ramCPEntry=0x167f8) at resolvesupport.cpp:533
533                 initializeClass(vmStruct, methodClass);
(gdb) list
528         if (initStatus != J9ClassInitSucceeded && initStatus != (UDATA)vmStruct) {
529             /* Initialize the class if java code is allowed */
530             if (canRunJavaCode) {
531                 UDATA preCount = vmStruct->javaVM->hotSwapCount;
532 
533                 initializeClass(vmStruct, methodClass);
534                 if (threadEventsPending(vmStruct)) {
535                     method = NULL;
536                     goto done;
537                 }

(gdb) frame 15
#15 0x00007ffff73bda71 in resolveStaticMethodRefInto (vmStruct=0x16700, ramCP=0x13e0b0, cpIndex=20, resolveFlags=0, 
    ramCPEntry=0x167f8) at resolvesupport.cpp:533
533                 initializeClass(vmStruct, methodClass);
(gdb) info locals
preCount = 0
methodClass = 0x13e300
initStatus = 3  <-----------------  J9ClassInitUnverified 0x3
romMethodRef = 0x7ffff4129308
resolvedClass = 0x13e300

plus the corresponding java stacktrace as follows:

> !stack 0x00016700
<16700>     !j9method 0x000000000002D0A0   java/lang/invoke/MethodHandle.invokeBsm(Ljava/lang/invoke/MethodHandle;[Ljava/lang/Object;)Ljava/lang/Object;
<16700>     !j9method 0x000000000002D100   java/lang/invoke/MethodHandle.resolveInvokeDynamic(JLjava/lang/String;Ljava/lang/String;J)Ljava/lang/invoke/MethodHandle;
<16700>                             JNI call-in frame
<16700>                             Generic special frame
<16700>     !j9method 0x000000000013E4F8   Test$Class1.<clinit>()V
<16700>                             JNI call-in frame
<16700>     !j9method 0x000000000002D020   java/lang/invoke/MethodHandle.getCPMethodHandleAt(Ljava/lang/Object;I)Ljava/lang/invoke/MethodHandle;
<16700>     !j9method 0x000000000002D080   java/lang/invoke/MethodHandle.getAdditionalBsmArg(Lcom/ibm/oti/vm/VMLangAccess;Ljava/lang/Object;Ljava/lang/Class;Ljava/lang/invoke/MethodHandle;JII)Ljava/lang/Object;
<16700>     !j9method 0x000000000002D100   java/lang/invoke/MethodHandle.resolveInvokeDynamic(JLjava/lang/String;Ljava/lang/String;J)Ljava/lang/invoke/MethodHandle; <----------
<16700>                             JNI call-in frame
<16700>                             Generic special frame
<16700>     !j9method 0x000000000013DE98   Test$Class2.<clinit>()V
<16700>                             JNI call-in frame
<16700>                             Generic special frame
<16700>     !j9method 0x000000000013DE28   Test.main([Ljava/lang/String;)V
<16700>                             JNI call-in frame
<16700>                             Native method frame

It seems the static initialization of Test$Class1.<clinit>()V came from the same place as Test$Class2.<clinit>()V in resolveStaticMethodRefInto at /runtime/vm/resolvesupport.cpp`

J9Method *   
resolveStaticMethodRefInto(J9VMThread *vmStruct, J9ConstantPool *ramCP, UDATA cpIndex, UDATA resolveFlags, J9RAMStaticMethodRef *ramCPEntry)
{
  ...
    method = (J9Method *)javaLookupMethod(vmStruct, resolvedClass, J9ROMMETHODREF_NAMEANDSIGNATURE(romMethodRef), cpClass, lookupOptions);

    Trc_VM_resolveStaticMethodRef_lookupMethod(vmStruct, method);

    if (method == NULL) {
        goto done;
    }
 ...
    /* Initialize the defining class of the method. */

    if (J9_ARE_NO_BITS_SET(resolveFlags, J9_RESOLVE_FLAG_NO_CLASS_INIT)) {
        J9Class *methodClass = J9_CLASS_FROM_METHOD(method);
        UDATA initStatus = methodClass->initializeStatus;
        if (jitCompileTimeResolve && (J9ClassInitSucceeded != initStatus)) {
            method = NULL;
            goto done;
        }
        if (initStatus != J9ClassInitSucceeded && initStatus != (UDATA)vmStruct) { <-------------
            /* Initialize the class if java code is allowed */
            if (canRunJavaCode) {
                UDATA preCount = vmStruct->javaVM->hotSwapCount;
    initializeClass(vmStruct, methodClass);  <-------- calling Test$Class2.<clinit> and later Test$Class1.<clinit>from there
                if (threadEventsPending(vmStruct)) {
                    method = NULL;
                    goto done;
                }

I didn't notice there is anything illogical along the calling path in dealing with <clinit> of Test$Class2 and later with <clinit> of Test$Class1 (we didn't force to initilze Test$Class1 given it was based on the value of initStatus)

The problem with this test case above is there is dependency between Test$Class1.<clinit> and Test$Class2.<clinit>, in which case 1Test$Class2.requiresTest$Class1to be initilized first butTest$Class1.` has to access the static field of Test$Class2 being initialized)

From the code perspective, if we prevent initiliazating Test$Class1 in resolveStaticMethodRefInto, it also disable Test$Class2.<clinit> at the same place.

ChengJin01 commented 4 years ago

It seems the only difference between Test$Class1.<clinit> and Test$Class2.<clinit> is the value of resolveFlags given it was set up on different calling paths as follows:

[1] Test$Class1.: resolveFlags = 0 = J9_RESOLVE_FLAG_RUNTIME_RESOLVE

#14 0x00007ffff72df420 in initializeClass (currentThread=0x16700, clazz=0x13e300) at ClassInitialization.cpp:335
#15 0x00007ffff73bda71 in resolveStaticMethodRefInto (vmStruct=0x16700, ramCP=0x13e0b0, cpIndex=20, resolveFlags=0, <------
    ramCPEntry=0x167f8) at resolvesupport.cpp:533
#16 0x00007ffff73bdb7a in resolveStaticMethodRef (vmStruct=0x16700, ramCP=0x13e0b0, cpIndex=20, resolveFlags=0)
    at resolvesupport.cpp:568
#17 0x00007ffff73c1d08 in resolveMethodHandleRefInto (vmThread=0x16700, ramCP=0x13e0b0, cpIndex=17, resolveFlags=0, 
    ramCPEntry=0x13e1c0) at resolvesupport.cpp:1904
#18 0x00007ffff73c1ff7 in resolveMethodHandleRef (vmThread=0x16700, ramCP=0x13e0b0, cpIndex=17, resolveFlags=0)
    at resolvesupport.cpp:1976
#19 0x00007ffff618a049 in Java_java_lang_invoke_MethodHandle_getCPMethodHandleAt (env=0x16700, unusedClass=0x2d630, 
    constantPoolOop=0xced98, cpIndex=17) at common/sun_reflect_ConstantPool.c:755 <-------

against the code at common/sun_reflect_ConstantPool.c:

Java_java_lang_invoke_MethodHandle_getCPMethodHandleAt(JNIEnv *env, jclass unusedClass, jobject constantPoolOop, jint cpIndex)
{
...
            if (NULL == methodHandleObject) {
---> methodHandleObject = vmFunctions->resolveMethodHandleRef(vmThread, J9_CP_FROM_CLASS(ramClass), cpIndex, J9_RESOLVE_FLAG_RUNTIME_RESOLVE);
            }

[2] Test$Class2.: resolveFlags = 32 = J9_RESOLVE_FLAG_RUNTIME_RESOLVE | J9_RESOLVE_FLAG_CHECK_CLINIT

#37 0x00007ffff72df420 in initializeClass (currentThread=0x16700, clazz=0x13df00) at ClassInitialization.cpp:335
#38 0x00007ffff73bda71 in resolveStaticMethodRefInto (vmStruct=0x16700, ramCP=0x13ddb0, cpIndex=2, resolveFlags=32, <------
    ramCPEntry=0x167f8) at resolvesupport.cpp:533
#39 0x00007ffff73bdb7a in resolveStaticMethodRef (vmStruct=0x16700, ramCP=0x13ddb0, cpIndex=2, resolveFlags=32)
    at resolvesupport.cpp:568
#40 0x00007ffff72a9c04 in VM_BytecodeInterpreterCompressed::initialStaticMethod (this=0x7ffff7d47810, _sp=@0x7ffff7d47780: 0xcefa0, 
    _pc=@0x7ffff7d47788: 0x1 <error: Cannot access memory at address 0x1>) at BytecodeInterpreter.hpp:1927

against the code at BytecodeInterpreter.hpp:

    initialStaticMethod(REGISTER_ARGS_LIST)
    {
        VM_BytecodeAction rc = GOTO_RUN_METHOD;
        bool split = (JBinvokestaticsplit == _pc[0]);
        U_16 index = *(U_16*)(_pc + 1);
        J9ConstantPool *ramConstantPool = J9_CP_FROM_METHOD(_literals);
        buildGenericSpecialStackFrame(REGISTER_ARGS, 0);
        updateVMStruct(REGISTER_ARGS);
        if (split) {
            _sendMethod = resolveStaticSplitMethodRef(_currentThread, ramConstantPool, index, J9_RESOLVE_FLAG_RUNTIME_RESOLVE | J9_RESOLVE_FLAG_CHECK_CLINIT);
        } else {
---> _sendMethod = resolveStaticMethodRef(_currentThread, ramConstantPool, index, J9_RESOLVE_FLAG_RUNTIME_RESOLVE | J9_RESOLVE_FLAG_CHECK_CLINIT);
        }

To differentiate these two kinds of static initialization method, we should check the value (J9_RESOLVE_FLAG_CHECK_CLINIT) of resolveFlags in resolveStaticMethodRefInto so as to stop initializing Test$Class1 from Java_java_lang_invoke_MethodHandle_getCPMethodHandleAt as follows:

    /* Initialize the defining class of the method. */
    if (J9_ARE_NO_BITS_SET(resolveFlags, J9_RESOLVE_FLAG_NO_CLASS_INIT) 
      && J9_ARE_ALL_BITS_SET(resolveFlags, J9_RESOLVE_FLAG_RUNTIME_RESOLVE | J9_RESOLVE_FLAG_CHECK_CLINIT) <------
     ) {
        J9Class *methodClass = J9_CLASS_FROM_METHOD(method);
        UDATA initStatus = methodClass->initializeStatus;
        if (jitCompileTimeResolve && (J9ClassInitSucceeded != initStatus)) {
            method = NULL;
            goto done;
        }
        if (initStatus != J9ClassInitSucceeded && initStatus != (UDATA)vmStruct) {
            /* Initialize the class if java code is allowed */
            if (canRunJavaCode) {
                UDATA preCount = vmStruct->javaVM->hotSwapCount;
                initializeClass(vmStruct, methodClass);
ChengJin01 commented 4 years ago

Test results indicate the proposed fix above works good as expected

 ../jdk11_openj9_mh_debug_v3/bin/java  Test
Class2.<clinit> called
obtaining method reference to Class1.dummyMethod
incrementing Class2.a
running Class1.dummyMethod via method reference
Class1.<clinit>: Class2.a is 1.0
Class1.dummyMethod: Class2.a is 1.0

1.16.2pre1$ ../jdk11_openj9_mh_debug_v3/bin/java   -Xmx1024M -Xms1024M   -jar server.jar
[02:08:54] [main/INFO]: Environment: authHost='https://authserver.mojang.com', accountsHost='https://api.mojang.com', sessionHost='https://sessionserver.mojang.com', name='PROD'
[02:08:56] [main/WARN]: Ambiguity between arguments [teleport, destination] and [teleport, targets] with inputs: [Player, 0123, @e, dd12be42-52a9-4a91-a8a1-11c01849e498]
[02:08:56] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[02:08:56] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, targets] with inputs: [0.1 -0.5 .9, 0 0 0]
[02:08:56] [main/WARN]: Ambiguity between arguments [teleport, targets] and [teleport, destination] with inputs: [Player, 0123, dd12be42-52a9-4a91-a8a1-11c01849e498]
[02:08:56] [main/WARN]: Ambiguity between arguments [teleport, targets, location] and [teleport, targets, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[02:08:56] [main/INFO]: Reloading ResourceManager: Default
[02:08:59] [Worker-Main-5/INFO]: Loaded 7 recipes
[02:09:00] [Worker-Main-5/INFO]: Loaded 927 advancements
[02:09:06] [Server thread/INFO]: Starting minecraft server version 1.16.2 Pre-release 1
[02:09:06] [Server thread/INFO]: Loading properties
[02:09:06] [Server thread/INFO]: Default game type: SURVIVAL
[02:09:06] [Server thread/INFO]: Generating keypair
[02:09:07] [Server thread/INFO]: Starting Minecraft server on *:25565
[02:09:07] [Server thread/INFO]: Using epoll channel type
[02:09:07] [Server thread/INFO]: Preparing level "world"
[02:09:08] [Server thread/WARN]: Unable to find spawn biome
[02:09:18] [Server thread/INFO]: Preparing start region for dimension minecraft:overworld
[02:09:18] [Worker-Main-5/INFO]: Preparing spawn area: 2%
[02:09:18] [Worker-Main-4/INFO]: Preparing spawn area: 2%
[02:09:19] [Worker-Main-6/INFO]: Preparing spawn area: 2%
[02:09:19] [Worker-Main-6/INFO]: Preparing spawn area: 2%
...
[02:09:43] [Worker-Main-6/INFO]: Preparing spawn area: 91%
[02:09:43] [Server thread/INFO]: Time elapsed: 25499 ms
[02:09:43] [Server thread/INFO]: Done (36.357s)! For help, type "help"

1.16.2pre2$ ../jdk11_openj9_mh_debug_v3/bin/java   -Xmx1024M -Xms1024M   -jar server.jar
[02:11:41] [main/INFO]: Environment: authHost='https://authserver.mojang.com', accountsHost='https://api.mojang.com', sessionHost='https://sessionserver.mojang.com', name='PROD'
[02:11:43] [main/WARN]: Ambiguity between arguments [teleport, destination] and [teleport, targets] with inputs: [Player, 0123, @e, dd12be42-52a9-4a91-a8a1-11c01849e498]
[02:11:43] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[02:11:43] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, targets] with inputs: [0.1 -0.5 .9, 0 0 0]
[02:11:43] [main/WARN]: Ambiguity between arguments [teleport, targets] and [teleport, destination] with inputs: [Player, 0123, dd12be42-52a9-4a91-a8a1-11c01849e498]
[02:11:43] [main/WARN]: Ambiguity between arguments [teleport, targets, location] and [teleport, targets, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[02:11:43] [main/INFO]: Reloading ResourceManager: Default
[02:11:44] [Worker-Main-5/INFO]: Loaded 7 recipes
[02:11:45] [Worker-Main-5/INFO]: Loaded 927 advancements
[02:11:48] [Server thread/INFO]: Starting minecraft server version 1.16.2 Pre-release 2
[02:11:48] [Server thread/INFO]: Loading properties
[02:11:48] [Server thread/INFO]: Default game type: SURVIVAL
[02:11:48] [Server thread/INFO]: Generating keypair
[02:11:49] [Server thread/INFO]: Starting Minecraft server on *:25565
[02:11:49] [Server thread/INFO]: Using epoll channel type
[02:11:49] [Server thread/INFO]: Preparing level "world"
[02:11:59] [Server thread/INFO]: Preparing start region for dimension minecraft:overworld
[02:12:00] [Worker-Main-5/INFO]: Preparing spawn area: 0%
[02:12:00] [Worker-Main-4/INFO]: Preparing spawn area: 0%
[02:12:02] [Worker-Main-6/INFO]: Preparing spawn area: 0%
[02:12:02] [Worker-Main-4/INFO]: Preparing spawn area: 0%
[02:12:02] [Worker-Main-5/INFO]: Preparing spawn area: 0%
[02:12:02] [Worker-Main-5/INFO]: Preparing spawn area: 0%
[02:12:02] [Worker-Main-5/INFO]: Preparing spawn area: 0%
[02:12:02] [Worker-Main-6/INFO]: Preparing spawn area: 0%
[02:12:03] [Worker-Main-5/INFO]: Preparing spawn area: 0%
[02:12:03] [Worker-Main-6/INFO]: Preparing spawn area: 0%
[02:12:04] [Worker-Main-5/INFO]: Preparing spawn area: 1%
[02:12:04] [Worker-Main-4/INFO]: Preparing spawn area: 3%
[02:12:05] [Worker-Main-4/INFO]: Preparing spawn area: 3%
[02:12:05] [Worker-Main-4/INFO]: Preparing spawn area: 3%
...
[02:12:33] [Worker-Main-6/INFO]: Preparing spawn area: 96%
[02:12:33] [Worker-Main-4/INFO]: Preparing spawn area: 99%
[02:12:34] [Server thread/INFO]: Time elapsed: 34594 ms
[02:12:34] [Server thread/INFO]: Done (44.469s)! For help, type "help"
DanHeidinga commented 4 years ago

@ChengJin01 Nice find tracking down the path causing the resolve to request the <clinit>. The proposed fix isn't the right approach though as that flag means something else - basically whether the check is happening in a <clinit> method or not.

If the MH resolves shouldn't init the class, then it might be better to pass J9_RESOLVE_FLAG_NO_CLASS_INIT either from the Java_java_lang_invoke_MethodHandle_getCPMethodHandleAt call or from resolveMethodHandleRefInto when calling the other resolve helpers (ie: resolveStaticMethodRef)

ChengJin01 commented 4 years ago

@DanHeidinga, J9_RESOLVE_FLAG_NO_CLASS_INIT makes more sense to me rather than checking J9_RESOLVE_FLAG_CHECK_CLINIT (which means different thing I was unaware of).

In addition, setting J9_RESOLVE_FLAG_NO_CLASS_INIT to resolveMethodHandleRef from Java_java_lang_invoke_MethodHandle_getCPMethodHandleAt might be better as we already have similar code to set up J9_RESOLVE_FLAG_NO_CLASS_INIT in the interperter .e.g.

    VMINLINE VM_BytecodeAction
    ldc(REGISTER_ARGS_LIST, UDATA parmSize)
    {
...
            switch (romCPEntry->cpType & J9DescriptionCpTypeMask) {
...
            case J9DescriptionCpTypeMethodHandle:
                resolveMethodHandleRef(_currentThread, ramConstantPool, index, 
      -----> J9_RESOLVE_FLAG_RUNTIME_RESOLVE | J9_RESOLVE_FLAG_NO_CLASS_INIT);
                break;
gacholio commented 4 years ago

This should also require initializing the class at the point of method invoke or static field access, as we're no longer doing at MH resolution time.

DanHeidinga commented 4 years ago

This should also require initializing the class at the point of method invoke or static field access, as we're no longer doing at MH resolution time.

The MHInterpreter already does that, as do the thunkArchetype jit templates. I don't expect any changes required there but we should do some tests to confirm.

ChengJin01 commented 4 years ago

With the fix at Java_java_lang_invoke_MethodHandle_getCPMethodHandleAt:

Java_java_lang_invoke_MethodHandle_getCPMethodHandleAt(JNIEnv *env, jclass unusedClass, jobject constantPoolOop, jint cpIndex)
{
...
            if (NULL == methodHandleObject) {
       methodHandleObject = vmFunctions->resolveMethodHandleRef(vmThread, J9_CP_FROM_CLASS(ramClass), cpIndex, 
----> J9_RESOLVE_FLAG_RUNTIME_RESOLVE | J9_RESOLVE_FLAG_NO_CLASS_INIT);
            }

The test results indicate it works good as expected:

$ ../jdk11_openj9_mh_debug_v4/bin/java  Test
Class2.<clinit> called
obtaining method reference to Class1.dummyMethod
incrementing Class2.a
running Class1.dummyMethod via method reference
Class1.<clinit>: Class2.a is 1.0
Class1.dummyMethod: Class2.a is 1.0

 $../jdk11_openj9_mh_debug_v4/bin/java   -Xmx1024M -Xms1024M   -jar server.jar
[11:31:07] [main/INFO]: Environment: authHost='https://authserver.mojang.com', accountsHost='https://api.mojang.com', sessionHost='https://sessionserver.mojang.com', name='PROD'
[11:31:09] [main/WARN]: Ambiguity between arguments [teleport, destination] and [teleport, targets] with inputs: [Player, 0123, @e, dd12be42-52a9-4a91-a8a1-11c01849e498]
[11:31:09] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[11:31:09] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, targets] with inputs: [0.1 -0.5 .9, 0 0 0]
[11:31:09] [main/WARN]: Ambiguity between arguments [teleport, targets] and [teleport, destination] with inputs: [Player, 0123, dd12be42-52a9-4a91-a8a1-11c01849e498]
[11:31:09] [main/WARN]: Ambiguity between arguments [teleport, targets, location] and [teleport, targets, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[11:31:09] [main/INFO]: Reloading ResourceManager: Default
[11:31:12] [Worker-Main-5/INFO]: Loaded 7 recipes
[11:31:13] [Worker-Main-5/INFO]: Loaded 927 advancements
[11:31:17] [Server thread/INFO]: Starting minecraft server version 1.16.2 Pre-release 1
[11:31:17] [Server thread/INFO]: Loading properties
[11:31:17] [Server thread/INFO]: Default game type: SURVIVAL
[11:31:17] [Server thread/INFO]: Generating keypair
[11:31:19] [Server thread/INFO]: Starting Minecraft server on *:25565
[11:31:19] [Server thread/INFO]: Using epoll channel type
[11:31:19] [Server thread/INFO]: Preparing level "world"
[11:31:20] [Server thread/WARN]: Unable to find spawn biome
[11:31:30] [Server thread/INFO]: Preparing start region for dimension minecraft:overworld
[11:31:30] [Worker-Main-4/INFO]: Preparing spawn area: 2%
[11:31:30] [Worker-Main-4/INFO]: Preparing spawn area: 2%
[11:31:31] [Worker-Main-4/INFO]: Preparing spawn area: 2%
[11:31:31] [Worker-Main-5/INFO]: Preparing spawn area: 2%
[11:31:32] [Worker-Main-5/INFO]: Preparing spawn area: 2%
[11:31:32] [Worker-Main-6/INFO]: Preparing spawn area: 3%
[11:31:33] [Worker-Main-6/INFO]: Preparing spawn area: 5%
[11:31:33] [Worker-Main-5/INFO]: Preparing spawn area: 9%
[11:31:34] [Worker-Main-5/INFO]: Preparing spawn area: 9%
[11:31:34] [Worker-Main-6/INFO]: Preparing spawn area: 10%
...
[11:31:56] [Worker-Main-4/INFO]: Preparing spawn area: 89%
[11:31:56] [Server thread/INFO]: Time elapsed: 26317 ms
[11:31:56] [Server thread/INFO]: Done (36.814s)! For help, type "help"

$ ../jdk11_openj9_mh_debug_v4/bin/java  -Xmx1024M -Xms1024M   -jar server.jar
[11:34:30] [main/INFO]: Environment: authHost='https://authserver.mojang.com', accountsHost='https://api.mojang.com', sessionHost='https://sessionserver.mojang.com', name='PROD'
[11:34:31] [main/WARN]: Ambiguity between arguments [teleport, destination] and [teleport, targets] with inputs: [Player, 0123, @e, dd12be42-52a9-4a91-a8a1-11c01849e498]
[11:34:31] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[11:34:31] [main/WARN]: Ambiguity between arguments [teleport, location] and [teleport, targets] with inputs: [0.1 -0.5 .9, 0 0 0]
[11:34:31] [main/WARN]: Ambiguity between arguments [teleport, targets] and [teleport, destination] with inputs: [Player, 0123, dd12be42-52a9-4a91-a8a1-11c01849e498]
[11:34:31] [main/WARN]: Ambiguity between arguments [teleport, targets, location] and [teleport, targets, destination] with inputs: [0.1 -0.5 .9, 0 0 0]
[11:34:31] [main/INFO]: Reloading ResourceManager: Default
[11:34:32] [Worker-Main-5/INFO]: Loaded 7 recipes
[11:34:33] [Worker-Main-5/INFO]: Loaded 927 advancements
[11:34:37] [Server thread/INFO]: Starting minecraft server version 1.16.2 Pre-release 2
[11:34:37] [Server thread/INFO]: Loading properties
[11:34:37] [Server thread/INFO]: Default game type: SURVIVAL
[11:34:37] [Server thread/INFO]: Generating keypair
[11:34:37] [Server thread/INFO]: Starting Minecraft server on *:25565
[11:34:37] [Server thread/INFO]: Using epoll channel type
[11:34:37] [Server thread/INFO]: Preparing level "world"
[11:34:38] [Server thread/INFO]: Preparing start region for dimension minecraft:overworld
[11:34:45] [Server thread/INFO]: Preparing spawn area: 0%
[11:34:45] [Server thread/INFO]: Preparing spawn area: 0%
[11:34:45] [Server thread/INFO]: Preparing spawn area: 0%
...
[11:35:03] [Server thread/INFO]: Preparing spawn area: 91%
[11:35:04] [Worker-Main-4/INFO]: Preparing spawn area: 95%
[11:35:04] [Server thread/INFO]: Time elapsed: 26449 ms
[11:35:04] [Server thread/INFO]: Done (26.648s)! For help, type "help"

Will launch personal builds on Java 8 & 11 to ensure there is no issue introduced with the fix.

ChengJin01 commented 4 years ago

I verified two cases with simple tests with the fix above as @gacholio mentioned, which also works good as expected.

[1] initializing the class at the point of static field access:

public class Test2 {
    public static class Class1 {
        public static int a = 0;

        static {
            a = 1;
            System.out.println("Class1.<clinit>: Class1.a = " + Class1.a);
        }
    }

    public static void main(String[] args) {
        int b = Class1.a;
        System.out.println("b = " + b);
    }
}

with the following output:

$ ../jdk11_openj9_mh_debug_v4/bin/java  Test2
Class1.<clinit>: Class1.a = 1  <--- <clinit> was triggered before accessing the static filed
b = 1

[2] initializing the class at the point of method invoke

public class Test3 {
    public static class Class1 {
        public static void dummyMethod() {
            System.out.println("calling Class1.dummyMethod");
        }

        static {
            System.out.println("calling Class1.<clinit>");
        }
    }

    public static void main(String[] args) {
        Class1.dummyMethod();
    }
}

with the following output:

$ ../jdk11_openj9_mh_debug_v4/bin/java  Test3
calling Class1.<clinit>    <------------ <clinit> was triggered before calling the static method
calling Class1.dummyMethod
gacholio commented 4 years ago

Neither of those above tests are using MethodHandle, so I'm not sure what they prove.

ChengJin01 commented 4 years ago

[1] Test2 used MethodHandle as follows:

$ ../jdk11_openj9_mh_debug_v4/bin/javap -v -p  Test2.class
Classfile /home/jincheng/X86_64_OPENJ9/issues_2020/10356_minecraft_load/Testcase/Test2.class
  Last modified Aug. 18, 2020; size 921 bytes
  MD5 checksum f63ac48827feb8bb8c2acefb99987c57
  Compiled from "Test2.java"
...
  public static void main(java.lang.String[]);
    descriptor: ([Ljava/lang/String;)V
    flags: (0x0009) ACC_PUBLIC, ACC_STATIC
    Code:
      stack=2, locals=2, args_size=1
         0: getstatic     #2                  // Field Test2$Class1.a:I
         3: istore_1
         4: getstatic     #3                  // Field java/lang/System.out:Ljava/io/PrintStream;
         7: iload_1
----> 8: invokedynamic #4,  0              // InvokeDynamic #0:makeConcatWithConstants:(I)Ljava/lang/String;
        13: invokevirtual #5                  // Method java/io/PrintStream.println:(Ljava/lang/String;)V
        16: return
      LineNumberTable:
        line 12: 0
        line 13: 4
        line 14: 16
}
SourceFile: "Test2.java"
NestMembers:
  Test2$Class1
InnerClasses:
  public static #9= #8 of #6;             // Class1=class Test2$Class1 of class Test2
  public static final #49= #48 of #51;    // Lookup=class java/lang/invoke/MethodHandles$Lookup of class java/lang/invoke/MethodHandles
BootstrapMethods:
  0: #25 REF_invokeStatic java/lang/invoke/StringConcatFactory.makeConcatWithConstants:(Ljava/lang/invoke/MethodHandles$Lookup;Ljava/lang/String;Ljava/lang/invoke/MethodType;Ljava/lang/String;[Ljava/lang/Object;)Ljava/lang/invoke/CallSite;
    Method arguments:
      #26 b = \u0001

Test3 might need to rewritten.

{
  public Test3();
    descriptor: ()V
    flags: (0x0001) ACC_PUBLIC
    Code:
      stack=1, locals=1, args_size=1
         0: aload_0
         1: invokespecial #1                  // Method java/lang/Object."<init>":()V
         4: return
      LineNumberTable:
        line 1: 0

  public static void main(java.lang.String[]);
    descriptor: ([Ljava/lang/String;)V
    flags: (0x0009) ACC_PUBLIC, ACC_STATIC
    Code:
      stack=0, locals=1, args_size=1
         0: invokestatic  #2                  // Method Test3$Class1.dummyMethod:()V
         3: return
      LineNumberTable:
        line 13: 0
        line 14: 3
}
SourceFile: "Test3.java"
NestMembers:
  Test3$Class1
InnerClasses:
  public static #6= #5 of #3;             // Class1=class Test3$Class1 of class Test3
gacholio commented 4 years ago

The MH use in Test2 appears to be from the string concatenation, not from the field access.

ChengJin01 commented 4 years ago

I modified Test2 to use MethodHandle as follows:

BaseExample.java
public class BaseExample {
   public static int intField = 0;
        static {
            intField = 1;
            System.out.println("calling BaseExample.<clinit>");
        }
}

Test2.java
import java.lang.invoke.MethodHandle;
import java.lang.invoke.MethodHandles;
import java.lang.invoke.MethodHandles.Lookup;
import java.lang.invoke.MethodType;

public class Test2 {
    public static void main(String[] args) throws Throwable {
        MethodHandle intHandle = MethodHandles.lookup().findStaticGetter(BaseExample.class, "intField",int.class);
        System.out.println("prepared to invoke intHandle");
        int intValue = (int) intHandle.invoke();
        System.out.println("intValue = " + intValue);
    }
}

with the expected result:

$ ../jdk11_openj9_mh_debug_v4/bin/java  Test2
prepared to invoke intHandle
calling BaseExample.<clinit>  <------------------
intValue = 1
ChengJin01 commented 4 years ago

Updated Test3.java (for method) as follows:

BaseExample3.java
public class BaseExample3 {
   public static int addPublicStatic (int a,int b) {return a + b;}
        static {
            System.out.println("calling BaseExample3.<clinit>");
        }
}

Test3.java
import java.lang.invoke.MethodHandle;
import java.lang.invoke.MethodHandles;
import java.lang.invoke.MethodHandles.Lookup;
import java.lang.invoke.MethodType;
public class Test3 {
    public static void main(String[] args) throws Throwable {
 MethodHandle addHandle = MethodHandles.lookup().findStatic( BaseExample3.class, "addPublicStatic", MethodType.methodType( int.class, int.class, int.class ) );
    System.out.println("prepared to invoke addHandle");
        int sum = ( int )addHandle.invoke( 1, 2 );
        System.out.println("sum = " + sum);
    }
}

with the expected result:

$ ../jdk11_openj9_mh_debug_v4/bin/java  Test3
prepared to invoke addHandle
calling BaseExample3.<clinit>  <--------
sum = 3