8

My understanding of classloading was that a class gets loaded when it is first needed (to put it in a very simple way). Running the following sample with -verbose:class and a modified version of the Iterators class that prints a message when its clinit is called I observed something that I can not really explain though:

public class IteratorsTest
{
    public static void main(String[] args)
    {
        com.google.common.collect.Iterators.forArray(1, 2, 3);
    }
}

The (cleaned-up) output is the following:

[Loaded com.google.common.collect.Iterators from file:...]
[Loaded com.google.common.collect.Iterators$1 from file:...]
---------> Iterators <clinit>

Why is Iterators$1 loaded before clinit is called? It is only defined in the clinit, isn't it?

  static final UnmodifiableListIterator<Object> EMPTY_LIST_ITERATOR =
      new UnmodifiableListIterator<Object>() {
  ...
  }

Which results in the following byte code:

static <clinit>()V
   L0
    GETSTATIC java/lang/System.out : Ljava/io/PrintStream;
    LDC "---------> Iterators clinit --------------"**
    INVOKEVIRTUAL java/io/PrintStream.println (Ljava/lang/String;)V
   L1
    NEW com/google/common/collect/Iterators$1
    DUP
    INVOKESPECIAL com/google/common/collect/Iterators$1.<init> ()V
   L2
    PUTSTATIC com/google/common/collect/Iterators.EMPTY_LIST_ITERATOR : Lcom/google/common/collect/UnmodifiableListIterator;

And to confuse me even more I have one more sample (too complex to post here) where the same line of code as in the main above leads to the following output:

[Loaded com.google.common.collect.Iterators from file:...]
---------> Iterators <clinit>
[Loaded com.google.common.collect.Iterators$1 from file:...]

This is actually what I would have expected from the simple test program as well.

I tried to find the answer here https://docs.oracle.com/javase/specs/jvms/se7/html/jvms-5.html , but that didn't really help.

  • What could be the reason for sometimes the clinit being executed first and sometimes the anonymous class being loaded first?
  • Is there a way to trace when the JVM invokes the clinit of the classes? something similar to -verbose:class or -XX:+TraceClassLoading, etc?
Haasip Satang
  • 457
  • 3
  • 17
  • openjdk9's new logging infrastructure allows fairly fine-grained breakdown of a lot of internals, including class loading and initialization. maybe that'll provide the information you want. – the8472 Jan 15 '17 at 12:33
  • Good idea, I read about the new logging features but haven't tried them yet. Maybe worth to do a test run. Thanks! – Haasip Satang Jan 15 '17 at 15:54
  • Although I found it I wanted to know if JDK9 would have helped, and yes indeed, that would have done the job. I started with -Xlog:class+init=info,class+load=info:file=trace.log (btw: is there a complete list of available selectors somewhere? What is provided here http://openjdk.java.net/jeps/158 is not really enough). PS: it was actually your comment here http://stackoverflow.com/questions/39321345/how-do-i-measure-jvm-startup-time where I read about this first. – Haasip Satang Jan 16 '17 at 12:57
  • see http://stackoverflow.com/q/41678557/1362755 – the8472 Jan 16 '17 at 14:24

2 Answers2

9

What could be the reason for sometimes the clinit being executed first and sometimes the anonymous class being loaded first?

the class load process contains the follow process.

  • loading
  • linking
    • verification
    • preparation
    • Resolution
  • initialization
  • Using
  • unload

and now what we focus on resolution and initialization phase for the reference class loaded take place at resolution phase and the <clint> take place at initialization phase. The order of loading verfication preparation initialization unloading is fixed, however the time when invoke resolution phase is not fixed, it may take place before initialization(correspond your former case) phase and it may also take place after initialization at some scenario(correspond your latter case).

For performance, the HotSpot VM generally waits until class initialization to load and link a class. So if class A references class B, loading class A will not necessarily cause loading of class B (unless required for verification). Execution of the first instruction that references B will cause initialization of B, which requires loading and linking of class B.

Is there a way to trace when the JVM invokes the clinit of the classes? something similar to -verbose:class or -XX:+TraceClassLoading, etc?

I dont know whether there exist some jvm parameter that you can get the time when jvm invokes <clinit> method directly, but there is another way that you can achieve this, using jvm_ti. You can listen some event like methodEntry and then get the time invoking <clinit> method. For more information google jvm_ti.

reference:

nail fei
  • 2,179
  • 3
  • 16
  • 36
  • I also ran with -XX:+TraceClassResolution but there is no output for Iterators$1 before the class is loaded. What makes you think that the time for the resolution is not fixed? To my understanding it is the instructions from chapter 5.4.3 of the JVM spec that lead to resolution of the symbolic references. These instructions are, however, only invoked during clinit (hence I would expect the resolution and load at that point). I really need to understand what triggers the loading of Iterators$1 before clinit of Iterators is called. – Haasip Satang Jan 15 '17 at 11:55
  • 1
    @Haasip Satang [the jvm specification 5.4 linking](https://docs.oracle.com/javase/specs/jvms/se7/html/jvms-5.html#jvms-5.4.3) says: `a Java Virtual Machine implementation may choose to resolve each symbolic reference in a class or interface individually when it is used ("lazy" or "late" resolution), or to resolve them all at once when the class is being verified ("eager" or "static" resolution).` – nail fei Jan 15 '17 at 12:35
  • Yes, but since we are talking about the same VM (not different implementations) I would have assumed the same behaviour. But even if the JVM decides to choose different approaches for the same line of code I would like to understand the reason for it. This surely is not random.It always loads the class first in program A while in B clinit is invoked first. The the method with one line of code is exactly the same in both programs. The question is why the JVM selects a different strategy. NOTE:I'm doing some research on non-determinism in the JVM, that's why I need to know this low level detail. – Haasip Satang Jan 15 '17 at 12:59
  • @Haasip Satang I agree with you that it is not random. And it seemed you can use *jvm parameter* `-XX:+TraceClassLoading -XX:+TraceClassResolution` it will log some *RESOLVE* info which tell use the reason that the class was loaded. And about your former example it log `RESOLVE com.google.common.collect.Iterators com.google.common.collect.Iterators$1 (verification)`, it respond to `the HotSpot VM generally waits until class initialization to load and link a class(unless required for verification)`. And I have update my answer,hope it is a little helpful for you. – nail fei Jan 15 '17 at 13:59
  • I appreciate your feedback but I have to admit that I still don't get the point. We both seem to have the same understanding of loading and resolution. I also used the jvm parameters you mentioned (as described above in my previous comments). None of that explains, however, why the JVM loads the anonymous class Iterators$1 BEFORE it was referenced in the clinit. In the log output I am getting I also to not get any RESOLVE statements refering to Iterators$1 before Iterators$1 is actually loaded. I'm still puzzled. PS: I updated the Q to add a little bytecode to show the 1st reference. – Haasip Satang Jan 15 '17 at 15:52
  • @Haasip Satang use Tthese **two** parameters `-XX:+TraceClassLoading -XX:+TraceClassResolution` at the same time. – nail fei Jan 16 '17 at 01:37
  • I always used both options but that didn't tell me anything. But I actually found the problem for the difference: The program that executed the clinit first was started with -noverify option. So it seems like the verifier led to the loading of the anonymous classes. Is this "(verification)" in the RESOLVE message part of the output you are getting from the JVM? Or did you add this manually in your comment because I don't get this. If it's from the VM, which version are you using? I'm on 1.8.0_102. Knowing that it's the verifier leading to the classload would have helped finding it faster. – Haasip Satang Jan 16 '17 at 12:35
  • @Haasip Satang: isn’t it obvious that the verification of the assignment of that anonymous inner class to a field of type `UnmodifiableListIterator` requires loading of *both*? Not omitting the type `UnmodifiableListIterator` from your log, “would have helped finding it faster” either… – Holger Jan 16 '17 at 12:47
  • @Holger I'm sorry, wasn't obvious to me (and still is not to be honest). Will need to read up on the details about the verifier. I assumed that it verifies the general byte code structure and maybe the availabilty of super classes and interfaces plus maybe field types. Since the creation of the Iterators$1 object only happens inside a method (although it's the clinit in this case) I would have expected a load at this point (or an exception in case the class is not available). Sorry for not posting the complete trace, I thought I covered the parts that were needed. – Haasip Satang Jan 16 '17 at 13:03
  • @Haasip Satang good job and victory lies ahead. I do get the message from jvm and the version of my jvm is 1.8.0_77. I have post the output and some screenShot on [issueExplore](https://github.com/cainiaofei/issueCommunicate/tree/master/issueExplore) . – nail fei Jan 16 '17 at 13:03
  • @Haasip Satang: the actual behavior is close to your expectation. It’s only that the verification of the `` method happens right before entering its execution, so the loading happens before the printing of the message. It’s not a required behavior. It’s also allowed to perform the type compatibility check right before executing the instruction; in that case, the message would be printed before the loading. – Holger Jan 16 '17 at 13:40
  • @Holger: I did some more tests and it seems not really related to the execution of the ``. Even if the field `EMPTY_LIST_ITERATOR` would be assigned later (let's say it wouldn't be final and the field would be assigned from an instance method that is never executed) the verifier would trigger the loading of the class type assigned to the field during verification already before `` is invoked (unless the field is of type Object or some interface). I really didn't know that. Seems to be this: https://docs.oracle.com/javase/specs/jvms/se7/html/jvms-4.html#jvms-4.10.1.2 . Thanks! – Haasip Satang Jan 16 '17 at 16:33
  • @nailfei Very interesting, I checked with three versions of jdk8 now (31, 66 and 102) and with none of them I get the `(verification)` suffix in the log. I do get `(explicit)`, `(super)`, `(reflection)`, etc, but never 'verification'. No clue why. With jdk9, however, the log is very nice and detailed now. – Haasip Satang Jan 16 '17 at 16:37
7

Here the summary of the solution for those who don't want to read through all the comments ;)

  1. The difference in the execution order was caused by one of the launchers having -noverify specified. The verifier may cause additional classes to be loaded as also specified here in the JVM Spec. Whether the class is loaded or not, seems to depend on the type of the field to which the object is assigned. More details here. On the other hand, when started with -noverify, there is no verification and hence the loading of the class only happens at exactly the point where it is first used in the code, which is inside the <clinit>in my case.
  2. There are ways to trace the invocation <clinit> without having to modify the byte code. One way is to use the -XX:+TraceClassInitialization on JDK8. This, however, requires a debug version of the JVM (NOTE: this is not your program started in debug mode but really the VM compiled with debug enabled. A guide for how to build it can be found here). The other way - that only comes with JDK9 though - is to use the new JEP 158: Unified JVM Logging feature and to provide something like the following when starting your program:
    -Xlog:class+load=info,class+init=info:file=trace.log (see here for how to get a complete list of tags and arguments)
Community
  • 1
  • 1
Haasip Satang
  • 457
  • 3
  • 17