Strange thing about ArrayList Performance (Java)

Question

I've had some concerns about java.util.ArrayList#add() method performance (it seems too slow to me), so I've downloaded Java source code and looked at the ArrayList implementation (which seems fine), I've copied clear() and add() methods and created my own ArrayList2:

public class ArrayList2<E> 
{
    private static final int DEFAULT_CAPACITY = 10;

    private static final Object[] EMPTY_ELEMENTDATA = {};
    static int MAX_ARRAY_SIZE = 50000;

    private transient Object[] elementData;

    private int size;

    public ArrayList2(int initialCapacity) {
        super();
        if (initialCapacity < 0)
        throw new IllegalArgumentException("Illegal Capacity: "+
                                           initialCapacity);
        this.elementData = new Object[initialCapacity];
    }

    private static int hugeCapacity(int minCapacity) {
        if (minCapacity < 0)
            throw new OutOfMemoryError();
        return (minCapacity > MAX_ARRAY_SIZE) ?
            Integer.MAX_VALUE :
            MAX_ARRAY_SIZE;
    }    

    public boolean add(E e) {
        ensureCapacityInternal(size + 1);
        elementData[size++] = e;
        return true;
    }

    private void ensureCapacityInternal(int minCapacity) {
        if (elementData == EMPTY_ELEMENTDATA) {
            minCapacity = Math.max(DEFAULT_CAPACITY, minCapacity);
        }

        ensureExplicitCapacity(minCapacity);
    }

    private void ensureExplicitCapacity(int minCapacity) {

        if (minCapacity - elementData.length > 0){
            //System.out.println("WHAT");  //when this line is uncommented performance is improved
            grow(minCapacity);
        }
    }

    private void grow(int minCapacity) {
        int oldCapacity = elementData.length;
        int newCapacity = oldCapacity + (oldCapacity >> 1);
        if (newCapacity - minCapacity < 0)
            newCapacity = minCapacity;
        if (newCapacity - MAX_ARRAY_SIZE > 0)
            newCapacity = hugeCapacity(minCapacity);
        elementData = Arrays.copyOf(elementData, newCapacity);
    }

    public void clear() {

        for (int i = 0; i < size; i++)
            elementData[i] = null;

        size = 0;
    }
}

which of course has the same performance as java.util.ArrayList. Weird thing happens when line 49 is uncommented. It contains this :

System.out.println("What");

after this change, the add method runs 3-4 times faster, which is weird because this line is in a block of code that is never executed and therefore should have no impact on the performance. I've used a simple test to measure the time spent in different methods. This is the output :

**************************************
Filling Array List 2 took : 2107
Emptying Array List 2 took : 149
**************************************
**************************************
Filling Array List 3 took : 565
Emptying Array List 3 took : 182
**************************************

How can this logically irrelevant change improve the performance so significantly? Could someone please explain this? It really doesn't make any sense to me and currently seems to me as a big performance problem in java.util.ArrayList.

Answer 1

As mentionned in comments, that seems to be an innapropriate micro-benchmark.

You see, even though the inner part of the if statement might not be executed in your specific situation, the method itself is invoked frequently. Now, because of the inner call to System.out, the method byte code is longer, so the JIT might be less tempted in optimizing that method ("short" methods quickly gets inlined; the call to System.out might make it less interesting to optimize than some other methods elsewhere).

So if the first solution get optimized earlier, why is it slower in your tests? Because JIT compilation is performed asynchronously, and consume time. So while optimzation is happening, the method become slower, until it is fully optimized. Then it become very fast. Just execute Java with arguments "-XX:-PrintCompilation" to be sure.

But anyway... Use caliper. Really.

Answer 2

Now I'm sure... it's benchmark is bad. Just try to repeat it 10 times. First result:

**************************************
Filling Array List 2 took  : 1754
Emptying Array List 2 took : 191
**************************************
**************************************
Filling Array List 3 took  : 534
Emptying Array List 3 took : 188
**************************************

Last result without zeroing the timers, i.e., showing cumulative time:

**************************************
Filling Array List 2 took  : 18647
Emptying Array List 2 took : 1945
**************************************
**************************************
Filling Array List 3 took  : 17310
Emptying Array List 3 took : 1865
**************************************

Last result with zeroing the timers, i.e., showing the time of the last run:

**************************************
Filling Array List 2 took  : 1733
Emptying Array List 2 took : 179
**************************************
**************************************
Filling Array List 3 took  : 1897
Emptying Array List 3 took : 184
**************************************

You can see that the numbers make no sense, right? Just switch to caliper.