Understanding Java Garbage Collector

     Java’s garbage collection system reclaims objects automatically occurring transparently, behind the scenes, without any programmer intervention. It works like this: when no references to an object exist, that object is assumed to be no longer needed, and the memory occupied by the object is released. This recycled memory can then be used for a subsequent allocation.

Although it complete transparent to developer, understanding how GC works helps developer to improve efficiency of Java Program. It is also helpful to improve performance of the program.

JDK provides many runtime options to analysis GC and analysis your program behavior. Here is the simple java program to understand GC behavior

  1: public class GCTest {
  2:     public GCTest() {
  3:     }
  4: 
  5:     public static void main(String[] args) {
  6:         int count = 10000;
  7:         long startTime = System.currentTimeMillis();
  8:         System.out.println("Total Count =" + count);
  9:         String str = "Test";
 10:         for (int i = 0; i < count; i++) {
 11:             str += i;
 12:         }
 13:         double timeTaken = (System.currentTimeMillis() - startTime) / 1000.0;
 14:         System.out.println("Time Taken = " + timeTaken);
 15:     }
 16: }

Running this program

java GCTest
Total Count =10000
Time Taken = 2.146

In this program we are creating no of string object, which gets cahce as per immutable String class’s implementation, so it occupies more memory. If you have to improve this program’s performance efficient us of memory is one the option.

Lets use –verbosegc option to analysis GC activates

Program Output

java -verbosegc GCTest
Total Count =10000
[GC 4184K->3577K(5056K), 0.0003704 secs]
[GC 4412K->3653K(5056K), 0.0003089 secs]
.
.
[GC 4867K->4107K(5184K), 0.0003535 secs]
[Full GC 4107K->182K(5184K), 0.0129175 secs]
[GC 1018K->561K(5056K), 0.0005585 secs]
[GC 1321K->713K(5056K), 0.0003766 secs]
.
.
.
[GC 2537K->1927K(5056K), 0.0003615 secs]
Time Taken = 3.816

Here only few  lines of GC trace shown for simplicity. Lets understand GC trace before going forward

Understanding GC Trace :Simple GC and FULL GC:  Simple GC happens/runs on young generation of heap, it is fastest and less accurate GC. Whenever heap memory consumption is above particular limit, Full GC will happen, which run on almost complete heap , it is most accurate and slower.You can figure out from GC trace that GC consume most of time taken by program. One way to improve its performance is to increase heap size. It is all try and error practice.

java –verbosegc –Xms128m –Xmx128m GCTest
Total Count =10000
[GC 4184K->3577K(5056K), 0.0003704 secs]
[GC 4412K->3653K(5056K), 0.0003089 secs]
.
.
[GC 8362K->251K(130112K), 0.0004014 secs]
[GC 8314K->179K(130112K), 0.0003162 secs]
[GC 8266K->325K(130112K), 0.0004649 secs]
[GC 8363K->252K(130112K), 0.0003900 secs]
[GC 8314K->326K(130112K), 0.0006168 secs]
[GC 8411K->253K(130112K), 0.0003575 secs]
[GC 8378K->257K(130112K), 0.0004969 secs]
[GC 8325K->182K(130112K), 0.0003301 secs]
[GC 8273K->333K(130112K), 0.0004755 secs]
[GC 8371K->258K(130112K), 0.0003642 secs]
Time Taken = 2.006

It has been noticed that Full GC didn’t happen this time. Here we have used –Xms128m  and -Xmx128m options with –verbosegc to specify max and min heap size. Please note that total Heap size in this case is (130112K),

Let give couple of trial

java -verbosegc -Xms256m -Xmx256m GCTest
Total Count =10000
[GC 4184K->3577K(5056K), 0.0003704 secs]
[GC 4412K->3653K(5056K), 0.0003089 secs]
.
.
[GC 8362K->251K(130112K), 0.0004014 secs]
[GC 8314K->179K(130112K), 0.0003162 secs]
[GC 8266K->325K(130112K), 0.0004649 secs]
[GC 8363K->252K(130112K), 0.0003900 secs]
[GC 8314K->326K(130112K), 0.0006168 secs]
[GC 8411K->253K(130112K), 0.0003575 secs]
[GC 8378K->257K(130112K), 0.0004969 secs]
[GC 8325K->182K(130112K), 0.0003301 secs]
[GC 8273K->333K(130112K), 0.0004755 secs]
[GC 8371K->258K(130112K), 0.0003642 secs]
Time Taken = 1.951

java -verbosegc -Xms512m -Xmx512m GCTest Total Count =10000
[GC 32410K->274K(520256K), 0.0004366 secs]
[GC 32504K->220K(520256K), 0.0005552 secs]
[GC 32418K->164K(520256K), 0.0003394 secs]
.
.
[GC 32429K->242K(520256K), 0.0003815 secs]
[GC 32458K->313K(520256K), 0.0004461 secs]
[GC 32541K->316K(520256K), 0.0004218 secs]
[GC 32538K->248K(520256K), 0.0004065 secs]
[GC 32450K->249K(520256K), 0.0005034 secs]
[GC 32489K->179K(520256K), 0.0003222 secs]
[GC 32372K->253K(520256K), 0.0003315 secs]
[GC 32451K->255K(520256K), 0.0004410 secs]
[GC 32447K->181K(520256K), 0.0002904 secs]
[GC 32286K->258K(520256K), 0.0003896 secs]
Time Taken = 1.817

java -verbosegc -Xms1024m -Xmx1024m GCTest
Total Count =10000
[GC 64512K->137K(1040512K), 0.0035148 secs]
[GC 64649K->172K(1040512K), 0.0013554 secs]
[GC 64684K->188K(1040512K), 0.0010516 secs]
[GC 64677K->138K(1040512K), 0.0012509 secs]
[GC 64646K->212K(1040512K), 0.0010262 secs]
[GC 64724K->145K(1040512K), 0.0009083 secs]
[GC 64657K->190K(1040512K), 0.0009568 secs]
[GC 64634K->195K(1040512K), 0.0011240 secs]
[GC 64707K->154K(1040512K), 0.0008971 secs]
[GC 64666K->206K(1040512K), 0.0009871 secs]
[GC 64695K->211K(1040512K), 0.0009223 secs]
[GC 64714K->216K(1040512K), 0.0011811 secs]
[GC 64699K->277K(1040512K), 0.0011328 secs]
[GC 64789K->224K(1040512K), 0.0009822 secs]
[GC 64700K->167K(1040512K), 0.0012527 secs]
[GC 64679K->233K(1040512K), 0.0011840 secs]
[GC 64730K->237K(1040512K), 0.0010068 secs]
[GC 64688K->307K(1040512K), 0.0003946 secs]
[GC 64782K->175K(1040512K), 0.0002720 secs]
[GC 64687K->248K(1040512K), 0.0003041 secs]
[GC 64703K->179K(1040512K), 0.0005346 secs]
[GC 64659K->329K(1040512K), 0.0007257 secs]
[GC 64693K->258K(1040512K), 0.0003457 secs]
Time Taken = 1.873

It has been noticed that further increase in heap size is no more beneficial, so 512 MB is optimal memory size for our program.