Measuring code execution time – The wrong way

  • Post author:
  • Post category:jmh
  • Post comments:0 Comments

Introduction

We have all wanted to know how fast a piece of code or algorithm runs. We want to calculate the running time of a code either to know its efficiency or to compare two or more algorithms to choose the best one. This post is part of a series of posts that explains the pitfalls of the usual ways in measuring running time of a piece of code in Java, why it is a wrong way to measure execution/running time and the correct way to measure the execution time of a code in Java.

Measuring execution time

You have written a code that does something and want to measure the execution time of that code to find its efficiency. You might have two or more different code that does the same job. So, you measure the running time of each code to decide which one is the best. This process of finding the execution time is called benchmarking.
We have the code for insertion sort and we would like to measure its execution time. Insertion sort is one of the sorting algorithms with an average and worst case runtime of O(n^2). Its best case is O(n) and that happens when the input is already sorted. The worst case, O(n^2), is when the input is reverse sorted.
We also have code for quick sort. Its running time is O(n log n) (best, worst and average).

For the rest of the discussion, we would sort the array in ascending order and reverse order means descending order.

The sorting algorithms

The code for the insertion and quick sort are placed in a class as static methods.

public class Sorts {
    public static void insertionSort(int[] arr) {
        int n = arr.length;
        for (int i = 1; i < n; i++) {
            int key = arr[i];
            int j = i - 1;

            while (j >= 0 && arr[j] > key) {
                arr[j + 1] = arr[j];
                j = j - 1;
            }
            arr[j + 1] = key;
        }
    }

    private static int partition(int[] arr, int low, int high) {
        int pivot = arr[high];
        int i = (low - 1);
        for (int j = low; j < high; j++) {
            if (arr[j] <= pivot) {
                i++;
                int temp = arr[i];
                arr[i] = arr[j];
                arr[j] = temp;
            }
        }
        int temp = arr[i + 1];
        arr[i + 1] = arr[high];
        arr[high] = temp;

        return i + 1;
    }


    private static void quickSort(int[] arr, int low, int high) {
        if (low < high) {
            int p = partition(arr, low, high);

            quickSort(arr, low, p - 1);
            quickSort(arr, p + 1, high);
        }
    }
    public static void quickSort(int[] arr) {
        quickSort(arr, 0, arr.length - 1);
    }
}

Very naive way to benchmark code

The normal way, which I call the very naive way, is to measure the running time is to use a clock based approach. We would measure the (clock) time at the start and the time when the method/code run has completed and subtract the end time from the start. Typically, we use System.currentTimeMillis for this. But using System.nanoTime is more accurate than currentTimeMillis. 

A typical benchmark code looks like

long start = System.nanoTime();
Sorts.insertionSort(input);
long end = System.nanoTime();
System.out.println("Took (in ns)" + (end - start));

This gives the time it took in nano seconds. To get the time in milliseconds, we have to divide the result of the difference by 100_000 (106).

The rest of the post talks about the problems in the approach and why it must not be done to get accurate results. 

We start off by constructing a list of random numbers. Next, we run our (very) naive benchmark logic in a loop. Next, we extend it to compare the average case and the worst case of Insertion sort. Finally, we compare insertion sort with merge sort.

 

Building our data set

Let us construct a list of 10,000 numbers as our data set. I have made the upper bound (max number) of the number as 1,000,000 (1 million).

private static int[] buildArray(int size) {
Random random = new Random();
return IntStream.range(0, size)
        .map(i -> random.nextInt(1000000))
        .toArray();
}

Measuring performance in a loop

Let us run the benchmarking code of measuring the execution time in a loop.

private static void measurePerformance(int[] input) {
    for (int i = 0; i < 100; i++) {
        int[] newArray = Arrays.copyOf(input, input.length);
        long start = System.nanoTime();
        Sorts.insertionSort(newArray);
        long end = System.nanoTime();
        System.out.println("Sorting took " + (end - start) / 1000_000f + " ms ");
    }
    
}

Call it as

measurePerformance(buildArray(10000));

The reason we are copying the array before sorting is that our insertion sort sorts the array in place i.e., after the sort method returns the passed array will be in ascending order (sorted). This will affect the measurement on subsequent runs. Hence, we make a copy of the input array before each call.

This prints like (the exact result will definitely vary from run to run and from machine to machine)

Sorting took 28.479357 ms 
Sorting took 17.107634 ms 
Sorting took 16.817558 ms 
...
Sorting took 22.585983 ms 
Sorting took 38.791553 ms 
Sorting took 12.791842 ms 
Sorting took 19.27184 ms 
Sorting took 41.42186 ms 
Sorting took 33.064342 ms 
Sorting took 12.735878 ms 
Sorting took 21.854004 ms 
...
Sorting took 11.685804 ms 
Sorting took 11.447527 ms 
Sorting took 11.473101 ms

There is a lot of deviations in the timing numbers reported. The time varies from 11 ms to a max of 41 ms. It seems to get settled down towards the end where the time is around 11 ms. 

So, what we do to arrive at a single number as the running or execution time? We run it in a loop as above (and maybe more number of times say 1000 or 10,000) and take the average. This does not give us the right number as we are taking into account the occasional noisy readings as well. 

 
Let us see a couple of extensions of this where the noise is evident.

Performance of insertion sort when the input is reverse sorted

In this, we invoke selection sort with the sorted array reversed. In other words, we are simulating its worst case runtime. 

private static void measurePerformanceForAvgAndWorstCase(int[] input) {
    for (int i = 0; i < 100; i++) {
        int[] newArray = Arrays.copyOf(input, input.length);
        long start = System.nanoTime();
        Sorts.insertionSort(newArray); //avg case
        long end = System.nanoTime();
        long result1 = (end - start) / 1000_000L;

        //Reverse the sorted array
        int[] reversedArray = new int[newArray.length];
        for (int j = newArray.length - 1, k = 0; j >= 0; j--) {
            reversedArray[k++] = newArray[j];
        }
        start = System.nanoTime();
        Sorts.insertionSort(reversedArray); //worst case
        end = System.nanoTime();
        long result2 = (end - start) / 1000_000L;
        System.out.println(result1 + "," + result2);
    }
}

This prints like (all units are in milliseconds)

29,35
17,28
11,23
14,42
..
32,23
47,30
..
11,23
12,26

We print the average case execution time followed by the worst case time. As seen earlier, there are some discrepancies and noise in the numbers. The difference is not uniform (or close to uniform). 

Also, there are some cases where the worst case is less than the average case (32,23 and 47,30). And, this happens for the same data set (we run our measurement in a loop for the same array). But for most entries the worst case time > average case time. This is a second form of noise in our measurement.

Comparing Insertion sort with Quick sort

Let us compare the runtime of Insertion sort (average runtime of n2) with Quick sort (average runtime of n log n).

private static void compareInsertionAndQuickSort(int[] input) {
   for (int i = 0; i < 1000; i++) {
       int[] newArray = Arrays.copyOf(input, input.length);
       long start = System.nanoTime();
       Sorts.insertionSort(newArray);
       long end = System.nanoTime();
       long result1 = (end - start) / 1000_000L;

       newArray = Arrays.copyOf(input, input.length);
       start = System.nanoTime();
       Sorts.quickSort(newArray);
       end = System.nanoTime();
       long result2 = (end - start) / 1000_000L;
       System.out.println(result1 + "," + result2);
   }
}

It prints the runtime of insertion sort followed by that of quick sort (again all units are in milliseconds). 

Sample output:

27,6
21,0
31,0
14,0
16,2
16,1
..
12,14
..
35,0
11,0

First we can see deviations or oscillations in the time of insertion sort. Most cases, quick sort takes ~0 ms. But on some cases it takes as long as 14 ms. Second, on some cases the quick sort’s time is greater than that of insertion sort. 

Problems with our very naive approach

Running a benchmark using a clock or time based does not yield the right results.  I also mean the other approaches commonly used like Google Guava’s stopwatch and Instant class in Java. As said earlier we normally run the tests in a loop and take the average.  The noise of variations in the numbers seen are due to a lot of things happening behind the scenes in the JVM. The first time a code runs takes more time that the following runs. JVM identifies a hot method and does some optimisations. Garbage collection (GC) also has a part in this.

Other than this, the things we do like copying the input array, printing the results to the screen can also play a part. 

Summary

In this post, we saw the most common flawed approach of measuring the execution time of a code in Java. We started with measuring/benchmarking the insertion sort code. We followed it with by comparing the average and the worst case of it. Finally, we compared insertion sort with quick sort. In all cases, we noticed deviations in the output and learnt that such a method of measuring execution time of a code or benchmarking is wrong and should not be relied upon.
In the next post, we will improve this very naive approach to arrive at a reasonable sounding benchmarking method. Stay tuned.

Other references

https://stackoverflow.com/questions/2553347/how-can-i-benchmark-method-execution-time-in-java

Leave a Reply