115Young vs. Old Generation GC

Author: Dr. Heinz M. KabutzDate: 2005-10-13Java Version: 1.4Category: Performance

Abstract: A few weeks ago, I tried to demonstrate the effects of old vs. new generation GC. The results surprised me and reemphasized how important GC is to your overall program performance.

Welcome to the 115th edition of The Java(tm) Specialists' Newsletter. I am on the island of Crete again, this time with the whole family. We are enjoying the beauty and hospitality. Swimming was possible almost every day, even though it is already October!

My short trips to France and USA were very enjoyable. In France we did a design workshop followed by some Design Patterns. In the USA, I spoke at the Java In Action conference. Much to my delight, the room was packed to full capacity. Thanks all for attending! And thanks to the organisers for putting on a great conference! This was the very first time I got to go to the USA, and it certainly was quite an experience!

We've travelled enough (for now) and are looking forward to going home to South Africa soon.

javaspecialists.teachable.com: Please visit our new self-study course catalog to see how you can upskill your Java knowledge.

Young vs. Old Generation GC

It is common knowledge that it is more efficient to GC young than old generations. You should therefore avoid middle-aged objects. This is also a reason why object pooling is discouraged. You might end up with more objects in old space, which will slow down your GC. How much it slows down is interesting to watch.

Let's have a look at some simple classes derived from a CreateTest class. ObjectCreationTest1 contains an infinite loop that simply creates objects. A question here: what percentage of CPU time do you estimate is spent collecting garbage? 40%, 50%, 60%, 70%? ObjectCreationTest2 keeps an array of the last million created objects. Does the JVM need more CPU to collect garbage?

public abstract class CreateTest {
  private long count;
  public long getCount() {
    return count;
  }
  protected final void incCount() {
    count++;
  }
  public abstract void run();
}

public class ObjectCreationTest1 extends CreateTest {
  public void run() {
    while (true) {
      new Object();
      incCount();
    }
  }
}

public class ObjectCreationTest2 extends CreateTest {
  public void run() {
    Object[] pool = new Object[1 * 1024 * 1024];
    int count = 0;
    while (true) {
      pool[(count++) % pool.length] = new Object();
      incCount();
    }
  }
}

In order to try this out, I wrote a Launcher class that after 120 seconds kills the JVM using the System.exit() command:

import java.util.*;

public class Launcher {
  public static void main(String[] args) throws Exception {
    String testName = args[0];
    final CreateTest job =
      (CreateTest) Class.forName(testName).newInstance();
    Timer timer = new Timer();
    timer.schedule(new TimerTask() {
      public void run() {
        System.out.println(job.getCount());
        System.exit(0);
      }
    }, 120000);
    job.run();
  }
}

This is how we could run it:

java -Xloggc:nopool.log Launcher ObjectCreationTest1
java -Xloggc:pool.log Launcher ObjectCreationTest2

In my run, ObjectCreationTest1 created 8,762,510,385 objects and ObjectCreationTest2 only managed to create 389,105,915 objects.

A nice free tool that I learned about at Java In Action is JTune by HP which we can use to see what happened in the GC logs. I do not have a direct link to the tool, but you should be able to find one on the Java Performance Tuning.com website.

Using HP JTune, we should see that with ObjectCreationTest1, we get statistics such as:

• Duration of the measurement: 123s
• Total bytes allocated: 66,980 MB
• Number of GC events: 133,961
• Time spent in GC: 11s
• Percentage of time in GC: 9%

It must be said that the 134 thousand GCs all occurred in the young generation. Since the object references were immediately cleared, the objects were never moved into the old generation.

Again using HP JTune, we should see that with ObjectCreationTest2, we get statistics such as:

• Duration of the measurement: 123s
• Total bytes allocated: 2,975 MB
• Number of GC events: 1,455
• Time spent in GC: 96s
• Percentage of time in GC: 78%

Here the created objects live long enough to be pushed into the old generation or the young space could not accommodate new objects. The system only did 1165 young gen collections, and 290 old gen collections.

Object pools tend to let objects survive longer, thereby pushing them into the old generation space. This may be bad for performance due to the additional overhead of old gen GC, as seen here.

During Kirk Pepperdine's talk on performance, the question arose as to what percentage of GC activity was acceptable in a real system. In Kirk's experience, you should aim for 5%, but maximum 10%. The first example effectively does while(true) { new Object(); } but it only spends 9% of its CPU doing garbage collection. We should be careful to not be too generous in allocating CPU cycles to the GC.

Another fun display of GC activity is with Sun's jvmstat visualgc. Great tool that gives insight (using sampling) of what is happening inside running JVMs. Click here to see the graph for ObjectCreationTest1 and here for ObjectCreationTest2.

Sanity Check

Here is another test that sits in the infinite loop and is counting how quickly the looping works, which is basically what would happen when no objects are created. The loop executed 24,362,038,313 times in two minutes.

public class ObjectCreationTest3 extends CreateTest {
  public void run() {
    while (true) {
      incCount();
    }
  }
}

To summarise, creating and destroying objects is quite fast when the objects live in the young space, but rather slow when they live in old space. Even faster is creating no objects (obviously).

Kind regards

Heinz

Comments

We are always happy to receive comments from our readers. Feel free to send me a comment via email or discuss the newsletter in our JavaSpecialists Slack Channel (Get an invite here)

Related Articles

Browse the Newsletter Archive