Reason and tracing of class loading during verification, method execution and JIT compilation

Question

I'm trying to understand which events lead to class loads on a very detailed basis and during my testing encountered one behaviour I do not understand in this very basic sample:

public class ClinitTest {
    public static Integer num;
    public static Long NUMTEST;

    static {
        NUMTEST = new Long(15);;
        num = (int) (NUMTEST * 5);
        System.out.println(num);
    }

    public static void main(String[] args) {
        System.out.println( "The number is " + num);
    }
}

When running java.lang.Long gets loaded while executing the <clinit>. Well, it gets loaded earlier by bootstrap classloader but the AppClassloader is called at that point as it is not yet registered as initiating classloader. So the LauncherHelper will get the application class and before it can invoke the main method the JVM will ensure the class is initialized. During execution of <clinit> this class load happens.

In another run I use a Java agent to rename the <clinit> to something else and add an empty one instead. My expectation was that - since the original <clinit> code does not get executed I would not get the class load events either.

Strangely it seems that at this time the load of java.lang.Long happens at a much earlier time though. In my trace I see that it gets triggered when the LauncherHelper tries to validate the main class. Here it tries to get the main method via reflection and the call to java.lang.Class.getDeclaredMethods0() under the hood leads to the invocation of the AppClassLoader asking for java.lang.Long.

So the questions are:

How is it possible that at normal execution time the class is loaded later (i.e. when the code gets actually executed) but it is loaded so early when the code should actually never get executed because the renamed clinit is never called?
Is there a way in the JVM to trace which events lead to such class loads? Not just when it happens, but really which instruction or event lead to it as it could be caused by a class being first used, another class being verified, JIT compiled, etc.

score 4 · Accepted Answer · answered Aug 19 '18 at 17:51

With the help of an agent that subscribes to JVMTI ClassLoad event I've verified that java.lang.Long is not loaded when running ClinitTest with static initialized removed.

Since you are running a test with a Java agent, I suppose that either

java.lang.Long is loaded by the agent itself during the transformation of your class;
or the agent adds/modifies a public method with Long class in the signature.

When LauncherHelper validates the main class, it traverses public methods looking for public static void main(). As a side effect, all classes mentioned in the signatures of these methods are resolved.

I'm not aware of an existing tool that allows to trace class loading with respect to JVM internal events, but such a tool can be easily written in a few lines of code. Here it is.

#include <jvmti.h>
#include <string.h>
#include <stdio.h>
#include <stdlib.h>
#include <libunwind.h>
#include <cxxabi.h>

static char* fix_class_name(char* class_name) {
    class_name[strlen(class_name) - 1] = 0;
    return class_name + 1;
}

static void print_native_backtrace() {
    unw_context_t context;
    unw_cursor_t cursor;
    unw_getcontext(&context);
    unw_init_local(&cursor, &context);

    char func[256];
    unw_word_t offs;
    while (unw_step(&cursor) > 0 && unw_get_proc_name(&cursor, func, sizeof(func), &offs) == 0) {
        if (func[0] == '_' && func[1] == 'Z') {
            int status;
            char* demangled = abi::__cxa_demangle(func, NULL, NULL, &status);
            if (demangled != NULL) {
                strncpy(func, demangled, sizeof(func));
                free(demangled);
            }
        }
        printf("  - %s + 0x%x\n", func, offs);
    }
}

static void print_java_backtrace(jvmtiEnv *jvmti) {
    jvmtiFrameInfo framebuf[256];
    int num_frames;
    if (jvmti->GetStackTrace(NULL, 0, 256, framebuf, &num_frames) == 0 && num_frames > 0) {
        for (int i = 0; i < num_frames; i++) {
            char* method_name = NULL;
            char* class_name = NULL;
            jclass method_class;

            jvmtiError err;
            if ((err = jvmti->GetMethodName(framebuf[i].method, &method_name, NULL, NULL)) == 0 &&
                (err = jvmti->GetMethodDeclaringClass(framebuf[i].method, &method_class)) == 0 &&
                (err = jvmti->GetClassSignature(method_class, &class_name, NULL)) == 0) {
                printf("  * %s.%s + %ld\n", fix_class_name(class_name), method_name, framebuf[i].location);
            } else {
                printf(" [jvmtiError %d]\n", err);
            }

            jvmti->Deallocate((unsigned char*)class_name);
            jvmti->Deallocate((unsigned char*)method_name);
        }
    }
}

void JNICALL ClassLoad(jvmtiEnv *jvmti, JNIEnv* jni, jthread thread, jclass klass) {
    char* class_name;
    jvmti->GetClassSignature(klass, &class_name, NULL);
    printf("Class loaded: %s\n", fix_class_name(class_name));
    jvmti->Deallocate((unsigned char*)class_name);

    print_native_backtrace();
    print_java_backtrace(jvmti);
}

JNIEXPORT jint JNICALL Agent_OnLoad(JavaVM *vm, char *options, void *reserved) {
    jvmtiEnv *jvmti;
    vm->GetEnv((void**)&jvmti, JVMTI_VERSION_1_0);

    jvmtiEventCallbacks callbacks = {0};
    callbacks.ClassLoad = ClassLoad;
    jvmti->SetEventCallbacks(&callbacks, sizeof(callbacks));
    jvmti->SetEventNotificationMode(JVMTI_ENABLE, JVMTI_EVENT_CLASS_LOAD, NULL);

    return 0;
}

Compile:

g++ -shared -fPIC -olibclassload.so classload.c -lunwind -lunwind-x86_64

Run:

java -agentpath:/path/to/libclassload.so ClinitTest

It will show a mixed stack trace (C + Java) whenever a class load event happens, e.g.

Class loaded: java/lang/Long
  - ClassLoad(_jvmtiEnv*, JNIEnv_*, _jobject*, _jclass*) + 0x69
  - JvmtiExport::post_class_load(JavaThread*, Klass*) + 0x15b
  - SystemDictionary::resolve_instance_class_or_null(Symbol*, Handle, Handle, Thread*) + 0x87c
  - SystemDictionary::resolve_or_fail(Symbol*, Handle, Handle, bool, Thread*) + 0x33
  - get_mirror_from_signature(methodHandle, SignatureStream*, Thread*) + 0xc6
  - Reflection::get_parameter_types(methodHandle, int, oopDesc**, Thread*) + 0x5df
  - Reflection::new_method(methodHandle, bool, bool, Thread*) + 0xfc
  - get_class_declared_methods_helper(JNIEnv_*, _jclass*, unsigned char, bool, Klass*, Thread*) + 0x479
  - JVM_GetClassDeclaredMethods + 0xcb
  * java/lang/Class.getDeclaredMethods0 @ -1
  * java/lang/Class.privateGetDeclaredMethods @ 37
  * java/lang/Class.privateGetMethodRecursive @ 2
  * java/lang/Class.getMethod0 @ 16
  * java/lang/Class.getMethod @ 13
  * sun/launcher/LauncherHelper.validateMainClass @ 12
  * sun/launcher/LauncherHelper.checkAndLoadMain @ 214

Awesome! Your little trace tool helped to proof what you already assumed: There is no Java agent at all, but it was indeed a newly generated public setter method that was added by a colleague of mine for test purposes in one of the many transformers. I was not aware of that and he forgot to mention it. Since without the C trace I only saw `Class.getDeclaredMethods0` followed by a class load I was puzzled since the type that was loaded also changed when I changed the type of the static variable (which now makes sense knowing there is a generated getter method and seeing the native trace).THANKS — Haasip Satang, Aug 21 '18 at 17:37

Reason and tracing of class loading during verification, method execution and JIT compilation

1 Answers1

Linked