same code, same input, sometimes running fast, sometimes slow, why?

Question

I wrote some java classes, to evaluate/demo different Sorting algorithms. However I got confused when I run my demo class. Hope you guys can give me an explanation. (this question is NOT a homework.)

First I would list some codes related to this question.

AbstractDemo

public abstract class AbstractDemo {
    protected final int BIG_ARRAY_SIZE = 20000;
    protected final int SMALL_ARRAY_SIZE = 14;
    protected Stopwatch stopwatch = new Stopwatch();

    public final void doDemo() {
        prepareDemo();
        specificDemo();
    }

    protected abstract void prepareDemo();

    protected abstract void specificDemo();

    protected final void printInfo(final String text) {
        System.out.println(text);
    }
}

SortingDemo

public class SortingDemo extends AbstractDemo {
    private static final String FMT = "%-10s| %-21s| %7s ms.";
    private static final String SPL = AlgUtil.lineSeparator('-', 45);
    private static final String SPLT = AlgUtil.lineSeparator('=', 45);

    private int[] data;

    private final List<Sorting> demoList = new LinkedList<Sorting>();

    @Override
    protected void specificDemo() {
        int[] testData;
        //*** this comment is interesting!!! for (int x = 1; x < 6; x++) {  

            printInfo(String.format("Sorting %7s elements", data.length));
            printInfo(SPLT);
            for (final Sorting sort : demoList) {

                // here I made a copy of the original Array, avoid to sort an already sorted array.
                testData = new int[data.length];
                System.arraycopy(data, 0, testData, 0, data.length);
                stopwatch.start();
                // sort
                sort.sort(testData);
                stopwatch.stop();
                printInfo(String.format(FMT, sort.getBigO(), sort.getClass().getSimpleName(), stopwatch.read()));
                printInfo(SPL);
                testData = null;
                stopwatch.reset();
            }
        //}
    }

    @Override
    protected void prepareDemo() {
        data = AlgUtil.getRandomIntArray(BIG_ARRAY_SIZE, BIG_ARRAY_SIZE * 5, false);
        demoList.add(new InsertionSort());
        demoList.add(new SelectionSort());
        demoList.add(new BubbleSort());
        demoList.add(new MergeSort());  //here is interesting too
        demoList.add(new OptimizedMergeSort());

    }

    public static void main(final String[] args) {
        final AbstractDemo sortingDemo = new SortingDemo();
        sortingDemo.doDemo();
    }
}

Stopwatch

public class Stopwatch {
    private boolean running;
    private long startTime;
    private long elapsedMillisec;

    public void start() {
        if (!running) {
            this.startTime = System.currentTimeMillis();
            running = true;
        } else {
            throw new IllegalStateException("the stopwatch is already running");
        }
    }

    public void stop() {
        if (running) {
            elapsedMillisec = System.currentTimeMillis() - startTime;
            running = false;
        } else {
            throw new IllegalStateException("the stopwatch is not running");
        }
    }

    public void reset() {
        elapsedMillisec = 0;

    }

    public long read() {
        if (running) {
            elapsedMillisec = System.currentTimeMillis() - startTime;
        }
        return this.elapsedMillisec;
    }

}

method to generate the random array

public static int[] getRandomIntArray(final int len, final int max, boolean allowNegative) {
        final int[] intArray = new int[len];
        final Random rand = new Random();
        rand.setSeed(20100102);

        if (!allowNegative) {
            if (max <= 0) {
                throw new IllegalArgumentException("max must be possitive if allowNegative false");
            }
            for (int i = 0; i < intArray.length; i++) {
                intArray[i] = rand.nextInt(max);
            }
        } else {
            int n;
            int i = 0;
            while (i < len) {
                n = rand.nextInt();
                if (n < max) {
                    intArray[i] = n;
                    i++;
                }
            }
        }

        return intArray;
    }

you can see, I generate an int array, with 20000 elements. And since I have a fixed seed in the getRandomIntArray method, I have always the same array every time I call it. The class SortingDemo has main method, if I run this class, I got output:

Sorting   20000 elements
=============================================
O(n^2)    | InsertionSort        |     101 ms.
---------------------------------------------
O(n^2)    | SelectionSort        |     667 ms.
---------------------------------------------
O(n^2)    | BubbleSort           |    1320 ms.
---------------------------------------------
O(nlog(n))| MergeSort            |      39 ms.
---------------------------------------------
O(?)      | OptimizedMergeSort   |      11 ms.
---------------------------------------------

looks ok. Now comes something that made me confused. If I change the demoList.add() sequence in SortingDemo, say:

demoList.add(new InsertionSort());
    demoList.add(new SelectionSort());
    demoList.add(new BubbleSort());
    // OptimizedMergeSort before Mergesort
    demoList.add(new OptimizedMergeSort()); 
    demoList.add(new MergeSort());

I got:

Sorting   20000 elements
=============================================
O(n^2)    | InsertionSort        |     103 ms.
---------------------------------------------
O(n^2)    | SelectionSort        |     676 ms.
---------------------------------------------
O(n^2)    | BubbleSort           |    1313 ms.
---------------------------------------------
O(?)      | OptimizedMergeSort   |      41 ms.
---------------------------------------------
O(nlog(n))| MergeSort            |      14 ms.
---------------------------------------------

why the output is different from the first run? OptimizedMergeSort took longer than normal MergeSort...

And if I uncomment the for (int x=1; x<6; x++) line in SortingDemo, (run the test with same Array 5 times) I got:

Sorting   20000 elements
=============================================
O(n^2)    | InsertionSort        |     101 ms.
---------------------------------------------
O(n^2)    | SelectionSort        |     668 ms.
---------------------------------------------
O(n^2)    | BubbleSort           |    1311 ms.
---------------------------------------------
O(?)      | OptimizedMergeSort   |      37 ms.
---------------------------------------------
O(nlog(n))| MergeSort            |      10 ms.
---------------------------------------------

Sorting   20000 elements
=============================================
O(n^2)    | InsertionSort        |      94 ms.
---------------------------------------------
O(n^2)    | SelectionSort        |     665 ms.
---------------------------------------------
O(n^2)    | BubbleSort           |    1308 ms.
---------------------------------------------
O(?)      | OptimizedMergeSort   |       5 ms.
---------------------------------------------
O(nlog(n))| MergeSort            |       7 ms.
---------------------------------------------

Sorting   20000 elements
=============================================
O(n^2)    | InsertionSort        |     116 ms.
---------------------------------------------
O(n^2)    | SelectionSort        |     318 ms.
---------------------------------------------
O(n^2)    | BubbleSort           |     969 ms.
---------------------------------------------
O(?)      | OptimizedMergeSort   |       5 ms.
---------------------------------------------
O(nlog(n))| MergeSort            |      10 ms.
---------------------------------------------

Sorting   20000 elements
=============================================
O(n^2)    | InsertionSort        |     116 ms.
---------------------------------------------
O(n^2)    | SelectionSort        |     319 ms.
---------------------------------------------
O(n^2)    | BubbleSort           |     964 ms.
---------------------------------------------
O(?)      | OptimizedMergeSort   |       5 ms.
---------------------------------------------
O(nlog(n))| MergeSort            |       5 ms.
---------------------------------------------

Sorting   20000 elements
=============================================
O(n^2)    | InsertionSort        |     116 ms.
---------------------------------------------
O(n^2)    | SelectionSort        |     320 ms.
---------------------------------------------
O(n^2)    | BubbleSort           |     963 ms.
---------------------------------------------
O(?)      | OptimizedMergeSort   |       4 ms.
---------------------------------------------
O(nlog(n))| MergeSort            |       6 ms.
---------------------------------------------

For other sortings, the result looks reasonable. but for mergeSort, why the 1st time run took much longer time than later? 37ms:4ms for OptimizedMergeSort.

I think even if the implementation of Optimized/MergeSort was wrong, the output should keep the same, why sometime same method call takes longer time, sometime shorter time?

As info, all those *Sort class extends a super abstract class Sorting. it has an abstract method void sort(int[] data)

MergeSort has mergeSorting method and merge() method. OptimizedMergeSort extends MergeSort, and override mergeSorting() method, (since when array size<=7, it is gonna do insertionSort) and reuse the merge() method from MergeSort class.

Thanks for reading through this long text and codes. I appreciate if you guys can give me some explanations.

All tests were done in Eclipse under linux.

Answer 1

Micro-benchmarking Java code is notoriously tricky.

It's very likely that the Just-in-Time compiler kicks in at some point to compile your Java bytecode into native machine code. Every compilation takes time, but the resulting code is likely to run faster.

There are other pitfalls, but I think the above is the most likely in your case.

The following SO answer is a very good read: https://stackoverflow.com/a/513259/367273

Answer 2

Basically, there are two possible reasons, both related to the environment rather than your program: something else took up lots of space, or something else took up lots of CPU time.

In the first case, you have some other program consuming physical memory, causing your program to page and/or garbage-collect more often.

In the second, some other program (if you're running a Mac, I'd bet Time Machine) intermittently runs consuming the CPU.

In any case, the way you can find out is to start using the tools that come with Java. jconsole and the VirtualVM are good possibilities.

In general, when you have a performance issue, there are three key steps to take: measure, measure, and MEASURE.

Update

I agree that JIT could make a difference, but the impression I get is that these are separate runs; you're invoking a new JVM each time. That minimizes the effect of JIT.

Answer 3

To reduce the effect of JIT, you can discard initial few runs for each test. Also for more accurate results average over 100 or 1000 runs.

You can also do System.gc() and Thread.yeild() before starting measurements. If you are going to test only few iterations prefer system.nanoTime() and don't use system.currentTimeMillis (its not accurate enough).