Openj9: JITServer failures for extended test suite

Created on 1 Nov 2019  路  19Comments  路  Source: eclipse/openj9

Local testing with the 'extended' test bucket showed the following failures that do not appear when JITServer is disabled:

        cmdLineTester_fieldwatchtests_0
        cmdLineTester_jvmtitests_hcr_OSRG_nongold_SE80_3
        cmdLineTester_jvmtitests_hcr_OSRG_nongold_SE80_4

Example

Testing: fw001-4
Test start time: 2019/11/01 10:38:15 Pacific Standard Time
Running command: "/home/mpirvu/JITaaSVM/openj9-openjdk-jdk8/build/linux-x86_64-normal-server-release/images/j2sdk-image/bin/java" -Xcompressedrefs -XX:+UseJITServer -XX:JITServerTimeout=20000  -Xdump  -XX:+JITInlineWatches                                 -Xjit:disableAsyncCompilation,dontInline={*jitme*},disableSuffixLogs,{*jitme*}(count=2) -agentlib:jvmtitest=test:fw001 -cp "/home/mpirvu/JITaaSVM/openj9-openjdk-jdk8/openj9/test/TestConfig/../../jvmtest/functional/cmdLine                                Tests/jvmtitests/jvmtitest.jar" com.ibm.jvmti.tests.util.TestRunner
Time spent starting: 13 milliseconds
Time spent executing: 8102 milliseconds
Test result: FAILED
Output from test:
 [OUT] *** Testing [1/1]:       testFieldWatch
 [OUT] =============== Beginning - STATIC AND INSTANCE FIELD WATCH TESTS
 [OUT]
 [OUT]
 [OUT] ===============adding field read watches for staticDoubleField
 [OUT]
 [OUT]
 [OUT] ===============run
 [OUT]
 [OUT]
 [OUT] **NOTE**: Modified fieldwatch(access) for staticDoubleField. The fieldID is: 0x7fe36016df18 and it is associated with class: com/ibm/jvmti/tests/fieldwatch/MyObject, field: staticDoubleField, signature: D, isStatic:                                 Yes, modificationType: add
 [OUT] Field Access Report #1: method: 0x7fe36016df40 location 26. Class: 0xf99e50, fieldID: 0x7fe36016df18
 [OUT] Field Access Report #2: method: 0x7fe36016df40 location 26. Class: 0xf99e50, fieldID: 0x7fe36016df18
 [ERR] Unhandled exception
 [ERR] Type=Segmentation error vmState=0x00040000
 [ERR] J9Generic_Signal_Number=00000018 Signal_Number=0000000b Error_Value=00000000 Signal_Code=00000080
 [ERR] Handler1=00007FE365A77FF0 Handler2=00007FE364E5FEB0 InaccessibleAddress=0000000000000000
 [ERR] RDI=0000000000ECCA00 RSI=0000000000F99E50 RAX=0000000000F99E50 RBX=0000000000ECCA00
 [ERR] RCX=0000000000000000 RDX=0000000000000005 R8=0000000000000024 R9=000000000102DB60
 [ERR] R10=000000000102DC00 R11=00007FE35DD64BAA R12=00007FE3661D60E0 R13=00007FE34B0018AB
 [ERR] R14=00007FE360010930 R15=8000000000000008
 [ERR] RIP=00007FE35F557A2F GS=0000 FS=0000 RSP=00007FE3669D8010
 [ERR] EFlags=0000000000010202 CS=0033 RBP=00007FE34B001AE5 ERR=0000000000000000
 [ERR] TRAPNO=000000000000000D OLDMASK=0000000000000000 CR2=0000000000000000
 [ERR] xmm0 4036ae147ae147ae (f: 2061584256.000000, d: 2.268000e+01)
 [ERR] xmm1 0000000041fc7ae1 (f: 1107065600.000000, d: 5.469631e-315)
 [ERR] xmm2 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] xmm3 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] xmm4 ffffffffffffff00 (f: 4294967040.000000, d: -nan)
 [ERR] xmm5 402f2d0351681281 (f: 1365774976.000000, d: 1.558792e+01)
 [ERR] xmm6 0000000000000000 (f: 0.000000, d: 0.000000e+00)
 [ERR] xmm7 0000000000000001 (f: 1.000000, d: 4.940656e-324)
 [ERR] xmm8 3bbcc86800000000 (f: 0.000000, d: 6.095003e-21)
 [ERR] xmm9 3fd5acea17e2c35e (f: 400737120.000000, d: 3.386789e-01)
 [ERR] xmm10 3d7546d0b3dfa6ae (f: 3017778944.000000, d: 1.209436e-12)
 [ERR] xmm11 402f2d036f57231b (f: 1867981568.000000, d: 1.558792e+01)
 [ERR] xmm12 bca0000000000000 (f: 0.000000, d: -1.110223e-16)
 [ERR] xmm13 bfd5acea17e2c360 (f: 400737120.000000, d: -3.386789e-01)
 [ERR] xmm14 402e7f9c1e980d00 (f: 513281280.000000, d: 1.524924e+01)
 [ERR] xmm15 bc78e1b97042c1c2 (f: 1883423232.000000, d: -2.158147e-17)
 [ERR] Module=/home/mpirvu/JITaaSVM/openj9-openjdk-jdk8/build/linux-x86_64-normal-server-release/images/j2sdk-image/jre/lib/amd64/compressedrefs/libj9jit29.so
 [ERR] Module_base_address=00007FE35EC12000
 [ERR] Target=2_90_20191031_000000 (Linux 4.4.0-138-generic)
 [ERR] CPU=amd64 (8 logical CPUs) (0x3eaec3000 RAM)
 [ERR] ----------- Stack Backtrace -----------
 [ERR] (0x00007FE35F557A2F [libj9jit29.so+0x945a2f])
 [ERR] (0x00007FE35F566F26 [libj9jit29.so+0x954f26])
 [ERR] ---------------------------------------
 [ERR] JVMDUMP039I Processing dump event "gpf", detail "" at 2019/11/01 10:38:15 - please wait.
 [ERR] JVMDUMP032I JVM requested System dump using '/home/mpirvu/JITaaSVM/openj9-openjdk-jdk8/openj9/test/TestConfig/test_output_15726298676102/cmdLineTester_fieldwatchtests_0/core.20191101.103815.25778.0001.dmp' in respon                                se to an event
 [ERR] JVMPORT030W /proc/sys/kernel/core_pattern setting "|/lib/systemd/systemd-coredump %P %u %g %s %t 9223372036854775808 %e" specifies that the core dump is to be piped to an external program.  Attempting to rename eith                                er core or core.25805.
 [ERR]
 [ERR] JVMDUMP012E Error in System dump: The core file created by child process with pid = 25805 was not found. Expected to find core file with name "/home/mpirvu/JITaaSVM/openj9-openjdk-jdk8/openj9/test/TestConfig/test_ou                                tput_15726298676102/cmdLineTester_fieldwatchtests_0/core"
 [ERR] JVMDUMP032I JVM requested Java dump using '/home/mpirvu/JITaaSVM/openj9-openjdk-jdk8/openj9/test/TestConfig/test_output_15726298676102/cmdLineTester_fieldwatchtests_0/javacore.20191101.103815.25778.0002.txt' in resp                                onse to an event
 [ERR] JVMDUMP010I Java dump written to /home/mpirvu/JITaaSVM/openj9-openjdk-jdk8/openj9/test/TestConfig/test_output_15726298676102/cmdLineTester_fieldwatchtests_0/javacore.20191101.103815.25778.0002.txt
 [ERR] JVMDUMP032I JVM requested Snap dump using '/home/mpirvu/JITaaSVM/openj9-openjdk-jdk8/openj9/test/TestConfig/test_output_15726298676102/cmdLineTester_fieldwatchtests_0/Snap.20191101.103815.25778.0003.trc' in response                                 to an event
 [ERR] JVMDUMP010I Snap dump written to /home/mpirvu/JITaaSVM/openj9-openjdk-jdk8/openj9/test/TestConfig/test_output_15726298676102/cmdLineTester_fieldwatchtests_0/Snap.20191101.103815.25778.0003.trc
 [ERR] JVMDUMP007I JVM Requesting JIT dump using '/home/mpirvu/JITaaSVM/openj9-openjdk-jdk8/openj9/test/TestConfig/test_output_15726298676102/cmdLineTester_fieldwatchtests_0/jitdump.20191101.103815.25778.0004.dmp'
 [ERR] JVMDUMP010I JIT dump written to /home/mpirvu/JITaaSVM/openj9-openjdk-jdk8/openj9/test/TestConfig/test_output_15726298676102/cmdLineTester_fieldwatchtests_0/jitdump.20191101.103815.25778.0004.dmp
 [ERR] JVMDUMP013I Processed dump event "gpf", detail "".
>> Success condition was not found: [Return code: 0]
bug jitserver
Source
picture mpirvu

All 19 comments

Will take a look.

harryyu1994 picture harryyu1994 on 1 Nov 2019

Debug story:
@dchopra001 credit to Dhruv for helping me out with this issue, as he's very familiar with the code path the fieldwatch test is exercising.

  1. An assertion is triggered inside wantToPatchClassPointer. It was determined that the class pointer was not valid. Which means JITServer generated some bad code.
 if (TR::CodeGenerator::wantToPatchClassPointer(reloRuntime->comp(), newAddress, reloLocation))
  1. JITServer codegen:
    We create the snippet inside J9CodeGenerator:
dataSnippet = TR::TreeEvaluator::getFieldWatchStaticSnippet(cg, node, owningMethod, bcIndex, fieldAddress, fieldClass);

And that fieldClass comes from:

J9Class *fieldClass = isUnresolved ? NULL : reinterpret_cast<J9Class *>(symRef->getOwningMethod(cg->comp())->getDeclaringClassFromFieldOrStatic(cg->comp(), symRef->getCPIndex()));

  • which means the fieldClass pointer is already a client class pointer (obtained through the JITServer version of getDeclaringClassFromFieldOrStatic())

  • It looks like we are still creating a relocation record for a client class pointer

  • If the pointer is already a client pointer, we shouldn't relocate it
else
         {
         // As things currently stand, this will not work on Power because TR_ClassAddress is used to a generate a 5 instruction sequence that materializes the address into a register. Meanwhile we are using TR_ClassAddress here to represent a contiguous word.
         // A short-term solution would be to use TR_ClassPointer. However this is hacky because TR_ClassPointer expects an aconst node (so we would have to create a dummy node). The proper solution would be to implement the functionality in the power
         // codegenerator to be able to patch TR_ClassAddress contiguous word.
         cg()->addExternalRelocation(
            new (cg()->trHeapMemory()) TR::ExternalRelocation(cursor + offsetof(J9JITWatchedStaticFieldData, fieldClass), reinterpret_cast<uint8_t *>(node->getSymbolReference()), reinterpret_cast<uint8_t *>(node->getInlinedSiteIndex()), TR_ClassAddress, cg()),
            __FILE__,
            __LINE__,
            node);
         }
  • Trying to not let JITServer get into this portion of the code
  • Test passed with this fix
harryyu1994 picture harryyu1994 on 15 Nov 2019
🎉1

Now looking into 

        cmdLineTester_jvmtitests_hcr_OSRG_nongold_SE80_3
        cmdLineTester_jvmtitests_hcr_OSRG_nongold_SE80_4

Merge point 1:
on August 13, 2019
https://github.com/eclipse/openj9/pull/6696

OpenJ9 SHA: 401414ac55c3de88aadb364c984dabb5aead2888
OMR SHA: 6e99760bcded06f8f85c6753e0c2f4370298703b
OPENJDK8 SHA: 9c5a52ee84fe1f74a8494a9bc2b05cb0fd6e5419

JITServer option
./java -XX:+StartAsJITServer -Xjit:verbose={jitaas}

JITClient option
./java -XX:+UseJITServer

Observed same failure as latest build.

Testing: rc020
Test start time: 2019/11/19 21:48:44 Coordinated Universal Time
Running command: "/root/Harry_Regular_Build/openj9-openjdk-jdk8/build/linux-x86_64-normal-server-release/images/j2sdk-image/bin/java" -Xcompressedrefs -Xcompressedrefs -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation -Xgcpolicy:gencon  -XX:+UseJITServer  -Xdump    -agentlib:jvmtitest=test:rc020 -cp "/root/Harry_Regular_Build/openj9-openjdk-jdk8/openj9/test/TestConfig/../../jvmtest/functional/cmdLineTests/jvmtitests/jvmtitest.jar:/root/Harry_Regular_Build/openj9-openjdk-jdk8/openj9/test/TestConfig/../../jvmtest/TestConfig/lib/asm-all.jar" com.ibm.jvmti.tests.util.TestRunner
Time spent starting: 2 milliseconds
Time spent executing: 4855 milliseconds
Test result: FAILED
Output from test:
 [OUT] *** Testing [1/1]:   testIndyRedefinition
 [OUT] testIndyRedefinition (basic test, bsm args): BSM call count was expected to be 1 after original indy call, count is actually 0
 [OUT] *** Test took 4173 milliseconds
 [OUT] FAILED
 [OUT] 
>> Success condition was not found: [Return code: 0]

Merge Point 2:
on Jul 18, 2019
https://github.com/eclipse/openj9/pull/6503
OpenJ9 SHA: 9e3480e093040c90493cd80dab52e1436fca372b
OMR SHA: aaad20c0b7a0e767e78d8d518c6ee870e9509ce5
OPENJDK8 SHA: 5cae160d4e5315ec115544accf53d89c0dc614aa

Testing: rc020
Test start time: 2019/11/19 23:07:10 Coordinated Universal Time
Running command: "/root/Harry_Regular_Build/openj9-openjdk-jdk8/build/linux-x86_64-normal-server-release/images/j2sdk-image/bin/java" -Xcompressedrefs -Xcompressedrefs -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation -Xgcpolicy:gencon  -XX:JITaaSClient  -Xdump    -agentlib:jvmtitest=test:rc020 -cp "/root/Harry_Regular_Build/openj9-openjdk-jdk8/openj9/test/TestConfig/scripts/testKitGen/../../../../jvmtest/functional/cmdLineTests/jvmtitests/jvmtitest.jar:/root/Harry_Regular_Build/openj9-openjdk-jdk8/openj9/test/TestConfig/scripts/testKitGen/../../../../jvmtest/TestConfig/lib/asm-all.jar" com.ibm.jvmti.tests.util.TestRunner
Time spent starting: 3 milliseconds
Time spent executing: 4680 milliseconds
Test result: FAILED
Output from test:
 [OUT] *** Testing [1/1]:   testIndyRedefinition
 [OUT] testIndyRedefinition (basic test, bsm args): BSM call count was expected to be 1 after original indy call, count is actually 0
 [OUT] *** Test took 3964 milliseconds
 [OUT] FAILED
 [OUT]

Same failure.

harryyu1994 picture harryyu1994 on 19 Nov 2019

Reduced down to compiling a single method

+ (no-opt) com/ibm/jvmti/tests/redefineClasses/rc020.runTest(Ljava/lang/String;[B[BII)Z @ 00007F49B56ABC34-00007F49B56AC655 OrdinaryMethod - Q_SZ=0 Q_SZI=0 QW=1 j9m=0000000001015648 bcsz=229 sync remote compThread=0 CpuLoad=82%(10%avg) JvmCpu=41%

          <mode number="610-OSRG">
                <description>JIT on with OSROnGuardFailure gencon gc (J9)</description>
                <settings>
                        <setting type="either">
                                <envVar name="OPENJ9_JAVA_OPTIONS" value="-Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation"/>
                                <clArg>-Xjit:count=1,disableAsyncCompilation,limitFile=/root/Harry_Build/openj9-openjdk-jdk8/openj9/test/TestConfig/limit_file_3,optLevel=noOpt</clArg>
                        </setting>
                        <setting type="either">
                                <clArg>-Xgcpolicy:gencon</clArg>
                                <envVar name="OPENJ9_JAVA_OPTIONS" value="-Xgcpolicy:gencon"/>
                        </setting>
                </settings>
        </mode>

It looks like -Xjit:count=0,disableAsyncCompilation passed the test but not -Xjit:count=1,disableAsyncCompilation

harryyu1994 picture harryyu1994 on 20 Nov 2019

Nice! A no-opt method cannot be very hard to track I assume.
Maybe comparing to code generated by non-jitserver will surface something

mpirvu picture mpirvu on 20 Nov 2019

Though I don't have any major breakthroughs, from reading the test case, I think we can narrow it down to JITServer mishandling something related to "JSR292(Dynamic methods)", and I'll be going through the set of functions responsible for JSR292 that JITServer overrides.

harryyu1994 picture harryyu1994 on 21 Nov 2019

Looking into this commit, https://github.com/eclipse/openj9/pull/6305, the corresponding regular JIT change might have not gotten mirrored to JITServer.

Listing all of the recent JSR292 related changes here:

harryyu1994 picture harryyu1994 on 21 Nov 2019

More information on the testcase: added on June 19, which means it's a relatively new test and most likely not a regression for JITServer.
More details on the testcase:
https://github.com/eclipse/openj9/pull/5029
The test was expected to fail without this change, https://github.com/eclipse/openj9/pull/5402
The issue explains the change and the test: https://github.com/eclipse/openj9/issues/4542
There are no JIT related changes in there.

How Invokedynamic(Indy) works briefly (from online resources):

  • MethodHandle is just a function pointer that points to a method
  • CallSite is used by Indy invocation and contains a MethodHandle
  • the MethodHandle that CallSite contains can change dynamically
  • Bootstrap method(BSM) is used to "initialize" the indy invocation
  • Bootstrap method(BSM) returns a permanent CallSite object for the indy invocation
  • JVM jumps to the method pointed to by the CallSite

First part of the test: use invokedynamic in a method, run the method and check if BSM was invoked.
In our case, BSM was not invoked.

private boolean runTest(String testName, byte[] classBytesO, byte[] classBytesR, int expectedOriginalBSMCount, int expectedBSMCountAfterRedefine) 
        {
        /* define original class */ 
        boolean redefineWithOriginal = redefineClass(rc020_testIndyAsmGenerator.testClass, classBytesO.length, classBytesO);
        if (! redefineWithOriginal) {
            System.out.println(testName + ": Class " + rc020_testIndyAsmGenerator.testClassName + " could not be redefined to original.");
            return false; /* fail */
        }

        /* call test method that runs invokedynamic. This should invoke the BSM to resolve the callsite */
        rc020_Source.testCall();

        /* verify that BSM was invoked */
        if (expectedOriginalBSMCount != rc020_testIndyBSMs.bsmCallCount()) {
            System.out.println(testName + ": BSM call count was expected to be " + expectedOriginalBSMCount 
                + " after original indy call, count is actually " + rc020_testIndyBSMs.bsmCallCount());
            return false; /* fail */
        }

        /* redefine class from original to new */
        boolean redefineWithNew = redefineClass(rc020_testIndyAsmGenerator.testClass, classBytesR.length, classBytesR);
        if (! redefineWithNew) {
            System.out.println(testName + ": Class " + rc020_testIndyAsmGenerator.testClassName + " could not be redefined to new class.");
            return false; /* fail */
        }

        /* call redefined test method and verify that callsite information was propagated to redefinition. */
        rc020_Source.testCall();

        /* verify that BSM count is correct */
        int expectedTotalBSMCount = expectedOriginalBSMCount + expectedBSMCountAfterRedefine;
        if (expectedTotalBSMCount != rc020_testIndyBSMs.bsmCallCount()) {
            System.out.println(testName + ": BSM call count was expected to be " + expectedTotalBSMCount 
                + " after redefined indy call, actually " + rc020_testIndyBSMs.bsmCallCount());
            return false; /* fail */
        }

        /* reset for next test */
        return resetTest(testName);
    }

    private void generateOneIndyMethod(ClassWriter cw, String methodName) {
        Handle bootstrap1 = new Handle(H_INVOKESTATIC, bootstrapFullClassName, bootstrap1MethodName, bootstrap1Signature);

        MethodVisitor mv = cw.visitMethod(ACC_PUBLIC | ACC_STATIC, methodName, voidSignature, null, null);
        mv.visitCode();
        mv.visitInvokeDynamicInsn(dynamicMethodName, voidSignature, bootstrap1);
        mv.visitInsn(RETURN);
        mv.visitMaxs(-1, -1);
        mv.visitEnd();
    } 

    private void generateOneIndyMethodWithArgs(ClassWriter cw, String methodName) {
        Handle bootstrap3 = new Handle(H_INVOKESTATIC, bootstrapFullClassName, bootstrap3MethodName, bootstrap3Signature);

        MethodVisitor mv = cw.visitMethod(ACC_PUBLIC | ACC_STATIC, methodName, voidSignature, null, null);
        mv.visitCode();
        mv.visitInvokeDynamicInsn(dynamicMethodName, voidSignature, bootstrap3, bootstrapIntArg);
        mv.visitInsn(RETURN);
        mv.visitMaxs(-1, -1);
        mv.visitEnd();
harryyu1994 picture harryyu1994 on 22 Nov 2019

Reduced testcase:
How this reduced testcase operates:

  • Step 1. we redefine the testClass with a "Basic Indy Class"
  • Step 2. we call its "testCall()" and the bootstrap method(BSM) should be invoked and its call count incremented. Here we verify call count == 1.
  • Step 3. we redefine the testClass again with the same "Basic Indy Class"
  • Step 4. we call "testCall()" again and BSM should not be invoked this time. Here we verify call count == 1.
  • Step 5. we reset the call count to 0 and redefine class back to the original class.
  • Step 6. we repeat Step 1 to Step 5 again the second time, and we fail at Step 2. BSM was supposed to be invoked but didn't.
/*
 * The purpose of this test is to verify that the resolved state for invokedynamic is propagated
 * to equivalent methods in a redefined class.
 * 
 * Every time an invokedynamic instruction is called with a bootstrap method in the IndyBSMs class, 
 * a counter will be incremented. If after invokedynamic calls the counter value is greater than expected,
 * the invokedynamic bytecodes are not being propagated.
 */
public class rc020 {
    private static byte[] resetClassBytes;

    public static native boolean redefineClass(Class name, int classBytesSize, byte[] classBytes);

    public boolean testIndyRedefinition() throws Throwable {
        resetClassBytes = new rc020_testIndyAsmGenerator().generateExistingIndyClass();

        /* Redefine class with one indy call. Iteration 1 */
        byte[] classBytes1 = new rc020_testIndyAsmGenerator().generateBasicIndyClass();
        if (!runTest("testIndyRedefinition (basic test) 1", classBytes1, classBytes1, 1, 0)) {
                return false;
        }

        /* Redefine class with one indy call. Iteration 2 */
        byte[] classBytes2 = new rc020_testIndyAsmGenerator().generateBasicIndyClass();
        if (!runTest("testIndyRedefinition (basic test) 2", classBytes2, classBytes2, 1, 0)) {
                return false;
        }
        return true; /* success */
    }

    private boolean runTest(String testName, byte[] classBytesO, byte[] classBytesR, int expectedOriginalBSMCount, int expectedBSMCountAfterRedefine) {
        /* define original class */ 
        boolean redefineWithOriginal = redefineClass(rc020_testIndyAsmGenerator.testClass, classBytesO.length, classBytesO);
        if (! redefineWithOriginal) {
            System.out.println(testName + ": Class " + rc020_testIndyAsmGenerator.testClassName + " could not be redefined to original.");
            return false; /* fail */
        }

        /* call test method that runs invokedynamic. This should invoke the BSM to resolve the callsite */
        rc020_Source.testCall();

        /* verify that BSM was invoked */
        if (expectedOriginalBSMCount != rc020_testIndyBSMs.bsmCallCount()) {
            System.out.println(testName + ": BSM call count was expected to be " + expectedOriginalBSMCount 
                + " after original indy call, count is actually " + rc020_testIndyBSMs.bsmCallCount());
            return false; /* fail */
        }

        /* redefine class from original to new */
        boolean redefineWithNew = redefineClass(rc020_testIndyAsmGenerator.testClass, classBytesR.length, classBytesR);
        if (! redefineWithNew) {
            System.out.println(testName + ": Class " + rc020_testIndyAsmGenerator.testClassName + " could not be redefined to new class.");
            return false; /* fail */
        }

        /* call redefined test method and verify that callsite information was propagated to redefinition. */
        rc020_Source.testCall();

        /* verify that BSM count is correct */
        int expectedTotalBSMCount = expectedOriginalBSMCount + expectedBSMCountAfterRedefine;
        if (expectedTotalBSMCount != rc020_testIndyBSMs.bsmCallCount()) {
            System.out.println(testName + ": BSM call count was expected to be " + expectedTotalBSMCount 
                + " after redefined indy call, actually " + rc020_testIndyBSMs.bsmCallCount());
            return false; /* fail */
        }
        /* reset for next test */
        /* reset BSM count to zero */
        rc020_testIndyBSMs.resetBsmCallCount();

        /* reset test class to have no indy calls, resolved callsites will be reset */
        boolean resetResult = redefineClass(rc020_testIndyAsmGenerator.testClass, resetClassBytes.length, resetClassBytes);
        if (! resetResult) {
            System.out.println(testName + ": reset redefine failed.");
            return false; /* fail */
        }
        System.out.println(testName + ": reset redefine succeeded.");
        return true;
    }

    public String helpIndyRedefinition() {
        return "Tests if indy MethodHandle resolution is propagated over redefined classes.";
    }
}

Test result: FAILED
Output from test:
 [OUT] *** Testing [1/1]:   testIndyRedefinition
 [OUT] bootstrapMethod1 called
 [OUT] 
 [OUT] testIndyRedefinition (basic test) 1: reset redefine succeeded.
 [OUT] testIndyRedefinition (basic test) 2: BSM call count was expected to be 1 after original indy call, count is actually 0
 [OUT] *** Test took 1080 milliseconds
 [OUT] FAILED
 [OUT] 
>> Success condition was not found: [Return code: 0]
  • Xjit:count=1 fails
  • Xjit:count=0 passes
    <mode number="610-OSRG">
        <description>JIT on with OSROnGuardFailure gencon gc (J9)</description>
        <settings>
            <setting type="either">
                <clArg>-Xcompressedrefs</clArg>
                <envVar name="OPENJ9_JAVA_OPTIONS" value="-Xcompressedrefs"/>
            </setting>
            <setting type="either">
                <envVar name="OPENJ9_JAVA_OPTIONS" value="-Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation"/>
                <clArg>-Xshareclasses:none -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation,verbose={compilePerformance},limitFile=/root/Harry_Build/openj9-openjdk-jdk8/openj9/test/TestConfig/limit_file_3,traceFull,log=vlog.log,optLevel=noopt</clArg>
            </setting>
            <setting type="either">
                <clArg>-Xgcpolicy:gencon</clArg>
                <envVar name="OPENJ9_JAVA_OPTIONS" value="-Xgcpolicy:gencon"/>
            </setting>
        </settings>
    </mode>
harryyu1994 picture harryyu1994 on 23 Nov 2019

count=1 fails => means that the first time it was interpreted and the second time it was a remote compile and failed.
count=0 passes => means that both first and second time were remote compiles and they were fine.

Things are unresolved with count=0 and are resolved with count=1. For example we may not know the address of a class with count=0 because no one has called that class (unresolved). In this case we generate JIT code that will go to some helper routine that will eventually do the resolution for us. On the other hand, count=1 indicates we have called it before so we don't need to use the helper routine anymore and instead we can use the class address directly. So a possibility of the issue is that we could be doing similar things for count=0 and count=1 somewhere but they should have been handled differently on JITServer.

Still haven't figured out how to track this down, may need to get familiar with the code path that the test is exercising.

Maybe trying to figure out the different paths count=1 and count=0 were taking.

Another thing to verify: count=0 succeeded on the reduced testcase, check count=0 for the original testcase. Verified.

Question: shouldn't runtest get compiled twice for count=0?

harryyu1994 picture harryyu1994 on 26 Nov 2019

There is a high chance it's related to HCR not being handled properly on the JITServer, as the test uses JVMTI agents to redefine Java method implementations.

harryyu1994 picture harryyu1994 on 26 Nov 2019

Final reduced testcase:

private void runTest(byte[] classBytes) {
        /* call test method that runs invokedynamic. This should invoke the BSM to resolve the callsite */
        redefineClass(rc020_testIndyAsmGenerator.testClass, classBytes.length, classBytes);
        rc020_Source.testCall();
    }

The assembly code looked almost identical.

I have a strong feeling that the callSite propagation change has something to do with this. I'm going to try to revert that change to see if the issue disappears. (areMethodsEquivalentPropagateCallSites())

public class rc020 {
    public static native boolean redefineClass(Class name, int classBytesSize, byte[] classBytes);

    public boolean testIndyRedefinition() throws Throwable {
        /* define original class */
        byte[] classBytes = new rc020_testIndyAsmGenerator().generateBasicIndyClass();

        /* Redefine class with one indy call. Iteration 1 */
        runTest(classBytes);

        /* verify that BSM was invoked */
        if (1 != rc020_testIndyBSMs.bsmCallCount()) {
            System.out.println("Test 0: BSM call count expected 1 but " + rc020_testIndyBSMs.bsmCallCount());
            return false; /* fail */
        }

        byte[] resetClassBytes = new rc020_testIndyAsmGenerator().generateExistingIndyClass();
        rc020_testIndyBSMs.resetBsmCallCount();
        redefineClass(rc020_testIndyAsmGenerator.testClass, resetClassBytes.length, resetClassBytes);

        /* Redefine class with one indy call. Iteration 1 */
        runTest(classBytes);

        /* verify that BSM was invoked */
        if (1 != rc020_testIndyBSMs.bsmCallCount()) {
            System.out.println("Test 1: BSM call count expected 1 but " + rc020_testIndyBSMs.bsmCallCount());
            return false; /* fail */
        }
        return true; /* success */
    }

    private void runTest(byte[] classBytes) {
        /* call test method that runs invokedynamic. This should invoke the BSM to resolve the callsite */
        redefineClass(rc020_testIndyAsmGenerator.testClass, classBytes.length, classBytes);
        rc020_Source.testCall();
    }

    public String helpIndyRedefinition() {
        return "Tests if indy MethodHandle resolution is propagated over redefined classes.";
    }
}

Passes:

private void runTest(byte[] classBytes, byte[] classBytesOriginal, boolean indy) {
        /* call test method that runs invokedynamic. This should invoke the BSM to resolve the callsite */
        if (indy) {
            redefineClass(rc020_testIndyAsmGenerator.testClass, classBytes.length, classBytes);
            rc020_Source.testCall();
        }
    }

Fails:

private void runTest(byte[] classBytes, byte[] classBytesOriginal, boolean indy) {
        /* call test method that runs invokedynamic. This should invoke the BSM to resolve the callsite */
        if (indy) {
            redefineClass(rc020_testIndyAsmGenerator.testClass, classBytes.length, classBytes);
            rc020_Source.testCall();
        }
        else {
            redefineClass(rc020_testIndyAsmGenerator.testClass, classBytesOriginal.length, classBytesOriginal);
            rc020_Source.testCall();
        }
    }
harryyu1994 picture harryyu1994 on 27 Nov 2019

RuntimeAssumptions + Hooks + MethodHandles trace

-Xshareclasses:none -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation,verbose={runtimeAssumptions,methodHandles,methodHandleDetails,patching,hooks,hookDetails},limit={*rc020.runTest*},traceFull,log=compile.log,vlog=verbose.log,optLevel=noopt
  1. nonJITServer
#INFO:  StartTime: Nov 28 12:37:30 2019
#INFO:  Free Physical Memory: 6870 MB 
#INFO:  CPU entitlement = 800.00
#HK:  e6fa00 hook jitIllegalFinalFieldModification vmThread=0000000000E6FA00 class 0000000000E96C00 java/lang/J9VMInternals
#RA:  key 0000000000E96C00 not registered!
#HD:  e6fa00 finished 
#HK:  e6fa00 hook jitIllegalFinalFieldModification vmThread=0000000000E6FA00 class 0000000000EA1B00 java/lang/String
#RA:  key 0000000000EA1B00 not registered!
#HD:  e6fa00 finished 
#HK:  e6fa00 hook jitIllegalFinalFieldModification vmThread=0000000000E6FA00 class 0000000000EAE300 java/lang/System
#RA:  key 0000000000EAE300 not registered!
#HD:  e6fa00 finished 
#HK:  e6fa00 hook jitClassesRedefined vmThread=0000000000E6FA00 
#HD:   e6fa00: Redefined class old=0000000000FD1200 new=0000000000FDB600 stale=0000000000FDB600 fresh=0000000000FD1200 com/ibm/jvmti/tests/redefineClasses/rc020_Source
#HD:   e6fa00:   Invalidate compilation requests for classes old=0000000000FD1200 and new=0000000000FDB600
#HK:  invalidateRequestsForUnloadedMethods class=0000000000FD1200 vmThread=0000000000E6FA00 hotCodeReplacement=1
#HK:  invalidateRequestsForUnloadedMethods class=0000000000FDB600 vmThread=0000000000E6FA00 hotCodeReplacement=1
#HD:   e6fa00:     Notify MCC for method stale=0000000000FD13A0 fresh=0000000000FDB578 e=0
#HD:   e6fa00:     Notify MCC for method stale=0000000000FD13C0 fresh=0000000000FDB5B8 e=0
#HD:   e6fa00:     Notify MCC for method stale=0000000000FD13E0 fresh=0000000000FDB598 e=0
#HD:   e6fa00:   Notify RAT on class old=0000000000FD1200 fresh=0000000000FD1200
#RA:  Scanning for PIC assumptions for 0000000000FD1200 in array 00007FC6350AE510 bucket 00007FC6350AEB08
#RA:  oldKey 0000000000FD1200 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000000FD1200 in array 00007FC6350AFCF0 bucket 00007FC6350B02E8
#RA:  oldKey 0000000000FD1200 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   e6fa00:     Notify RAT on method old=0000000000FD13A0 fresh=0000000000FDB578
#RA:  Scanning for PIC assumptions for 0000000000FD13A0 in array 00007FC6350AE510 bucket 00007FC6350AEB10
#RA:  oldKey 0000000000FD13A0 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000000FD13A0 in array 00007FC6350AFCF0 bucket 00007FC6350B02F0
#RA:  oldKey 0000000000FD13A0 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   e6fa00:     Notify RAT on method old=0000000000FD13C0 fresh=0000000000FDB5B8
#RA:  Scanning for PIC assumptions for 0000000000FD13C0 in array 00007FC6350AE510 bucket 00007FC6350AECE0
#RA:  oldKey 0000000000FD13C0 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000000FD13C0 in array 00007FC6350AFCF0 bucket 00007FC6350B04C0
#RA:  oldKey 0000000000FD13C0 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   e6fa00:     Notify RAT on method old=0000000000FD13E0 fresh=0000000000FDB598
#RA:  Scanning for PIC assumptions for 0000000000FD13E0 in array 00007FC6350AE510 bucket 00007FC6350AE6D8
#RA:  oldKey 0000000000FD13E0 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000000FD13E0 in array 00007FC6350AFCF0 bucket 00007FC6350AFEB8
#RA:  oldKey 0000000000FD13E0 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:  e6fa00 finished 
#HK:  e6fa00 hook jitClassesRedefined vmThread=0000000000E6FA00 
#HD:   e6fa00: Redefined class old=0000000000FD1200 new=0000000000FDB800 stale=0000000000FDB800 fresh=0000000000FD1200 com/ibm/jvmti/tests/redefineClasses/rc020_Source
#HD:   e6fa00:   Invalidate compilation requests for classes old=0000000000FD1200 and new=0000000000FDB800
#HK:  invalidateRequestsForUnloadedMethods class=0000000000FD1200 vmThread=0000000000E6FA00 hotCodeReplacement=1
#HK:  invalidateRequestsForUnloadedMethods class=0000000000FDB800 vmThread=0000000000E6FA00 hotCodeReplacement=1
#HD:   e6fa00:     Notify MCC for method stale=0000000000FDB578 fresh=0000000000FDB770 e=1
#HD:   e6fa00:     Notify MCC for method stale=0000000000FDB598 fresh=0000000000FDB790 e=0
#HD:   e6fa00:     Notify MCC for method stale=0000000000FDB5B8 fresh=0000000000FDB7B0 e=1
#HD:   e6fa00:   Notify RAT on class old=0000000000FD1200 fresh=0000000000FD1200
#RA:  Scanning for PIC assumptions for 0000000000FD1200 in array 00007FC6350AE510 bucket 00007FC6350AEB08
#RA:  oldKey 0000000000FD1200 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000000FD1200 in array 00007FC6350AFCF0 bucket 00007FC6350B02E8
#RA:  oldKey 0000000000FD1200 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   e6fa00:     Notify RAT on method old=0000000000FDB578 fresh=0000000000FDB770
#RA:  Scanning for PIC assumptions for 0000000000FDB578 in array 00007FC6350AE510 bucket 00007FC6350AE898
#RA:  oldKey 0000000000FDB578 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000000FDB578 in array 00007FC6350AFCF0 bucket 00007FC6350B0078
#RA:  oldKey 0000000000FDB578 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   e6fa00:     Notify RAT on method old=0000000000FDB598 fresh=0000000000FDB790
#RA:  Scanning for PIC assumptions for 0000000000FDB598 in array 00007FC6350AE510 bucket 00007FC6350AEA68
#RA:  oldKey 0000000000FDB598 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000000FDB598 in array 00007FC6350AFCF0 bucket 00007FC6350B0248
#RA:  oldKey 0000000000FDB598 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   e6fa00:     Notify RAT on method old=0000000000FDB5B8 fresh=0000000000FDB7B0
#RA:  Scanning for PIC assumptions for 0000000000FDB5B8 in array 00007FC6350AE510 bucket 00007FC6350AEC38
#RA:  oldKey 0000000000FDB5B8 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000000FDB5B8 in array 00007FC6350AFCF0 bucket 00007FC6350B0418
#RA:  oldKey 0000000000FDB5B8 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:  e6fa00 finished 
#RA:  Adding ClassRedefinitionPIC assumption: TR_RedefinedClassPicSite@00007FC63518C110: key=0000000000FDB790 picLocation=00007FC622C001AE size=8
#RA:  Adding RegisterNative assumption: TR_PatchJNICallSite@00007FC63518C150: key=0000000000FD0200 pc=00007FC622C00113
#HK:  e6fa00 hook jitClassesRedefined vmThread=0000000000E6FA00 
#HD:   e6fa00: Redefined class old=0000000000FD1200 new=0000000000FDBA00 stale=0000000000FDBA00 fresh=0000000000FD1200 com/ibm/jvmti/tests/redefineClasses/rc020_Source
#HD:   e6fa00:   Invalidate compilation requests for classes old=0000000000FD1200 and new=0000000000FDBA00
#HK:  invalidateRequestsForUnloadedMethods class=0000000000FD1200 vmThread=0000000000E6FA00 hotCodeReplacement=1
#HK:  invalidateRequestsForUnloadedMethods class=0000000000FDBA00 vmThread=0000000000E6FA00 hotCodeReplacement=1
#HD:   e6fa00:     Notify MCC for method stale=0000000000FDB770 fresh=0000000000FDB970 e=1
#HD:   e6fa00:     Notify MCC for method stale=0000000000FDB790 fresh=0000000000FDB990 e=0
#HD:   e6fa00:     Notify MCC for method stale=0000000000FDB7B0 fresh=0000000000FDB9B0 e=1
#HD:   e6fa00:   Notify RAT on class old=0000000000FD1200 fresh=0000000000FD1200
#RA:  Scanning for PIC assumptions for 0000000000FD1200 in array 00007FC6350AE510 bucket 00007FC6350AEB08
#RA:  oldKey 0000000000FD1200 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000000FD1200 in array 00007FC6350AFCF0 bucket 00007FC6350B02E8
#RA:  oldKey 0000000000FD1200 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   e6fa00:     Notify RAT on method old=0000000000FDB770 fresh=0000000000FDB970
#RA:  Scanning for PIC assumptions for 0000000000FDB770 in array 00007FC6350AE510 bucket 00007FC6350AE9B0
#RA:  oldKey 0000000000FDB770 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000000FDB770 in array 00007FC6350AFCF0 bucket 00007FC6350B0190
#RA:  oldKey 0000000000FDB770 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   e6fa00:     Notify RAT on method old=0000000000FDB790 fresh=0000000000FDB990
#RA:  Scanning for PIC assumptions for 0000000000FDB790 in array 00007FC6350AE510 bucket 00007FC6350AEB80
#RA:  old=0000000000FDB790 @ 00007FC622C001AE compensating new=0000000000FDB990 (array 00007FC6350AE510 bucket 00007FC6350AE920)
#RA:  Scanning for NOP assumptions for 0000000000FDB790 in array 00007FC6350AFCF0 bucket 00007FC6350B0360
#RA:  oldKey 0000000000FDB790 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   e6fa00:     Notify RAT on method old=0000000000FDB7B0 fresh=0000000000FDB9B0
#RA:  Scanning for PIC assumptions for 0000000000FDB7B0 in array 00007FC6350AE510 bucket 00007FC6350AE578
#RA:  oldKey 0000000000FDB7B0 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000000FDB7B0 in array 00007FC6350AFCF0 bucket 00007FC6350AFD58
#RA:  oldKey 0000000000FDB7B0 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:  e6fa00 finished
  1. JITServer
#INFO:  StartTime: Nov 28 12:38:36 2019
#INFO:  Free Physical Memory: 6844 MB 
#INFO:  CPU entitlement = 800.00
#HK:  1c6fa00 hook jitIllegalFinalFieldModification vmThread=0000000001C6FA00 class 0000000001C96C00 java/lang/J9VMInternals
#RA:  key 0000000001C96C00 not registered!
#HD:  1c6fa00 finished 
#HK:  1c6fa00 hook jitIllegalFinalFieldModification vmThread=0000000001C6FA00 class 0000000001CA1B00 java/lang/String
#RA:  key 0000000001CA1B00 not registered!
#HD:  1c6fa00 finished 
#HK:  1c6fa00 hook jitIllegalFinalFieldModification vmThread=0000000001C6FA00 class 0000000001CAE300 java/lang/System
#RA:  key 0000000001CAE300 not registered!
#HD:  1c6fa00 finished 
#HK:  1c6fa00 hook jitClassesRedefined vmThread=0000000001C6FA00 
#HD:   1c6fa00: Redefined class old=0000000001DD1200 new=0000000001DDB600 stale=0000000001DDB600 fresh=0000000001DD1200 com/ibm/jvmti/tests/redefineClasses/rc020_Source
#HD:   1c6fa00:   Invalidate compilation requests for classes old=0000000001DD1200 and new=0000000001DDB600
#HK:  invalidateRequestsForUnloadedMethods class=0000000001DD1200 vmThread=0000000001C6FA00 hotCodeReplacement=1
#HK:  invalidateRequestsForUnloadedMethods class=0000000001DDB600 vmThread=0000000001C6FA00 hotCodeReplacement=1
#HD:   1c6fa00:     Notify MCC for method stale=0000000001DD13A0 fresh=0000000001DDB578 e=0
#HD:   1c6fa00:     Notify MCC for method stale=0000000001DD13C0 fresh=0000000001DDB5B8 e=0
#HD:   1c6fa00:     Notify MCC for method stale=0000000001DD13E0 fresh=0000000001DDB598 e=0
#HD:   1c6fa00:   Notify RAT on class old=0000000001DD1200 fresh=0000000001DD1200
#RA:  Scanning for PIC assumptions for 0000000001DD1200 in array 00007F725DAE7510 bucket 00007F725DAE76A0
#RA:  oldKey 0000000001DD1200 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000001DD1200 in array 00007F725DAE8CF0 bucket 00007F725DAE8E80
#RA:  oldKey 0000000001DD1200 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   1c6fa00:     Notify RAT on method old=0000000001DD13A0 fresh=0000000001DDB578
#RA:  Scanning for PIC assumptions for 0000000001DD13A0 in array 00007F725DAE7510 bucket 00007F725DAE76A8
#RA:  oldKey 0000000001DD13A0 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000001DD13A0 in array 00007F725DAE8CF0 bucket 00007F725DAE8E88
#RA:  oldKey 0000000001DD13A0 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   1c6fa00:     Notify RAT on method old=0000000001DD13C0 fresh=0000000001DDB5B8
#RA:  Scanning for PIC assumptions for 0000000001DD13C0 in array 00007F725DAE7510 bucket 00007F725DAE7878
#RA:  oldKey 0000000001DD13C0 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000001DD13C0 in array 00007F725DAE8CF0 bucket 00007F725DAE9058
#RA:  oldKey 0000000001DD13C0 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   1c6fa00:     Notify RAT on method old=0000000001DD13E0 fresh=0000000001DDB598
#RA:  Scanning for PIC assumptions for 0000000001DD13E0 in array 00007F725DAE7510 bucket 00007F725DAE7A48
#RA:  oldKey 0000000001DD13E0 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000001DD13E0 in array 00007F725DAE8CF0 bucket 00007F725DAE9228
#RA:  oldKey 0000000001DD13E0 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:  1c6fa00 finished 
#HK:  1c6fa00 hook jitClassesRedefined vmThread=0000000001C6FA00 
#HD:   1c6fa00: Redefined class old=0000000001DD1200 new=0000000001DDB800 stale=0000000001DDB800 fresh=0000000001DD1200 com/ibm/jvmti/tests/redefineClasses/rc020_Source
#HD:   1c6fa00:   Invalidate compilation requests for classes old=0000000001DD1200 and new=0000000001DDB800
#HK:  invalidateRequestsForUnloadedMethods class=0000000001DD1200 vmThread=0000000001C6FA00 hotCodeReplacement=1
#HK:  invalidateRequestsForUnloadedMethods class=0000000001DDB800 vmThread=0000000001C6FA00 hotCodeReplacement=1
#HD:   1c6fa00:     Notify MCC for method stale=0000000001DDB578 fresh=0000000001DDB770 e=1
#HD:   1c6fa00:     Notify MCC for method stale=0000000001DDB598 fresh=0000000001DDB790 e=0
#HD:   1c6fa00:     Notify MCC for method stale=0000000001DDB5B8 fresh=0000000001DDB7B0 e=1
#HD:   1c6fa00:   Notify RAT on class old=0000000001DD1200 fresh=0000000001DD1200
#RA:  Scanning for PIC assumptions for 0000000001DD1200 in array 00007F725DAE7510 bucket 00007F725DAE76A0
#RA:  oldKey 0000000001DD1200 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000001DD1200 in array 00007F725DAE8CF0 bucket 00007F725DAE8E80
#RA:  oldKey 0000000001DD1200 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   1c6fa00:     Notify RAT on method old=0000000001DDB578 fresh=0000000001DDB770
#RA:  Scanning for PIC assumptions for 0000000001DDB578 in array 00007F725DAE7510 bucket 00007F725DAE7C08
#RA:  oldKey 0000000001DDB578 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000001DDB578 in array 00007F725DAE8CF0 bucket 00007F725DAE93E8
#RA:  oldKey 0000000001DDB578 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   1c6fa00:     Notify RAT on method old=0000000001DDB598 fresh=0000000001DDB790
#RA:  Scanning for PIC assumptions for 0000000001DDB598 in array 00007F725DAE7510 bucket 00007F725DAE7600
#RA:  oldKey 0000000001DDB598 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000001DDB598 in array 00007F725DAE8CF0 bucket 00007F725DAE8DE0
#RA:  oldKey 0000000001DDB598 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   1c6fa00:     Notify RAT on method old=0000000001DDB5B8 fresh=0000000001DDB7B0
#RA:  Scanning for PIC assumptions for 0000000001DDB5B8 in array 00007F725DAE7510 bucket 00007F725DAE77D0
#RA:  oldKey 0000000001DDB5B8 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000001DDB5B8 in array 00007F725DAE8CF0 bucket 00007F725DAE8FB0
#RA:  oldKey 0000000001DDB5B8 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:  1c6fa00 finished 
#HK:  1c6fa00 hook jitClassesRedefined vmThread=0000000001C6FA00 
#HD:   1c6fa00: Redefined class old=0000000001DD1200 new=0000000001DDBA00 stale=0000000001DDBA00 fresh=0000000001DD1200 com/ibm/jvmti/tests/redefineClasses/rc020_Source
#HD:   1c6fa00:   Invalidate compilation requests for classes old=0000000001DD1200 and new=0000000001DDBA00
#HK:  invalidateRequestsForUnloadedMethods class=0000000001DD1200 vmThread=0000000001C6FA00 hotCodeReplacement=1
#HK:  invalidateRequestsForUnloadedMethods class=0000000001DDBA00 vmThread=0000000001C6FA00 hotCodeReplacement=1
#HD:   1c6fa00:     Notify MCC for method stale=0000000001DDB770 fresh=0000000001DDB970 e=1
#HD:   1c6fa00:     Notify MCC for method stale=0000000001DDB790 fresh=0000000001DDB990 e=0
#HD:   1c6fa00:     Notify MCC for method stale=0000000001DDB7B0 fresh=0000000001DDB9B0 e=1
#HD:   1c6fa00:   Notify RAT on class old=0000000001DD1200 fresh=0000000001DD1200
#RA:  Scanning for PIC assumptions for 0000000001DD1200 in array 00007F725DAE7510 bucket 00007F725DAE76A0
#RA:  oldKey 0000000001DD1200 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000001DD1200 in array 00007F725DAE8CF0 bucket 00007F725DAE8E80
#RA:  oldKey 0000000001DD1200 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   1c6fa00:     Notify RAT on method old=0000000001DDB770 fresh=0000000001DDB970
#RA:  Scanning for PIC assumptions for 0000000001DDB770 in array 00007F725DAE7510 bucket 00007F725DAE7548
#RA:  oldKey 0000000001DDB770 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000001DDB770 in array 00007F725DAE8CF0 bucket 00007F725DAE8D28
#RA:  oldKey 0000000001DDB770 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   1c6fa00:     Notify RAT on method old=0000000001DDB790 fresh=0000000001DDB990
#RA:  Scanning for PIC assumptions for 0000000001DDB790 in array 00007F725DAE7510 bucket 00007F725DAE7718
#RA:  oldKey 0000000001DDB790 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000001DDB790 in array 00007F725DAE8CF0 bucket 00007F725DAE8EF8
#RA:  oldKey 0000000001DDB790 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:   1c6fa00:     Notify RAT on method old=0000000001DDB7B0 fresh=0000000001DDB9B0
#RA:  Scanning for PIC assumptions for 0000000001DDB7B0 in array 00007F725DAE7510 bucket 00007F725DAE78E8
#RA:  oldKey 0000000001DDB7B0 not registered with PIC!
#RA:  Scanning for NOP assumptions for 0000000001DDB7B0 in array 00007F725DAE8CF0 bucket 00007F725DAE90C8
#RA:  oldKey 0000000001DDB7B0 not registered with NOP!
#RA:  Scanning for unresolved PIC assumptions
#RA:  Scanning for unresolved PIC address materialization assumptions
#HD:  1c6fa00 finished
harryyu1994 picture harryyu1994 on 28 Nov 2019

By comparing the two verbose logs, I noticed that JITServer is missing these two runtime assumptions

#RA:  Adding ClassRedefinitionPIC assumption: TR_RedefinedClassPicSite@00007FC63518C110: key=0000000000FDB790 picLocation=00007FC622C001AE size=8   
#RA:  Adding RegisterNative assumption: TR_PatchJNICallSite@00007FC63518C150: key=0000000000FD0200 pc=00007FC622C00113
harryyu1994 picture harryyu1994 on 28 Nov 2019

Could you apply my proposed fix to runtime assumptions in #7907 ?
This will be a good to test to verify that I didn't do any mistakes in that PR.

mpirvu picture mpirvu on 28 Nov 2019
👍1 
[ERR] *** Invalid JIT return address 00000000E0015218 in 0000000001322D08
[ERR] 
[ERR] 23:03:31.796 0x1322a00    j9vm.249    *   ** ASSERTION FAILED ** at swalk.c:1565: ((0 ))

Reduced testcase available here: https://github.com/harryyu1994/openj9/commit/01ef0f74ead1be9e1ea3065792c563c290b33cf5

git cherry-pick 01ef0f74ead1be9e1ea3065792c563c290b33cf5
cd openj9/test/TestConfig
export NATIVE_TEST_LIBS=/root/Harry_Build/openj9-openjdk-jdk8/build/linux-x86_64-normal-server-release/images/test/openj9
export TEST_JDK_HOME=/root/Harry_Build/openj9-openjdk-jdk8/build/linux-x86_64-normal-server-release/images/j2sdk-image
export EXTRA_OPTIONS=" -XX:+UseJITServer "
make -f run_configure.mk
make compile
make _cmdLineTester_jvmtitests_hcr_OSRG_nongold_SE80_3
harryyu1994 picture harryyu1994 on 29 Nov 2019

After correcting a bug in my Runtime Assumption leak PR the test passes. I am running locally the extended suite to see if the other tests pass as well.

mpirvu picture mpirvu on 29 Nov 2019

Looking into cmdLineTester_jvmtitests_debug_3, as this is a jvmti redefine class related test as well, there's a chance that it will be fixed by #7907 as well.

Test result: FAILED
Output from test:
 [ERR] JVMCDRT000E Unable to locate JIT stack map - aborting VM
 [ERR] JVMCDRT001E Method: java/lang/Object.<init>()V (00000000026412A8)
 [ERR] JVMCDRT002E Failing PC: 00007F4149A0027E (offset 000000000000001E), metaData = 00007F41491B02F8
 [ERR] 02:46:39.453 0x261ea00j9codertvm(j9ji.110    *   ** ASSERTION FAILED ** at jswalk.c:538: ((0 ))

Some notes:

  • nonJITServer mode passed the test (40 runs without fail)
  • JITServer mode (without #7907) failed, the failure rate is about 1/20
  • JITServer mode (with #7907) passed, don't see the failure(I did 80 runs)
    Looks like #7907 has fixed it.
harryyu1994 picture harryyu1994 on 30 Nov 2019

Currently, there are no more sanity or extended failures with JITServer code. This issue can be closed.

mpirvu picture mpirvu on 2 Dec 2019
Was this page helpful?
0 / 5 - 0 ratings

Related issues

0xdaryl picture 0xdaryl  路  3Comments
AdamBrousseau picture AdamBrousseau  路  6Comments
ciplogic picture ciplogic  路  3Comments
pwagland picture pwagland  路  3Comments
Mesbah-Alam picture Mesbah-Alam  路  5Comments