Java: int and double take 0 millisecons to do simple calculation for 100 million times

Question

I am doing some simple tests with double, like this:

startTime = System.currentTimeMillis();

for (int i = 0; i < 100_000_000; i++) 
{
   doubleCalcTest();
}

endTime = System.currentTimeMillis();    
System.out.println("That took " + (endTime - startTime) + " nanoseconds");

.

public static double doubleCalcTest() 
{
    double x = 987.654321;
    double y = 123.456789;

    x = x + y;
    x = x - y;
    x = x * y;
    return x / y;
}

It turns out that the output is 0 milliseconds. It doesn't make sense to me because if I set the for loop to run only for 100,000 times, the output is 3 milliseconds. I found int also acting in the same way.

Can anyone give me a hand on this one? Thanks.

I changed my code to call 'System.nanoTime' time and passing in a double value incremented by the index of the loop as suggested.

double x = 123.456789
startTime = System.nanoTime();

for (int i = 0; i < 100_000_000; i++) 
{
   x = x + i;
   doubleCalcTest(x);
}

endTime = System.nanoTime();    
System.out.println("That took " + (endTime - startTime) + " nanoseconds");

.

public static double doubleCalcTest(double x) 
{
    double y = 123.456789;

    x = x + y;
    x = x - y;
    x = x * y;
    return x / y;
}

Run 10,000 times took 503,200 nanoseconds

Run 10,000,000 times took 3,421 nanoseconds

Answer 1

The JIT discards the execution of DoubleCalcTest since it does not have any side-effect (pure calculation) and the result is not used. The loop itself can also be optimized out since there is no effect.

Try this with JIT off and it will take around 8000 ms:

java -Xint snippet.Snippet

At the byteocde level, nothing is optimized out.

javap -c snippet.Snippet

result:

public class snippet.Snippet {
  public snippet.Snippet();
    Code:
       0: aload_0       
       1: invokespecial #8                  // Method java/lang/Object."<init>":()V
       4: return        

  public static void main(java.lang.String[]);
    Code:
       0: invokestatic  #16                 // Method java/lang/System.currentTimeMillis:()J
       3: lstore_1      
       4: iconst_0      
       5: istore_3      
       6: goto          16
       9: invokestatic  #22                 // Method DoubleCalcTest:()D
      12: pop2          
      13: iinc          3, 1
      16: iload_3       
      17: ldc           #26                 // int 100000000
      19: if_icmplt     9
      22: invokestatic  #16                 // Method java/lang/System.currentTimeMillis:()J
      25: lstore_3      
      26: getstatic     #27                 // Field java/lang/System.out:Ljava/io/PrintStream;
      29: new           #31                 // class java/lang/StringBuilder
      32: dup           
      33: ldc           #33                 // String That took 
      35: invokespecial #35                 // Method java/lang/StringBuilder."<init>":(Ljava/lang/String;)V
      38: lload_3       
      39: lload_1       
      40: lsub          
      41: invokevirtual #38                 // Method java/lang/StringBuilder.append:(J)Ljava/lang/StringBuilder;
      44: ldc           #42                 // String  milliseconds
      46: invokevirtual #44                 // Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
      49: invokevirtual #47                 // Method java/lang/StringBuilder.toString:()Ljava/lang/String;
      52: invokevirtual #51                 // Method java/io/PrintStream.println:(Ljava/lang/String;)V
      55: return        

  public static double DoubleCalcTest();
    Code:
       0: ldc2_w        #64                 // double 987.654321d
       3: dstore_0      
       4: ldc2_w        #66                 // double 123.456789d
       7: dstore_2      
       8: dload_0       
       9: dload_2       
      10: dadd          
      11: dstore_0      
      12: dload_0       
      13: dload_2       
      14: dsub          
      15: dstore_0      
      16: dload_0       
      17: dload_2       
      18: dmul          
      19: dstore_0      
      20: dload_0       
      21: dload_2       
      22: ddiv          
      23: dreturn       
}

If you try to use to result of DoubleCalc() by assigning it to a variable and print it afterward.

public static void main(String[] args) {
    long startTime = System.currentTimeMillis();

    double res = 0;
    for (int i = 0; i < 100000000; i++) {
        res = DoubleCalcTest();
    }

    System.out.println(res);
    long endTime = System.currentTimeMillis();
    System.out.println("That took " + (endTime - startTime) + " milliseconds");
}

It will take the same time. Why? The JIT seems to be smart enough to understand that the result does not depend on the number of time the iteration is done.

However, if you change this to:

public static void main(String[] args) {
    long startTime = System.currentTimeMillis();

    double res = 0;
    for (int i = 0; i < 100000000; i++) {
        res += DoubleCalcTest();
    }

    System.out.println(res);
    long endTime = System.currentTimeMillis();
    System.out.println("That took " + (endTime - startTime) + " milliseconds");
}

The result depends on the number of iteration and the JIT does not optimize further. In this case, it takes about 100 ms. If I change 100000000 for 200000000, it takes twice as much time.

So the conclusion is that the JIT stops there.

NOTE:

For the give C program:

#include <stdio.h>

int main(int argc, char** argv) {

    long x = 0;
    int i;

    for(i=0; i<1000000; i++) {
       x+=i;
    }
    printf("%ld", x);
}

GCC is able to optimized the loop entirely and compute the value of x at compile-time:

gcc -O2 -S main.c

main.s:

    .file   "main.c"
    .section    .rodata.str1.1,"aMS",@progbits,1
.LC0:
    .string "%ld"
    .section    .text.startup,"ax",@progbits
    .p2align 4,,15
    .globl  main
    .type   main, @function
main:
.LFB11:
    .cfi_startproc
    movabsq $499999500000, %rsi   <---- See, this is the pre-computed result
    movl    $.LC0, %edi
    xorl    %eax, %eax
    jmp printf
    .cfi_endproc
.LFE11:
    .size   main, .-main
    .ident  "GCC: (GNU) 4.7.2 20121109 (Red Hat 4.7.2-8)"
    .section    .note.GNU-stack,"",@progbits

Pretty cool, heh?

Answer 2

OK. I think the compiler finds that you never use the returning value of the method, so the method is not executed at all. My result seems different from yours, but it makes more sense.

public static void main (String args[]) {
    long startTime = System.currentTimeMillis();
    double d = 0;

    for (int i = 0; i < 100000000; i++) {
        //DoubleCalcTest();
    }

    long endTime = System.currentTimeMillis();
    System.out.println("That took " + (endTime - startTime) + " milliseconds");
}

Uncommenting DoubleCalcTest(); in the loop, the result is about 80 ms as I said. Commenting it, the result is the same.

Now change it to d += DoubleCalcTest(); The result is 844 ms.

I thought before I should use d later after logging the endTime, e.g. call System.out.println(d);, but it had no difference, so I deleted it.

With d += DoubleCalcTest(), running 1,000,000 times, it is about 10 ms. which is approximately 1/100 of the time for running 100,000,000 times, which is correct considering errors.

Answer 3

Gordon has good point. Did you leave the comma's in your actual code?

If not then try passing an argument value into the method so the JVM can't optimize away the entire thing.

For example :

public static double DoubleCalcTest(double x) 
{

double y = 123.456789;

    x = x + y;
    x = x - y;
    x = x * y;
    return x / y;
}

And then pass in a double value incremented by the index of your loop. The JVM won't be able to optimize away as much because it's no longer a static calculation.

Answer 4

This is because what you have written is not the value 100000000, it is the three values 100, 000, 000, seperated by the comma operator, which evaluates both of its operands, and returns the value of the one on the right. Your loop is never being entered, because 100,000,000 == (100,0),0 == 0,0 == 0.

Answer 5

There may have been optimization, but to be sure, replace System.currentTimeMillis with System.nanoTime.

System.nanoTime returns time in nanoseconds, which is far more precise. Also, the Javadocs recommend using it to measure elapsed time.