ArrayList shows different time of execution each time why?

Question

I was working with ArrayList and trying to add new object at starting of ArrayList of a prepopulated ArrayList having 3000000 record all ready.

According to my knowledge it will add new object at first index and move all record below to their previous position. And this should happen each time when i add new object to that array list. Means execution time should be same (Little variation may happen).

But when i add new record its shows 0 and some time 15.

Here is my program

package com.rais;

import java.util.ArrayList;
import java.util.List;

public class ArrayListTest {

    public static List<String> arrList = new ArrayList<String>();
    static {
        for (int i = 0; i < 3000000; i++) {
            arrList.add("Hello"+i);
        }
    }


    public static void main(String[] args) {
        for (int i = 0; i < 5; i++) {

            long startTime = System.currentTimeMillis();

            arrList.add(0,"Rais"+i);

            long endTime = System.currentTimeMillis();
            System.out.println("Total execution time ="+(endTime-startTime));


        }
       }

    }

And here is output of that program.

Total execution time =0
Total execution time =0
Total execution time =15
Total execution time =0
Total execution time =0

I am confused why it shows 0 . It should show 15 or little near to 15 each time but it should not show 0.

On some old versions of windows the have poor resolution of this timer. I suggest you use System.nanoTime() and since the code doesn't warmup until it has run 10,000 times, I would ignore the first 12,000 runs. — Peter Lawrey, Aug 11 '13 at 07:29

score 4 · Accepted Answer · answered Aug 11 '13 at 07:08

4

The problem may be the way you're measuring, from the docs of currentTimeMillis();

Returns the current time in milliseconds. Note that while the unit of time of the return value is a millisecond, the granularity of the value depends on the underlying operating system and may be larger. For example, many operating systems measure time in units of tens of milliseconds.

In other words, if currentTimeMillis has a granularity close to 15ms on your system, you'll get either 0 or 15ms, slightly randomly depending on the start time even if the operation always takes the same amount of time.

answered Aug 11 '13 at 07:08

Joachim Isaksson

176,943
25
281
294

Please explain little more. – Rais Alam Aug 11 '13 at 07:23
@RaisAlam In short, `currentTimeMillis` on your system seems like it increases by 15 every 15ms instead of by 1 every ms. If you end up starting your work just before it increases, even a short time will end up looking like 15ms. For example, if it increases and 14ms after that you start work that takes 2ms, `currentTimeMillis()` will increase by 15 in the middle of your job, making currentTimeMillis tell you that your job took 15ms even though it only took 2ms. If you want _accurate_ timing, you'll need to run your work multiple times (say 1000 times) and take an average. – Joachim Isaksson Aug 11 '13 at 07:47

score 1 · Answer 2 · answered Aug 11 '13 at 07:06

I can't explain the results you see, however I suspect they are at least partly caused by the simplistic benchmarking code you've written.

Good quality benchmarking code runs for hundreds or thousands of iterations and is sensitive to changes in performance due to recompilation and runtime optimisation. Generally speaking System.nanoTime() is also used for these calculations.

See this excellent article from IBM that explains how to benchmark in a robust fashion. The article concludes with a framework that can be used to perform benchmarking according to best practice.

score 1 · Answer 3 · answered Aug 11 '13 at 13:20

As mentioned in other answers, it is probably an issue with clock granularity. You can check whether that is the case with the following code:

public static void main(String[] args) {
    try {
        for (int i = 0; i < 30; i++) {

            long startTimeMillis = System.currentTimeMillis();
            long startTimeNanos = System.nanoTime();

            Thread.sleep(11);

            long endTimeMillis = System.currentTimeMillis();
            long endTimeNanos = System.nanoTime();
            System.out.println("Total execution time ="
                + (endTimeMillis-startTimeMillis)+" ms / "
                + (endTimeNanos-startTimeNanos)+" ns");
        }

    } catch (InterruptedException e) {
        e.printStackTrace();
    }
}

Another (less likely) possibility is that the array inside the ArrayList had reached capacity, and was being expanded (replaced by a larger array).

score 0 · Answer 4 · answered Aug 11 '13 at 07:05

0

Most likely the reason you are not getting accurate times is because currentTimeMillis() is not precise enough to measure it. Do a loop of 10000 of them and time that and see what you get. Adding to an ArrayList likely takes microseconds, not milliseconds (in the usual case). That 15ms you are seeing might be a lag due to garbage collection or something - but whatever it is, you are sampling too small to get accurate results.

answered Aug 11 '13 at 07:05

Brad Peabody

10,917
9
44
63

agreed that data is small, but after addition of new object it will move previously added 299999 object below to their previous position i guess that will take time and we can calulate them in in millis – Rais Alam Aug 11 '13 at 07:15
Gotcha - you have a point - I misread the code the first time and didn't catch that. I still suggest increasing the quantity of what you are doing until it's more measurable. – Brad Peabody Aug 11 '13 at 07:17
Increasing more will result in out of memory exception. Let me try with increasing heap memory. – Rais Alam Aug 11 '13 at 07:27

ArrayList shows different time of execution each time why?

4 Answers4