Showing posts with label GC. Show all posts
Showing posts with label GC. Show all posts

Tuesday, February 09, 2021

EpsilonGC and analyzing heap dump generated

Lets try to analyze the heap dump when our test program exits with OutOfMemoryError when run with EpsilonGC configuration. 

Code we use for this is the same test program we used in the previous post, which is 

class TestEpsilonGC {

    static final int ALLOCATION_SIZE = 1024 * 1024; // 1MB
    static final int LOOP_COUNT = 12;  
    static long start;

    public static void main(String[] args) {
        start();        
        for (int i = 0; i < LOOP_COUNT; i++) {
            System.out.print("Allocating iteration: "+i);
            byte[] array = new byte[ALLOCATION_SIZE];
            System.out.println(" Done");
        }
        end();
    }
    
    static void start() {
        start = System.currentTimeMillis();
}
    
    static void end() {
            System.out.println("Time taken: "+(System.currentTimeMillis() - start)+"ms");
    }
}

Now, lets run the below command to create the heap dump when the program exits with OutOfMemoryError

java -verbose:gc -Xmx10M -XX:+UnlockExperimentalVMOptions -XX:+UseEpsilonGC -XX:+HeapDumpOnOutOfMemoryError TestEpsilonGC 

This creates the .hprof file in the folder under which you executed the above command. Analyzing it with IBM Heap Analyzer, we find that all objects allocated by the code are listed in the heap dump


In our case, all the byte array objects created before OutOfMemoryError got thrown is listed. 

Remember when analyzing heap dump generated with EpsilonGC configuration, objects occupying the heap space are not necessarily leaked objects. All objects ever created during the run gets listed in the heap dump.

You could use EpsilonGC to 
  • Verify the performance characteristics of your application without any interference of GC overhead
  • Benchmark the heap space to duration of run for your application before it runs out of memory
  • Study all objects getting created and validate it against the design intent of your application
  • You could even choose to use it as final configuration for your application if your application is short lived. In this case having intermittent GC cycles could be undesirable as when application terminates, it will release all the memory
  • Or this could be useful for certain batch processes which are non memory intensive, which can restart and continue where it left off from the previous run 

We could use a simple technique to restart self when OutOfMemoryError is thrown. The next post details how this can be done. 

Sample code used in this post can be downloaded from https://github.com/ashokkumarta/awesomely-java/tree/main/2021/02/Garbage-Collection/EpsilonGC/analyzing-heap-dump

Monday, February 08, 2021

Measuring performance benefits of using EpsilonGC

Lets do a quick experiment to measure the performance benefit of using EpsilonGC.

For this, lets modify the previous program a bit adding in the code for instrumentation. We will use this modified code for our experiment

class TestEpsilonGC {

    static final int ALLOCATION_SIZE = 1024 * 1024; // 1MB
    static final int LOOP_COUNT = 12;  
    static long start;

    public static void main(String[] args) {
        start();        
        for (int i = 0; i < LOOP_COUNT; i++) {
            System.out.print("Allocating iteration: "+i);
            byte[] array = new byte[ALLOCATION_SIZE];
            System.out.println(" Done");
        }
        end();
    }
    
    static void start() {
        start = System.currentTimeMillis();
}
    
    static void end() {
            System.out.println("Time taken: "+(System.currentTimeMillis() - start)+"ms");
    }
}

Lets run this code with default GC now. We will increase the max heap size to 15M so as to allow the program to complete successfully with both the configurations. 

Here is the command and the output

java -verbose:gc -Xmx15M TestEpsilonGC
[0.012s][info][gc] Using G1
Allocating iteration: 0 Done
Allocating iteration: 1 Done
Allocating iteration: 2 Done
Allocating iteration: 3 Done
Allocating iteration: 4[0.075s][info][gc] GC(0) Pause Young (Concurrent Start) (G1 Humongous Allocation) 8M->0M(16M) 2.041ms
[0.075s][info][gc] GC(1) Concurrent Cycle
 Done
Allocating iteration: 5 Done
Allocating iteration: 6 Done
Allocating iteration: 7 Done
Allocating iteration: 8 Done
[0.077s][info][gc] GC(1) Pause Remark 10M->10M(16M) 0.578ms
Allocating iteration: 9[0.078s][info][gc] GC(1) Pause Cleanup 12M->12M(16M) 0.108ms
 Done
Allocating iteration: 10[0.078s][info][gc] GC(1) Concurrent Cycle 3.002ms
 Done
Allocating iteration: 11[0.081s][info][gc] GC(2) To-space exhausted
[0.081s][info][gc] GC(2) Pause Young (Concurrent Start) (G1 Humongous Allocation) 14M->0M(16M) 2.460ms
[0.081s][info][gc] GC(3) Concurrent Cycle
 Done
[0.083s][info][gc] GC(3) Pause Remark 2M->2M(14M) 0.644ms
[0.084s][info][gc] GC(3) Pause Cleanup 2M->2M(14M) 0.116ms
[0.084s][info][gc] GC(3) Concurrent Cycle 2.742ms
Time taken: 22ms

It has taken about 22ms to complete.

Now lets run this same program with EpsilonGC enabled. Command used and output are

java -verbose:gc -Xmx15M -XX:+UnlockExperimentalVMOptions -XX:+UseEpsilonGC TestEpsilonGC
[0.010s][info][gc] Using Epsilon
[0.010s][warning][gc,init] Consider enabling -XX:+AlwaysPreTouch to avoid memory commit hiccups
[0.049s][info   ][gc     ] Heap: 15360K reserved, 15360K (100.00%) committed, 814K (5.30%) used
Allocating iteration: 0[0.055s][info   ][gc     ] Heap: 15360K reserved, 15360K (100.00%) committed, 1919K (12.50%) used
 Done
Allocating iteration: 1[0.056s][info   ][gc     ] Heap: 15360K reserved, 15360K (100.00%) committed, 2943K (19.16%) used
 Done
Allocating iteration: 2[0.056s][info   ][gc     ] Heap: 15360K reserved, 15360K (100.00%) committed, 3967K (25.83%) used
 Done
Allocating iteration: 3[0.056s][info   ][gc     ] Heap: 15360K reserved, 15360K (100.00%) committed, 4991K (32.50%) used
 Done
Allocating iteration: 4[0.057s][info   ][gc     ] Heap: 15360K reserved, 15360K (100.00%) committed, 6015K (39.16%) used
 Done
Allocating iteration: 5[0.057s][info   ][gc     ] Heap: 15360K reserved, 15360K (100.00%) committed, 7039K (45.83%) used
 Done
Allocating iteration: 6[0.058s][info   ][gc     ] Heap: 15360K reserved, 15360K (100.00%) committed, 8063K (52.50%) used
 Done
Allocating iteration: 7[0.058s][info   ][gc     ] Heap: 15360K reserved, 15360K (100.00%) committed, 9087K (59.16%) used
 Done
Allocating iteration: 8[0.059s][info   ][gc     ] Heap: 15360K reserved, 15360K (100.00%) committed, 10111K (65.83%) used
 Done
Allocating iteration: 9[0.059s][info   ][gc     ] Heap: 15360K reserved, 15360K (100.00%) committed, 11135K (72.50%) used
 Done
Allocating iteration: 10[0.060s][info   ][gc     ] Heap: 15360K reserved, 15360K (100.00%) committed, 12159K (79.16%) used
 Done
Allocating iteration: 11[0.060s][info   ][gc     ] Heap: 15360K reserved, 15360K (100.00%) committed, 13183K (85.83%) used
 Done
Time taken: 13ms
[0.065s][info   ][gc     ] Heap: 15360K reserved, 15360K (100.00%) committed, 13372K (87.06%) used

This has taken just 13ms as against the 22ms taken by the G1 gc configuration. There clearly is a performance advantage in using EpsilonGC. But its use will be limited to very few special cases. 

Sample code used in this post can be downloaded from https://github.com/ashokkumarta/awesomely-java/tree/main/2021/02/Garbage-Collection/EpsilonGC/Measure-of-performance-benefits

 

Testing EpsilonGC

Lets create a small program to test EpsilonGC. 

This program would have to create enough objects to exhaust available heap memory so that the behavior of EpsilonGC can be studied.

Here is a simple program that will help us with this

class TestEpsilonGC {

    static final int ALLOCATION_SIZE = 1024 * 1024; // 1MB
    static final int LOOP_COUNT = 12;  

    public static void main(String[] args) {
        for (int i = 0; i < LOOP_COUNT; i++) {
            System.out.print("Allocating iteration: "+i);
            byte[] array = new byte[ALLOCATION_SIZE];
            System.out.println(" Done");
        }
    }
}

This code creates byte array of 1MB size on each iteration through the loop. 

Now lets try to run this program with default garbage collector and with EpsilonGC enabled, giving it a maximum of 10MB heap space and enabling verbose:gc

Running with default gc configuration.  Here is the command and the output

java -verbose:gc -Xmx10M TestEpsilonGC
[0.032s][info][gc] Using G1
Allocating iteration: 0 Done
Allocating iteration: 1 Done
Allocating iteration: 2[0.114s][info][gc] GC(0) Pause Young (Concurrent Start) (G1 Humongous Allocation) 4M->0M(10M) 3.739ms
[0.114s][info][gc] GC(1) Concurrent Cycle
 Done
Allocating iteration: 3 Done
Allocating iteration: 4 Done
Allocating iteration: 5[0.129s][info][gc] GC(1) Pause Remark 8M->8M(10M) 13.647ms
 Done
Allocating iteration: 6[0.130s][info][gc] GC(1) Pause Cleanup 8M->8M(10M) 0.203ms
[0.138s][info][gc] GC(2) To-space exhausted
[0.138s][info][gc] GC(2) Pause Young (Normal) (G1 Humongous Allocation) 8M->0M(10M) 7.786ms
[0.139s][info][gc] GC(1) Concurrent Cycle 24.785ms
 Done
Allocating iteration: 7 Done
Allocating iteration: 8[0.141s][info][gc] GC(3) Pause Young (Concurrent Start) (G1 Humongous Allocation) 4M->0M(10M) 1.592ms
[0.141s][info][gc] GC(4) Concurrent Cycle
 Done
Allocating iteration: 9 Done
Allocating iteration: 10 Done
Allocating iteration: 11 Done
[0.148s][info][gc] GC(4) Pause Remark 8M->8M(10M) 1.111ms
[0.150s][info][gc] GC(4) Pause Cleanup 8M->8M(10M) 0.145ms
[0.151s][info][gc] GC(4) Concurrent Cycle 9.700ms

As you can see, this has used G1 collector, which is the default garbage collector. You can also see that intermittent GC cycles kicking in to reclaim memory. The program ran to completion successfully indicating that the loop completed 12 iterations allocating 1.2MB of objects, using the space reclaimed by the GC.

Now lets see the same code in action with EpsilonGC configuration. 

java -verbose:gc -Xmx10M -XX:+UnlockExperimentalVMOptions -XX:+UseEpsilonGC TestEpsilonGC
[0.419s][info][gc] Using Epsilon
[0.425s][warning][gc,init] Consider enabling -XX:+AlwaysPreTouch to avoid memory commit hiccups
[0.513s][info   ][gc     ] Heap: 10240K reserved, 10240K (100.00%) committed, 524K (5.12%) used
Allocating iteration: 0[0.581s][info   ][gc     ] Heap: 10240K reserved, 10240K (100.00%) committed, 1935K (18.90%) used
 Done
Allocating iteration: 1[0.582s][info   ][gc     ] Heap: 10240K reserved, 10240K (100.00%) committed, 2959K (28.90%) used
 Done
Allocating iteration: 2[0.583s][info   ][gc     ] Heap: 10240K reserved, 10240K (100.00%) committed, 3983K (38.90%) used
 Done
Allocating iteration: 3[0.583s][info   ][gc     ] Heap: 10240K reserved, 10240K (100.00%) committed, 5007K (48.90%) used
 Done
Allocating iteration: 4[0.584s][info   ][gc     ] Heap: 10240K reserved, 10240K (100.00%) committed, 6031K (58.90%) used
 Done
Allocating iteration: 5[0.585s][info   ][gc     ] Heap: 10240K reserved, 10240K (100.00%) committed, 7055K (68.90%) used
 Done
Allocating iteration: 6[0.586s][info   ][gc     ] Heap: 10240K reserved, 10240K (100.00%) committed, 8079K (78.90%) used
 Done
Allocating iteration: 7[0.587s][info   ][gc     ] Heap: 10240K reserved, 10240K (100.00%) committed, 9103K (88.90%) used
 Done
Allocating iteration: 8[0.588s][info   ][gc     ] Heap: 10240K reserved, 10240K (100.00%) committed, 10127K (98.90%) used
 Done
Allocating iteration: 9Terminating due to java.lang.OutOfMemoryError: Java heap space

This has thrown OutOfMemoryError on the 10th iteration of the loop, indicating that by this time it has used up the heap space and there is not enough space left to continue with the iteration. Instead of GC kicking in, the program has terminated with the OutOfMemoryError.

How performant is EpsilonGC compared to other GC configurations? We will explore that in the next post


Sample code used in this post can be downloaded from https://github.com/ashokkumarta/awesomely-java/tree/main/2021/02/Garbage-Collection/EpsilonGC/Testing-EpsilonGC


Is there a way to disable garbage collection

Not until recently did I find that Java 11 has introduced a no-op garbage collector, which essentially does nothing. Configuring the Java runtime with this garbage collector essentially disables garbage collection.

Also to be noted is the fact that until Java 11, there is no way to disable garbage collection. That makes sense as for someone like me who have been using Java for the last 20 years, since version 1.2, I was never faced with a situation where there was a need to disable GC. Java does not have an option to deallocate memory. If GC is disabled, who will free up the memory that got allocated through new object creations?

So why now was I looking to disable garbage collection now?

Well, we were into micro-services implementation and experimenting with GraalVM and micro-services frameworks.

Our objective is to spin up services as quickly as possible and replace a running instance when any of our monitored parameters starts showing any sign of weakness.

The obvious problem with Java garbage collection showed its head in our deliberations. If Java stops everything when it does garbage collection, why not 

  • Disable the garbage collection
  • Stop the instance when memory usage goes beyond a threshold
  • Spin up a new instance to handle the low

Sounded by a good option to try

EpsilonGC is the no-ops GC introduced with Java 11. This can be enabled by starting the runtime with configuration flags 

-XX:+UseEpsilonGC

and

-XX:+UnlockExperimentalVMOptions 

Turned out that for our case, having proper GC configured on running instance is a better configuration to have, then to kill it and spin up a new instances frequently. But we are keeping the option of using EpsilonGC open to use when we find a right fit use case.  

We did quiet a few experiments with EpsilonGC. More on that hereherehere & here

Complete EpsilonGC specification can be found at JEP-318