Visualising Garbage Collection in the JVM

Recently, I have been working with a number of customers on JVM tuning exercises.  It seems that there is not widespread knowledge amongst developers and administrators about how garbage collection works, and how the JVM uses memory.  So, I decided to write a very basic introduction and an example that will let you see it happening in real time!  This post does not try to cover everything about garbage collection or JVM tuning – that is a huge area, and there are some great resources on the web already, only a Google away.

This post is about the HotSpot JVM – that’s the ‘normal’ JVM from Oracle (previously Sun).  It is the one you would most likely use on Windows.  If you are using a Linux variant that errs on the side of free software (like Ubuntu), you might have an open source JVM.  Or if your JVM came with another product, like WebLogic, you may even have the JRockit JVM from Oracle (formerly BEA).  And then there are other JVMs from IBM, Apple and others.  Most of these other JVMs work in a similar way to HotSpot, with the notable exception of JRockit, which handles memory differently, and does not have a separate Permanent Generation (see below) for example.

First, let’s take a look at the way the JVM uses memory.  There are two main areas of memory in the JVM – the ‘Heap’ and the ‘Permanent Generation.’  In the diagram below, the permanent generation is shown in green.  The remainder (to the left) is the heap.

The Permanent Generation

The permanent generation is used only by the JVM itself, to keep data that it requires.  You cannot place any data in the permanent generation.  One of the things the JVM uses this space for is keeping metadata about the objects you create.  So every time you create an object, the JVM will store some information in the permanent generation.  So the more objects you create, the more room you need in the permanent generation.

The size of the permanent generation is controlled by two JVM parameters. -XX:PermSize sets the minimum, or initial, size of the permanent generation, and -XX:MaxPermSize sets the maximum size.  When running large Java applications, we often set these two to the same value, so that the permanent generation will be created at its maximum size initially.  This can improve performance because resizing the permanent generation is an expensive (time consuming) operation.  If you set these two parameters to the same size, you can avoid a lot of extra work in the JVM to figure out if it needs to resize, and actually performing resizes of, the permanent generation.

The Heap

The heap is the main area of memory.  This is where all of your objects will be stored.  The heap is further divided into the ‘Old Generation’ and the ‘New Generation.’  The new generation in turn is divided into ‘Eden’ and two ‘Survivor’ spaces.

This size of the heap is also controlled by JVM paramaters.  You can see on the diagram above the heap size is -Xms at minimum and -Xmx at maximum.  Additional parameters control the sizes of the various parts of the heap.  We will see one of those later on, the others are beyond the scope of this post.

When you create an object, e.g. when you say byte[] data = new byte[1024], that object is created in the area called Eden.  New objects are created in Eden.  In addition to the data for the byte array, there will also be a reference (pointer) for ‘data.’

The following explanation has been simplified for the purposes of this post.  When you want to create a new object, and there is not enough room left in eden, the JVM will perform ‘garbage collection.’  This means that it will look for any objects in memory that are no longer needed and get rid of them.

Garbage collection is great!  If you have ever programmed in a language like C or Objective-C, you will know that managing memory yourself is somewhat tedious and error prone.  Having the JVM automatically find unused objects and get rid of them for you makes writing code much simpler and saves a lot of time debugging.  If you have never used a language that does not have garbage collection – you might want to go write a C program – it will certainly help you to appreciate what you are getting from your language for free!

There are in fact a number of different algorithms that the JVM may use to do garbage collection.  You can control which algorithms are used by changing the JVM paramaters.

Let’s take a look at an example.  Suppose we do the following:

String a = "hello";
String b = "apple";
String c = "banana";
String d = "apricot";
String e = "pear";
//
// do some other things
//
a = null;
b = null;
c = null;
e = null;

This will cause five objects to be created, or ‘allocated,’ in eden, as shown by the five yellow boxes in the diagram below.  After we have done ‘some other things,’ we free a, b, c and e – by setting the references to null.  Assuming there are no other references to these objects, they will now be unused.  They are shown in red in the second diagram.  We are still using String d, it is shown in green.

If we try to allocate another object, the JVM will find that eden is full, and that it needs to perform garbage collection.  The most simple garbage collection algorithm is called ‘Copy Collection.’  It works as shown in the diagram above.  In the first phase (‘Mark’) it will mark (illustrated by red colour) the unused objects.  In the second phase (‘Copy’) it will copy the objects we still need (i.e. d) into a ‘survivor’ space – the little box on the right.  There are two survivor spaces and they are smaller than eden in size.  Now that all the objects we want to keep are safe in the survivor space, it can simply delete everything in eden, and it is done.

This kind of garbage collection creates something known as a ‘stop the world’ pause.  While the garbage collection is running, all other threads in the JVM are paused.  This is necessary so that no thread tries to change memory after we have copied it, which would cause us to lose the change.  This is not a big problem in a small application, but if we have a large application, say with a 8GB heap for example, then it could actually take a significant amount of time to run this algorithm – seconds or even minutes.  Having your application stop for a few minutes every now and then is not suitable for many applications.  That is why other garbage collection algorithms exist and are often used.  Copy Collection works well when there is a relatively large amount of garbage and a small amount of used objects.

In this post, we will just discuss two of the commonly used algorithms.  For those who are interested, there is plenty of information available online and several good books if you want to know more!

The second garbage collection algorithm we will look at is called ‘Mark-Sweep-Compact Collection.’  This algorithm uses three phases.  In the first phase (‘Mark’), it marks the unused objects, shown below in red.  In the second phase (‘Sweep’), it deletes those objects from memory.  Notice the empty slots in the diagram below.  Then in the final phase (‘Compact’), it moves objects to ‘fill up the gaps,’ thus leaving the largest amount of contiguous memory available in case a large object is created.

So far this is all theoretical – let’s take a look at how this actually works with a real application.  Fortunately, the JDK includes a nice visual tool for watching the behaviour of the JVM in ‘real time.’  This tool is called jvisualvm.  You should find it right there in bin directory of your JDK installation.  We will use that a little later, but first, let’s create an application to test.

I used Maven to create the application and manage the builds and dependencies and so on.  You don’t need to use Maven to follow this example.  You can go ahead and type in the commands to compile and run the application if you prefer.

I created a new project using the Maven archetype generate goal:

mvn archetype:generate
  -DarchetypeGroupId=org.apache.maven.archetypes
  -DgroupId=com.redstack
  -DartifactId=memoryTool

I took type 98 – for a simple JAR – and the defaults for everything else.  Next, I changed into my memoryTool directory and edited my pom.xml as shown below.  I just added the part shown in red.  That will allow me to run my application directly from Maven, passing in some memory configuration and garbage collection logging parameters.

<project xmlns="http://maven.apache.org/POM/4.0.0" 
  xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
  xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
  <modelVersion>4.0.0</modelVersion>
  <groupId>com.redstack</groupId>
  <artifactId>memoryTool</artifactId>
  <version>1.0-SNAPSHOT</version>
  <packaging>jar</packaging>
  <name>memoryTool</name>
  <url>http://maven.apache.org</url>
  <properties>
    <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
  </properties>
  <build>
    <plugins>
      <plugin>
        <artifactId>maven-compiler-plugin</artifactId>
        <version>2.0.2</version>
        <configuration>
          <source>1.6</source>
          <target>1.6</target>
        </configuration>
      </plugin>
      <plugin>
        <groupId>org.codehaus.mojo</groupId>
        <artifactId>exec-maven-plugin</artifactId>
        <configuration>
          <executable>java</executable>
          <arguments>
            <argument>-Xms512m</argument>
            <argument>-Xmx512m</argument>
            <argument>-XX:NewRatio=3</argument>
            <argument>-XX:+PrintGCTimeStamps</argument>
            <argument>-XX:+PrintGCDetails</argument>
            <argument>-Xloggc:gc.log</argument>
            <argument>-classpath</argument>
            <classpath/>
            <argument>com.redstack.App</argument>
          </arguments>
        </configuration>
      </plugin>
    </plugins>
  </build>
  <dependencies>
    <dependency>
      <groupId>junit</groupId>
      <artifactId>junit</artifactId>
      <version>3.8.1</version>
      <scope>test</scope>
    </dependency>
  </dependencies>
</project>

If you prefer not to use Maven, you can start the application using the following command:

java -Xms512m -Xmx512m -XX:NewRatio=3 
  -XX:+PrintGCTimeStamps -XX:+PrintGCDetails
  -Xloggc:gc.log -classpath <whatever>
  com.redstack.App

The switches are telling the JVM the following:

• -Xms sets the initial/minimum heap size to 512 MB
• -Xmx sets the maximum heap size to 512 MB
• -XX:NewRatio sets the size of the old generation to three times the size of the new generation
• -XX:+PrintGCTimeStamps, -XX:+PrintGCDetails and -Xloggc:gc.log cause the JVM to print out additional information about garbage collection into a file call gc.log
• -classpath tells the JVM where to look for your program
• com.redstack.App is the name of the main class to execute

I have chosen these options so that you can see pretty clearly what is going on and you wont need to spend all day creating objects to make something happen!

Here is the code in that main class.  This is a simple program that will allow us to create objects and throw them away easily, so we can understand how much memory we are using, and watch what the JVM does with it.

package com.redstack;

import java.io.*;
import java.util.*;

public class App {

  private static List objects = new ArrayList();
  private static boolean cont = true;
  private static String input;
  private static BufferedReader in = new BufferedReader(new InputStreamReader(System.in));

  public static void main(String[] args) throws Exception {
    System.out.println("Welcome to Memory Tool!");

    while (cont) {
      System.out.println(
        "\n\nI have " + objects.size() + " objects in use, about " +
        (objects.size() * 10) + " MB." +
        "\nWhat would you like me to do?\n" +
        "1. Create some objects\n" +
        "2. Remove some objects\n" +
        "0. Quit");
      input = in.readLine();
      if ((input != null) && (input.length() >= 1)) {
        if (input.startsWith("0")) cont = false;
        if (input.startsWith("1")) createObjects();
        if (input.startsWith("2")) removeObjects();
      }
    }

    System.out.println("Bye!");
  }

  private static void createObjects() {
    System.out.println("Creating objects...");
    for (int i = 0; i < 2; i++) {
       objects.add(new byte[10*1024*1024]);
     }
   }

   private static void removeObjects() {
     System.out.println("Removing objects...");
     int start = objects.size() - 1;
     int end = start - 2;
     for (int i = start; ((i >= 0) && (i > end)); i--) {
      objects.remove(i);
    }
  }
}

If you are using Maven, you can build, package and execute this code using the following command:

mvn package exec:exec

Once you have this compiled and ready to go, start it up, and fire up jvisualvm as well.  You might like to arrange your screen so you can see both, as shown in the image below.  If you have never used JVisualVM before, you will need to install the VisualGC plugin.  Select Plugins from the Tools menu.  Open the Available Plugins tab.  Place a tick next to the entry for Visual GC.  Then click on the Install button.  You may need to restart it.

Back in the main panel, you should see a lit of JVM processes.  Double click on the one running your application, com.redstack.App in this example, and then open the Visual GC tab.  You should see something like what is shown below.

Notice that you can visually see the permanent generation, the old generation and eden and the two survivor spaces (S0 and S1).  The coloured bars indicate memory in use.  On the right hand side, you can also see a historical view that shows you when the JVM spent time performing garbage collections, and the amount of memory used in each space over time.

In your application window, start creating some objects (by selecting option 1).  Watch what happens in Visual GC.  Notice how the new objects always get created in eden.  Now throw away some objects (option 2).  You will probably not see anything happen in Visual GC.  That is because the JVM will not clean up that space until a garbage collection is performed.

To make it do a garbage collection, create some more objects until eden is full.  Notice what happens when you do this.  If there is a lot of garbage in eden, you should see the objects in eden move to a survivor space.  However, if eden had little garbage, you will see the objects in eden move to the old generation.  This happens when the objects you need to keep are bigger than the survivor space.

Notice as well that the permanent generation grows slowly as you create new objects.

Try almost filling eden, don’t fill it completely, then throw away almost all of your objects – just keep 20MB.  This will mean that eden is mostly full of garbage.  Then create some more objects.  This time you should see the objects in eden move into the survivor space.

Now, let’s see what happens when we run out of memory.  Keep creating objects until you have around 460MB.  Notice that both eden and the old generation are nearly full.  Create a few more objects.  When there is no more space left, your application will crash and you will get an OutOfMemoryException.  You might have got those before and wondered what causes them – especially if you have a lot more physical memory on your machine, you may have wondered how you could possibly be ‘out of memory’ – now you know!  If you happen to fill up your permanent generation (which will be pretty difficult to do in this example) you would get a different exception telling you PermGen was full.

Finally, another way to look at this data is in that garbage collection log we asked for.  Here are the first few lines from one run on my machine:

13.373: [GC 13.373: [ParNew: 96871K->11646K(118016K), 0.1215535 secs] 96871K->73088K(511232K), 0.1216535 secs] [Times
: user=0.11 sys=0.07, real=0.12 secs]
16.267: [GC 16.267: [ParNew: 111290K->11461K(118016K), 0.1581621 secs] 172732K->166597K(511232K), 0.1582428 secs] [Ti
mes: user=0.16 sys=0.08, real=0.16 secs]
19.177: [GC 19.177: [ParNew: 107162K->10546K(118016K), 0.1494799 secs] 262297K->257845K(511232K), 0.1495659 secs] [Ti
mes: user=0.15 sys=0.07, real=0.15 secs]
19.331: [GC [1 CMS-initial-mark: 247299K(393216K)] 268085K(511232K), 0.0007000 secs] [Times: user=0.00 sys=0.00, real
=0.00 secs]
19.332: [CMS-concurrent-mark-start]
19.355: [CMS-concurrent-mark: 0.023/0.023 secs] [Times: user=0.01 sys=0.01, real=0.02 secs]
19.355: [CMS-concurrent-preclean-start]
19.356: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
19.356: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 24.417: [CMS-concurrent-abortable-preclean: 0.050/5.061 secs] [Times: user=0.10 sys=
0.01, real=5.06 secs]
24.417: [GC[YG occupancy: 23579 K (118016 K)]24.417: [Rescan (parallel) , 0.0015049 secs]24.419: [weak refs processin
g, 0.0000064 secs] [1 CMS-remark: 247299K(393216K)] 270878K(511232K), 0.0016149 secs] [Times: user=0.00 sys=0.00, rea
l=0.00 secs]
24.419: [CMS-concurrent-sweep-start]
24.420: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
24.420: [CMS-concurrent-reset-start]
24.422: [CMS-concurrent-reset: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
24.711: [GC [1 CMS-initial-mark: 247298K(393216K)] 291358K(511232K), 0.0017944 secs] [Times: user=0.00 sys=0.00, real
=0.01 secs]
24.713: [CMS-concurrent-mark-start]
24.755: [CMS-concurrent-mark: 0.040/0.043 secs] [Times: user=0.08 sys=0.00, real=0.04 secs]
24.755: [CMS-concurrent-preclean-start]
24.756: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
24.756: [CMS-concurrent-abortable-preclean-start]
25.882: [GC 25.882: [ParNew: 105499K->10319K(118016K), 0.1209086 secs] 352798K->329314K(511232K), 0.1209842 secs] [Ti
mes: user=0.12 sys=0.06, real=0.12 secs]
26.711: [CMS-concurrent-abortable-preclean: 0.018/1.955 secs] [Times: user=0.22 sys=0.06, real=1.95 secs]
26.711: [GC[YG occupancy: 72983 K (118016 K)]26.711: [Rescan (parallel) , 0.0008802 secs]26.712: [weak refs processin
g, 0.0000046 secs] [1 CMS-remark: 318994K(393216K)] 391978K(511232K), 0.0009480 secs] [Times: user=0.00 sys=0.00, rea
l=0.01 secs]

You can see from this log what was happening in the JVM.  Notice it shows that the Concurrent Mark Sweep Compact Collection algorithm (it calls it CMS) was being used.  You can see when the different phases ran.  Also, near the bottom notice it is showing us the ‘YG’ (young generation) occupancy.

You can leave those same three settings on in production environments to produce this log.  There are even some tools available that will read these logs and show you what was happening visually.

Well, that was a short, and by no means exhaustive, introduction to some of the basic theory and practice of JVM garbage collection.  Hopefully the example application helped you to clearly visualise what happens inside the JVM as your applications run.

Thanks to Rupesh Ramachandran who taught me many of the things I know about JVM tuning and garbage collection.