Why Java System.timeNano() shows the same time?

Question

I want to test the runtime of some sorting algorithm with the following code

int n = 2000;
for(int i=0; i<10; i++){
    n *= 2;
    init(array, n); // initializes array with n elements
    long startTime = System.nanoTime();
    sort(array;
    long elapsedTime = System.nanoTime()-startTime;
    System.out.println("Size: "+n+"\t\tTime: "+elapsedTime/1000000+"(ms)");         
}

The output is

Size: 4000      Time: 0(ms)
Size: 8000      Time: 0(ms)
Size: 16000     Time: 0(ms)
Size: 32000     Time: 0(ms)
Size: 64000     Time: 0(ms)
Size: 128000    Time: 0(ms)
Size: 256000    Time: 0(ms)
Size: 512000    Time: 0(ms)
Size: 1024000   Time: 0(ms)
Size: 2048000   Time: 0(ms)

The problem is not with algorithm, it sorts arrays properly, and it takes noticeable time to do the job for large arrays. This example took about 10 seconds to run. I think I used the nanoTime() just as described in the Java documentation. I searched the answer for this problem and it seems that people have experienced a similar issue. E.g., here Is there a stopwatch in Java?. However, I could not find the answer how to resolve the issue. There were suggestions to use apache's StopWatch, but from what I understood, it uses similar calls to nanoTime(). So, how to fix this problem? If it makes a difference, I am running the code in Windows 7 with jre 1.8.0_31. Thanks

@Toby and yes, you are right, my init method did not initialize the arrays properly :) That's why it was so fast — Andy, Jun 02 '15 at 04:40
@Andy do you understand why the init method fails to work correctly? — , Jun 02 '15 at 04:41
@Toby Yes, I was passing the array and was trying to initialize it inside the init() via `array = new int[size]`. But in java arguments are passed by value, so that did not have an effect on my initial array outside the method. — Andy, Jun 02 '15 at 04:47

score 4 · Accepted Answer · answered Jun 02 '15 at 04:15

4

You're seeing all the same number because you're using integer division to convert nanoseconds to milliseconds, which has the effect of dividing it then truncating off any decimal places.

Try changing:

elapsedTime/1000000

to:

elapsedTime/1000000d

to get the result including decimal places so you get fractional milliseconds.

You can also verify the timing of the loop by replacing the call to sort with a Thread.sleep(50); - you should see every iteration of the loop taking slightly over 50ms.

answered Jun 02 '15 at 04:15

1337joe

2,327
1
20
25

Are you saying `elapsedTime` is smaller than `1000000`? – Sotirios Delimanolis Jun 02 '15 at 04:16
I don't have your sorting method so I really can't say what you're getting for `elapsedTime`, but if it is you'll always have it print `0`. That's why I suggested putting a `sleep` in the loop - you know how long the sleep will take so you can check your timer output against that. – 1337joe Jun 02 '15 at 04:18
Thank you, 1337joe. It looks that that rounding to zero was indeed the problem. Although, I am surprised with the result. The sorting algorithm I used was QuickSort. And the init() method initializes array randomly with the specified size. I must have some silly bugs in those methods too :) – Andy Jun 02 '15 at 04:24

score 1 · Answer 2 · answered Jun 02 '15 at 04:21

Well, it looks that the answer is simply that the sort algorithm runs faster than a millisecond in each case and my integer division rounded it to zero. I apologize for being that silly :)

Updated code

int n = 2000;
for(int i=0; i<10; i++){
    n *= 2;
    int maxN = 500;
    init(array, n, maxN);
    long startTime = System.nanoTime();
    sort(array, 0, array.length-1); 
    long endTime = System.nanoTime();
    int elapsedTime = (int) (endTime-startTime);
    System.out.println("Size: "+n+"\t\tTime: "+elapsedTime+"(ns)"+
                "\t\tStart Time: "+startTime+
                "\t\tEnd Time: "+endTime);          
}

shows the output

Size: 4000      Time: 15822(ns)     Start Time: 699563217433713     End Time: 699563217449535
Size: 8000      Time: 3849(ns)      Start Time: 699563218239780     End Time: 699563218243629
Size: 16000     Time: 4276(ns)      Start Time: 699563219213047     End Time: 699563219217323
Size: 32000     Time: 3421(ns)      Start Time: 699563220704592     End Time: 699563220708013
Size: 64000     Time: 9835(ns)      Start Time: 699563222929081     End Time: 699563222938916
Size: 128000        Time: 3849(ns)      Start Time: 699563227085137     End Time: 699563227088986
Size: 256000        Time: 3849(ns)      Start Time: 699563234049813     End Time: 699563234053662
Size: 512000        Time: 5987(ns)      Start Time: 699563247567366     End Time: 699563247573353
Size: 1024000       Time: 8980(ns)      Start Time: 699563274115410     End Time: 699563274124390
Size: 2048000       Time: 8125(ns)      Start Time: 699563326704767     End Time: 699563326712892

Why Java System.timeNano() shows the same time?

2 Answers2