Performance explanation: code runs faster with unused variable

Question

I was doing some performance testing earlier and can't explain the results I obtain.

When running the test below, if I uncomment private final List<String> list = new ArrayList<String>(); the performance improves significantly. On my machine, the test runs in 70-90 ms when that field is present vs. 650 ms when it is commented out.

I have also noticed that if I change the print statement to System.out.println((end - start) / 1000000);, the test without the variable runs in 450-500 ms instead of 650 ms. It has no effect when the variable is present.

My questions:

1. Can anyone explain the factor of almost 10 with or without the variable, considering that I don't even use that variable?
2. How can that print statement change the performance (especially since it comes after the performance measurement window)?

ps: when run sequentially, the 3 scenarios (with variable, without variable, with different print statement) all take around 260ms.

public class SOTest {

    private static final int ITERATIONS = 10000000;
    private static final int THREADS = 4;

    private volatile long id = 0L;
    //private final List<String> list = new ArrayList<String>();

    public static void main(String[] args) throws Exception {
        ExecutorService executor = Executors.newFixedThreadPool(THREADS);
        final List<SOTest> objects = new ArrayList<SOTest>();
        for (int i = 0; i < THREADS; i++) {
            objects.add(new SOTest());
        }

        //warm up
        for (SOTest t : objects) {
            getRunnable(t).run();
        }

        long start = System.nanoTime();

        for (SOTest t : objects) {
            executor.submit(getRunnable(t));
        }
        executor.shutdown();
        executor.awaitTermination(10, TimeUnit.SECONDS);

        long end = System.nanoTime();
        System.out.println(objects.get(0).id + " " + (end - start) / 1000000);
    }

    public static Runnable getRunnable(final SOTest object) {
        Runnable r = new Runnable() {
            @Override
            public void run() {
                for (int i = 0; i < ITERATIONS; i++) {
                    object.id++;
                }
            }
        };
        return r;
    }
}

EDIT

See below the results of 10 runs with the 3 scenarios:

• without the variable, using the short print statement
• without the variable, using the long print statement (prints one of the objects)
• sequential run (1 thread)
• with the variable

1   657 473 261 74
2   641 501 261 78
3   651 465 259 86
4   585 462 259 78
5   639 506 259 68
6   659 477 258 72
7   653 479 259 82
8   645 486 259 72
9   650 457 259 78
10  639 487 272 79

Answer 1

Clear (false) sharing

due to the layout in the memory the objects share cache lines... It has been explained a lot of times (even on this site): here is a good source for further read. The issue is applicable to C# just as much (or C/C++)

When you pad the object by adding the commented out line, the sharing is less and you see boost in the performance.

Edit: I missed the 2nd question:

---

How can that print statement change the performance (especially since it comes after the performance measurement window)?

I guess not enough warming, print both the GC and compilation logs so you can be sure there is no interference and the code is actually compiled. java -server needs 10k iterations preferably not all in main loop to generate good code.

Answer 2

You are hitting a subtle effect of the executing hardware. You SOTest objects are very small in memory, so all 4 instances may fit into the same cache line in memory. Since you are using a volatile this will cause cache trashing between different cores (only one core may have the cache line dirty).

When you comment in the ArrayList, the memory layout changes (the ArrayList is created in between to SOTest instances) and the volatile fields now go into different cache lines. Problem for the CPU disappears, thus performance skyrockets.

Proof: Comment out ArrayList and put instead in:

long waste1, waste2, waste3, waste4, waste5, waste6, waste7, waste8;

This enlarges your SOTest objects by 64 bytes (the size of one cache line on pentium processors). Performance is now the same as with ArrayList in.