13

Have a look at the code below:

class Test
{
    public static void main(String abc[])
    {
        for( int N=1; N <= 1_000_000_000; N=N*10)
        {
            long t1 = System.nanoTime();

            start(N);

            long t2 = System.nanoTime() - t1;
            System.out.println("Time taken for " + N + " : " + t2);
        }
    }

    public static void start( int N )
    {
        int j=1;
        for(int i=0; i<=N; i++)
            j=j*i;
    }
}

The output produced by the above question is:

Time taken for 1 : 7267
Time taken for 10 : 3312
Time taken for 100 : 7908
Time taken for 1000 : 51181
Time taken for 10000 : 432124
Time taken for 100000 : 4313696
Time taken for 1000000 : 9347132
Time taken for 10000000 : 858
Time taken for 100000000 : 658
Time taken for 1000000000 : 750

Questions:

1.) Why is time taken for N=1 unusually greater than the N=10 ? (sometimes it even exceeds N=100)

2.) Why is time taken for N=10M and onwards unusually lower ?

The pattern indicated in the above questions is profound and remains even after many iterations. Is there any connection to memoization here ?

EDIT:

Thank you for your answers. I thought of replacing the method call with the actual loop. But now, there is no JIT Optimization. Why not ? Is putting the statements in a method facilitating in the optimization process ? The modified code is below:

class test
{
    public static void main(String abc[])
    {
        for( int k=1; k<=3; k++)
        {
            for( int N=1; N<=1_000_000_000; N=N*10)
            {
                long t1 = System.nanoTime();

                int j=1;
                for(int i=0; i<=N; i++)
                    j=j*i;

                long t2 = System.nanoTime() - t1;
                System.out.println("Time taken for "+ N + " : "+ t2);
            }
        }
    }
}

EDIT 2: The output of above modified code:

Time taken for 1 : 2160
Time taken for 10 : 1142
Time taken for 100 : 2651
Time taken for 1000 : 19453
Time taken for 10000 : 407754
Time taken for 100000 : 4648124
Time taken for 1000000 : 12859417
Time taken for 10000000 : 13706643
Time taken for 100000000 : 136928177
Time taken for 1000000000 : 1368847843
Time taken for 1 : 264
Time taken for 10 : 233
Time taken for 100 : 332
Time taken for 1000 : 1562
Time taken for 10000 : 17341
Time taken for 100000 : 136869
Time taken for 1000000 : 1366934
Time taken for 10000000 : 13689017
Time taken for 100000000 : 136887869
Time taken for 1000000000 : 1368178175
Time taken for 1 : 231
Time taken for 10 : 242
Time taken for 100 : 328
Time taken for 1000 : 1551
Time taken for 10000 : 13854
Time taken for 100000 : 136850
Time taken for 1000000 : 1366919
Time taken for 10000000 : 13692465
Time taken for 100000000 : 136833634
Time taken for 1000000000 : 1368862705
13
  • Why should this be Integer overflow? t1 and t2 are of type long, as is the return type of System.nanoTime() Jul 20, 2013 at 11:01
  • Even so, why is it taking so less time ? It has to multiply even if the result is 0
    – Divyanshu
    Jul 20, 2013 at 11:02
  • @RohitJain: Yes, but the value of j is never actually used - so why do you think that integer overflow is relevant?
    – Jon Skeet
    Jul 20, 2013 at 11:03
  • 1
    Use ThreadMXBean.getCurrentThreadCpuTime() instead of System.nanoTime() for timing code execution, else if your browser plays a YouTube video while you run your code, that will be included in the numbers too. Jul 20, 2013 at 11:15
  • 1
    @DanielDinnyes Thank you! I was looking for such a method which would exactly time the execution of a thread!
    – Divyanshu
    Jul 20, 2013 at 11:22

3 Answers 3

16

1.) Why is time taken for N=1 unusually greater than the N=10

Because it's the first time the VM has seen that code - it may decide to just interpret it, or it will take a little bit of time JITting it to native code, but probably without optimization. This is one of the "gotchas" of benchmarking Java.

2.) Why is time taken for N=10M and onwards unusually lower ?

At that point, the JIT has worked harder to optimize the code - reducing it to almost nothing.

In particular, if you run this code multiple times (just in a loop), you'll see the effect of the JIT compiler optimizing:

Time taken for 1 : 3732
Time taken for 10 : 1399
Time taken for 100 : 3266
Time taken for 1000 : 26591
Time taken for 10000 : 278508
Time taken for 100000 : 2496773
Time taken for 1000000 : 4745361
Time taken for 10000000 : 933
Time taken for 100000000 : 466
Time taken for 1000000000 : 933
Time taken for 1 : 933
Time taken for 10 : 467
Time taken for 100 : 466
Time taken for 1000 : 466
Time taken for 10000 : 933
Time taken for 100000 : 466
Time taken for 1000000 : 933
Time taken for 10000000 : 467
Time taken for 100000000 : 467
Time taken for 1000000000 : 466
Time taken for 1 : 467
Time taken for 10 : 467
Time taken for 100 : 466
Time taken for 1000 : 466
Time taken for 10000 : 466
Time taken for 100000 : 467
Time taken for 1000000 : 466
Time taken for 10000000 : 466
Time taken for 100000000 : 466
Time taken for 1000000000 : 466

As you can see, after the first the loop takes the same amount of time whatever the input (module noise - basically it's always either ~460ns or ~933ns, unpredictably) which means the JIT has optimized the loop out.

If you actually returned j, and changed the initial value of i to 1 instead of 0, you'll see the kind of results you expect. The change of the initial value of i to 1 is because otherwise the JIT can spot that you'll always end up returning 0.

2
  • +1 for an awesome introduction to the JIT optimisation! Out of raised curiosity, where can I find the best material to get some more info about JITing?
    – Sankalp
    Jul 20, 2013 at 11:13
  • @Sankalp: It depends what you're after, to be honest - I don't know of any particularly good one-size-fits-all material. I suggest you do appropriate searching :) If you're interested in Java specifically, you probably want to search for information about hotspot.
    – Jon Skeet
    Jul 20, 2013 at 11:14
2

youre actually benchmarking java's JIT. if i modify yout code a bit:

class Test
{
    public static void main(String abc[])
    {
        for( int N=1; N <= 1_000_000_000; N=N*10)
        {
            long t1 = System.nanoTime();

            start(N);

            long t2 = System.nanoTime() - t1;
            System.out.println("Time taken for " + N + " : " + t2);
        }

        for( int N=1; N <= 1_000_000_000; N=N*10)
        {
            long t1 = System.nanoTime();

            start(N);

            long t2 = System.nanoTime() - t1;
            System.out.println("Time taken for " + N + " : " + t2);
        }
    }

    public static void start( int N )
    {
        int j=1;
        for(int i=0; i<=N; i++)
            j=j*i;
    }
}

i get this:

Time taken for 1 : 1811
Time taken for 10 : 604
Time taken for 100 : 1510
Time taken for 1000 : 10565
Time taken for 10000 : 104439
Time taken for 100000 : 829173
Time taken for 1000000 : 604
Time taken for 10000000 : 302
Time taken for 100000000 : 0
Time taken for 1000000000 : 0
Time taken for 1 : 0
Time taken for 10 : 302
Time taken for 100 : 0
Time taken for 1000 : 302
Time taken for 10000 : 301
Time taken for 100000 : 302
Time taken for 1000000 : 0
Time taken for 10000000 : 0
Time taken for 100000000 : 0
Time taken for 1000000000 : 302

never benchmark a "cold" system. always repeat every measurement several times and discard the 1st few ones because the optimizations have not yet kicked in

1
  • The problem is also about the JIT compiling the loop away, not just having a cold benchmark Jul 20, 2013 at 11:13
1

The reason is that 1) you don't return the value, and 2) the result of the calculation is always 0. Eventually the JIT will simply compile the loop away.

You get your expected behaviour if you change your loop to:

public static int start(int N) {
    int j = 1;
    for (int i = 1; i <= N; i++)
        j = j * i;
    return j;
}

Note that I have both changed the loop init to int i = 1 and added return j. If I only do one of those, the loop will (eventually) still be compiled away.

This will produce the following series (if executed twice):

Time taken for 1 : 2934
Time taken for 10 : 1466
Time taken for 100 : 3422
Time taken for 1000 : 20534
Time taken for 10000 : 191644
Time taken for 100000 : 1898845
Time taken for 1000000 : 1210489
Time taken for 10000000 : 11884401
Time taken for 100000000 : 115257525
Time taken for 1000000000 : 1061254223
Time taken for 1 : 978
Time taken for 10 : 978
Time taken for 100 : 978
Time taken for 1000 : 2444
Time taken for 10000 : 11244
Time taken for 100000 : 103644
Time taken for 1000000 : 1030089
Time taken for 10000000 : 10448535
Time taken for 100000000 : 107299391
Time taken for 1000000000 : 1072580803
2
  • In my recent edit, i've still kept i=0, so the product will become zero. But there doesn't seem to be any optimization now
    – Divyanshu
    Jul 20, 2013 at 11:17
  • @Divyanshu As I commented, that might be better as a separate question. Jul 20, 2013 at 11:19

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.