What can make Java code go faster and slower.

May 06, 2011

Overview

Something is fairly widely known is that the JVM optimises code as it runs. This can result in code running much faster as you execute it many times.

However, something not so well understood is what you do before a section of code can slow it down.

Warming up code

int[] display = {0, 1, 10, 100, 1000, 10000, 20000, 100001};
for (int i = 0; i <= display[display.length - 1]; i++) {
    long start = System.nanoTime();
    doTask();
    long time = System.nanoTime() - start;
    if (Arrays.binarySearch(display, i) >= 0)
        System.out.printf("%,d: Took %,d us to serialize/deserialze " +
                          "GregorianCalendar%n", i, time / 1000);
}

outputs

0: Took 34,751 us to serialize/deserialze GregorianCalendar
1: Took 1,551 us to serialize/deserialze GregorianCalendar
10: Took 1,474 us to serialize/deserialze GregorianCalendar
100: Took 1,010 us to serialize/deserialze GregorianCalendar
1,000: Took 264 us to serialize/deserialze GregorianCalendar
10,000: Took 151 us to serialize/deserialze GregorianCalendar
20,000: Took 95 us to serialize/deserialze GregorianCalendar
100,001: Took 91 us to serialize/deserialze GregorianCalendar

Cooling it down

Even performing a Thread.sleep() can cause the code following it to run slower. Reading from a socket or a file has a similar impact.

// run immediately after the previous section where the code has warmed up.
for (int i : new int[]{0, 1, 2, 5, 10, 20, 50, 100}) {
    int runs = i < 10 ? 1000: 100;
    long total = 0;
    for (int j = 0; j < runs; j++) {
        Thread.sleep(i);
        long start = System.nanoTime();
        doTask();
        long time = System.nanoTime() - start;
        total += time;
    }
    System.out.printf("After sleep %d ms: Took %,d us to serialize/deserialze " +
                      "GregorianCalendar%n", i, total / runs / 1000);
}

outputs

After sleep 0 ms: Took 100 us to serialize/deserialze GregorianCalendar
After sleep 1 ms: Took 164 us to serialize/deserialze GregorianCalendar
After sleep 2 ms: Took 162 us to serialize/deserialze GregorianCalendar
After sleep 5 ms: Took 173 us to serialize/deserialze GregorianCalendar
After sleep 10 ms: Took 187 us to serialize/deserialze GregorianCalendar
After sleep 20 ms: Took 198 us to serialize/deserialze GregorianCalendar
After sleep 50 ms: Took 230 us to serialize/deserialze GregorianCalendar
After sleep 100 ms: Took 231 us to serialize/deserialze GregorianCalendar

While the process is sleeping, the CPU caches get cleared and the operations take longer to execute.

Summary

You cannot just test the performance of a section of code in isolation. You have to see how it impacts your whole system, not just the time the added code takes, but it can make code which follows it slower.

The task

Here is the doTask() method

public static void doTask() {
try {
    GregorianCalendar cal = new GregorianCalendar();
    ByteArrayOutputStream baos = new ByteArrayOutputStream();
    ObjectOutputStream oos = new ObjectOutputStream(baos);
    oos.writeObject(cal);
    oos.close();
    ObjectInputStream ois = new ObjectInputStream(new ByteArrayInputStream(baos.toByteArray()));
    GregorianCalendar cal2 = (GregorianCalendar) ois.readObject();
    ois.close();
    cal2.toString();

} catch (Exception e) {
    throw new AssertionError(e);
}
}

Serialization of the GregorianCalendar was chosen as both as relatively heavy weight but can be used in a short section of code.

Vanilla Java