Problem in using System.currentTimeMillis(); in Java

Question

I tried to observe the time taken by different inputs in the calculation of the nth Fibonacci number, but the output is <50ms for the first input and 0 ms for the rest Why so?

import java.io.*;
import java.util.*;
class fib{
    long fibo(int s){
        if(s==1 ||s==2)
        return 1;
        else return fibo(s-1)+(s-2);
    }
}
class fibrec{
    public static void main(String args[]) throws java.io.IOException{
        BufferedWriter wr=new BufferedWriter(new FileWriter("C:/Users/91887/desktop/books/java/foo3.txt"));
        fib f=new fib();
        Random rand=new Random();
        int input[]=new int[10];
        for(int p=0;p<10;p++){
            long st=System.currentTimeMillis();
            int i=rand.nextInt(12000);
            wr.write("Input : "+i+"\nOutput : "+f.fibo(i)+"\n");
            long et=System.currentTimeMillis();
            wr.write("Time taken = "+(et-st)+"ms\n\n");
            System.out.println(st+"\t"+et+"\t"+(et-st));
        }

        wr.close();
    }
}

Input : 2348 Output : 2753032 Time taken = 35ms Input : 7718 Output : 29772187 Time taken = 1ms Input : 8485 Output : 35984887 Time taken = 0ms Input : 6620 Output : 21902272 Time taken = 0ms Input : 2671 Output : 3563116 Time taken = 0ms Input : 6244 Output : 19484404 Time taken = 0ms Input : 5370 Output : 14410397 Time taken = 0ms Input : 2340 Output : 2734292 Time taken = 0ms Input : 6547 Output : 21421786 Time taken = 0ms Input : 7580 Output : 28716832 Time taken = 0ms — Siddharth Meghwal, May 21 '19 at 03:15
Related: [How do I write a correct micro-benchmark in Java?](https://stackoverflow.com/questions/504103/how-do-i-write-a-correct-micro-benchmark-in-java). Among other things, it says "Make sure you run it for long enough to be able to measure the results in seconds or (better) tens of seconds" and "Use a library for your benchmark". — Bernhard Barker, May 21 '19 at 08:52

Stephen C · Answer 1 · 2019-05-21T04:18:48.267

The granularity of the millisecond clock is at best one millisecond¹.

But apparently, the execution times for your loop iterations are less than one millisecond. Sub-millisecond time intervals cannot be measured accurately using System.currentTimeMillis(). That is why you are getting zeros.

The explanation for the first measurement being 35 milliseconds is that this is due to JVM warmup effects. These may include:

time taken to load and initialize library code²,
time taken to JIT compile code, and
time taken up with a (possible) GC during or after loading and JIT compilation.

Secondly, I notice that your time measurement includes the time taken to print the number. You should move that after the second call to get the clock value because it could be significant.

Finally, it you want to get reproducible results, you should explicitly seed Random yourself rather than relying on the OS to give you a random seed. And I'm not convinced that you should be benchmarking a Fibonacci algorithm with random inputs anyway ...

^{1 - The numbers in your output suggest that it is actually 1 millisecond ...}

^{2 - For example, the initialization and construction of a Random instance entails an OS call to get some "entropy" to seed the random number generator. That should be fast, but there are circumstances where it may not be. In your case, this happens before you start measuring time ...}

score 0 · Answer 2 · answered May 21 '19 at 03:20

The code between the two calls to System.currentTimeMillis() is executing too fast (after the first iteration) for any difference to be captured. You'd be able to see a difference if you were using System.nanoTime().

As for why the first iteration is slower than the subsequent ones, that would be because Java uses a Just In Time (JIT) compiler to optimise code at runtime.

Problem in using System.currentTimeMillis(); in Java

2 Answers2