== JSR 292 Startup

Here, we try to dissect the startup costs for JSR 292. We use three basic classes that do roughly the same: invoke
a virtual method. It is known from Indify String Concat and Jigsaw that initializing the JSR 292 infrastructure takes
it's toll on the startup performance.

public class HelloMH {

    private static int x;

    public static void main(String[] args) throws Throwable {
        System.out.println("main() enter");

        {
            System.out.println("main() first lookup");
            MethodHandles.Lookup lookup = MethodHandles.publicLookup();

            System.out.println("main() first method type");
            MethodType mt = MethodType.methodType(int.class, int.class);

            System.out.println("main() first findVirtual");
            MethodHandle m = lookup.findVirtual(HelloMH.class, "m", mt);

            System.out.println("main() first invoke");
            int r = (int) m.invokeExact(new HelloMH(), x);
        }

        {
            System.out.println("main() second lookup");
            MethodHandles.Lookup lookup = MethodHandles.publicLookup();

            System.out.println("main() second method type");
            MethodType mt = MethodType.methodType(int.class, int.class);

            System.out.println("main() second findVirtual");
            MethodHandle m = lookup.findVirtual(HelloMH.class, "m", mt);

            System.out.println("main() second invoke");
            int r = (int) m.invokeExact(new HelloMH(), x);
        }

        System.out.println("main() exit");
    }

    public int m(int x) {
        return x;
    }

}

public class HelloReflection {

    private static int x;

    public static void main(String[] args) throws Throwable {
        System.out.println("main() enter");

        {
            System.out.println("main() first lookup");
            Method m = HelloReflection.class.getMethod("m", int.class);

            System.out.println("main() first invoke");
            Object r = m.invoke(new HelloReflection(), x);
        }

        {
            System.out.println("main() second lookup");
            Method m = HelloReflection.class.getMethod("m", int.class);

            System.out.println("main() second invoke");
            Object r = m.invoke(new HelloReflection(), x);
        }

        System.out.println("main() exit");
    }

    public int m(int x) {
        return x;
    }
}

public class HelloVirtual {

    private static int x;

    public static void main(String[] args) throws Throwable {
        System.out.println("main() enter");

        System.out.println("main() first invoke");
        new HelloVirtual().m(x);

        System.out.println("main() second invoke");
        new HelloVirtual().m(x);
        System.out.println("main() exit");
    }

    public int m(int x) {
        return x;
    }

}


There is a very limited supply of tools that can profile the startup sequence, and so we are moderately well served
with a hand-on instrumentation that prints the event lines as we go through the startup process. The logging should not
be intrusive (for example, we cannot easily print extended debugging info, like MemberName.toString), so we use only
the simple strings. In order to correlate the events from different subsystems, we have to employ the external timing [1],
that attributes the time for each line in stdin. To make it less biased, we have to unbuffer the pipes. Also, since
the startup time may be attenuated by VM doing the background work, we bind everything on the same core.

$ unbuffer taskset -c 0 java -cp target/classes/ org.openjdk.HelloMH | perl timeit.pl 

== Results

The runs were done on 2015-06-08 jdk9-dev and Linux x86_64, i7-4790K 4.0 GHz.

=== HelloVirtual:

0.0 java launched
0.0 JavaMain
0.1 JavaMain: init VM
50.0 JavaMain: load main class
57.5 JavaMain: get main class
57.5 JavaMain: invoke java main
58.4 main() enter
58.5 main() first invoke
58.5 main() second invoke
58.5 main() exit
58.5 JavaMain exited

It takes around 50ms for JVM to initialize, then another 5-10ms to load the dependencies for Main class, and then 
very quickly resolve the target method and invoke it.


=== HelloReflection:

0.0 java launched
0.0 JavaMain
0.0 JavaMain: init VM
49.2 JavaMain: load main class
56.9 JavaMain: get main class
56.9 JavaMain: invoke java main
57.7 main() enter
57.8 main() first lookup
57.8 main() first invoke
58.1 main() second lookup
58.1 main() second invoke
58.2 main() exit
58.2 JavaMain exited

The same picture is painted here.

=== HelloMH

0.0 java launched
0.0 JavaMain
0.0 JavaMain: init VM
49.3 JavaMain: load main class
56.8 JavaMain: get main class
56.8 JavaMain: invoke java main
57.7 main() enter
57.7 main() first lookup
58.0 MethodHandles clinit
60.0 MethodHandles clinit ends
60.3 Lookup outer init
60.3 Lookup outer init ends
60.3 Lookup init
60.4 Lookup init ends
60.4 main() first method type
60.9 methodType(Class,Class)
61.1 methodType(Class,Class) ends
61.1 main() first findVirtual
61.1 findVirtual
61.2 findVirtual: resolveOrFail
61.4 findVirtual: getDirectMethod
61.5 getDirectMethodCommon
61.7 DMH.make
61.7 DMH.make: insert receiver
61.9 DMH.make: prepare lambda form
65.0 getDirectMethodCommon
65.1 DMH.make
65.1 DMH.make: prepare lambda form
65.8 DMH.make
 (10x "prepare lambda form" sequences)
72.9 DMH.make: create DMH (method)
73.6 DMH.make: ends
73.6 getDirectMethodCommon: ends
73.9 resolveOrFail: byte,Class,String,Class
74.0 resolveOrFail ends
74.0 DMH.make
74.1 DMH.make: insert receiver
74.1 DMH.make: prepare lambda form (field)
74.8 DMH.make: create DMH (field)
75.0 DMH.make: ends
 (13x "prepare lambda form" sequences)
89.2 getDirectMethodCommon: ends
89.3 findVirtual ends
89.3 main() first invoke
 (4x "prepare lambda form" sequences)
93.5 DMH.make: insert receiver
93.5 DMH.make: prepare lambda form
93.8 DMH.make: create DMH (method)
93.8 DMH.make: ends
94.5 main() second lookup
94.5 main() second method type
94.5 methodType(Class,Class)
94.6 methodType(Class,Class) ends
94.6 main() second findVirtual
94.6 findVirtual
94.6 findVirtual: resolveOrFail
94.6 findVirtual: getDirectMethod
94.6 getDirectMethodCommon
94.6 DMH.make
94.7 DMH.make: insert receiver
94.7 DMH.make: prepare lambda form
94.7 DMH.make: create DMH (method)
94.7 DMH.make: ends
94.7 getDirectMethodCommon: ends
94.8 findVirtual ends
94.8 main() second invoke
94.8 main() exit
94.8 JavaMain exited

Most of JSR 292 infra is lazy, and initialized on the first access. The second lookup and invocation are rather fast.
The first access creates quite a few lambda forms, which takes around 30ms.

== Resources

[1] timeit.pl: http://cr.openjdk.java.net/~shade/8086045/timeit.perl
[2] invoke-instr.patch: http://cr.openjdk.java.net/~shade/8086045/invoke-instr.patch