The Java Specialists' Newsletter
Issue 1152005-10-13 Category: Performance Java version: Sun JDK 1.4, 1.5

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! One of my dreams is to run Java courses here, far away from the distractions of the office. Just imagine: Java exercises combined with snorkeling and swimming in the sea. We are planning some amazing specials for our subscribers so that you can also experience this wonderful island.

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.

Would you like to really understand Java concurrency? Join us for an in-depth study of how threading works in Java. During the course, you will learn how to write correct and fast multi-threaded Java code. Please click here if you would like to learn more.

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:

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:

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

P.S. A picture of my kids enjoying the beach near to where we want to run the Java courses on the island of Crete. Watch this space!

Performance Articles Related Java Course Discuss at The Java Specialist Club