Weird Time Taken

[purijatin]

In the below code, iam calculating the time taken to calculate the Square Root of first 30000000 numbers. But there is a weird thing happening:

import java.util.*;


public class Cache 
{
    public static void main(String args[])
    {

        for(int j=0;j<=1000;j++)
        {
            ;
        }
        float[] a = new float[30000000];
        long as = System.currentTimeMillis();
        for(int i=0;i<30000000;i++)
        {
            a[i]=(float) Math.sqrt(i);
        }
        long as2= System.currentTimeMillis();
        System.out.println(as2-as);


    }

}

Now in the for loop with counter j which is absolutely doing nothing, i found out that if i limit the counter till 1000 as shown above, the answer on an average is about 1500(ie msec). But if i increase the counter of j to 1000000. THe answer is 5000+.

This is weird because the time taken should be independent of how many times the loop is running.

[JamesCherrill]

Interesting...
for your two cases my little laptop gave me 2126 mSec and 3044 mSec - implying that the first loop takes an extra 900 mSec going from 1000 to 1000000.
But if I limit the main loop to just 1 pass, even j<10000000 runs in 1 mSec.

[purijatin]

the time is calculated from the line 15 to line 22. and hence it must be independent of the first loop. Whether we have a loop in the beginning or not shouldnt matter.
Is it because due to more memory consumption on RAM or so and hence taking more time to fetch the addresses?.

[purijatin]

the time is calculated from the line 15 to line 22. and hence it must be independent of the first loop. Whether we have a loop in the beginning or not shouldnt matter.
Is it because due to more memory consumption on RAM or so and hence taking more time to fetch the addresses?.

SO james what do you think??

[JamesCherrill]

I dunno, it's a mystery. Someone... answer please!

[jon.kiparsky]

Curiouser and curiouser. When I set it up, I put a timer around the first loop. For any simple numeric value in the test condition of the first loop, it optimized out to zero millis and about 1 second for the second loop.
However, when I set the test condition to j<Integer.MAX_VALUE; it just sat there stubbornly giving no response, suggesting that it failed to optimize out. Same result when I give 2147483647 as an explicit value...

Set it to Short.MAX_VALUE, and bang, we're back to running at zero time for loop 1.

I'm going to play with this a little, but I'm at work, so I don't have access to a proper system (*#@$ Windows crap...). If anyone wants to run a bit of javap on these, I'd love to see what the bytecode is looking like.

Here's the version that hangs:

public class Cache 
{
    public static void main(String args[])
    {
    	long time1 = System.currentTimeMillis();
    	int q = Integer.MAX_VALUE;
    	System.out.println("Before first loop. q = "+q);
        for(int j=0;j<=q;j++)
        {
            ;
        }
        long time2 = System.currentTimeMillis() - time1;
        System.out.println("After First loop. Time = "+time1);
        float[] a = new float[30000000];
        long as = System.currentTimeMillis();
        for(int i=0;i<30000000;i++)
        {
            a[i]=(float) Math.sqrt(i);
        }
        long as2= System.currentTimeMillis();
        
        System.out.println("Time loop 1 = " + time2 + " Time loop 2 = "+ (as2-as));


    }

}

[JamesCherrill]

I had tried j<Integer.MAX_VALUE as well, but broke out after maybe 10 secs assuming it was just how long it took for that number of iterations. Maybe that was too glib an assumption?

[jon.kiparsky]

Maybe, but I let it run for rather a while while I worked on some other stuff (a certain amount of web surfing if we're being honest here) and it showed no response. I suppose I could go in with the debugger and find out something, but I think I'd learn more reading the bytecode.

[JamesCherrill]

I did notice that my CPUs were only loaded ~ 50% each - not what I'd expect from a tight loop like that

[jon.kiparsky]

This may be interesting to exactly one other person here, but here you are, James.

This is what the compiler generates for the original code.

public static void main(java.lang.String[]);
  Code:
   Stack=5, Locals=6, Args_size=1
   0:	iconst_0
   1:	istore_1
   2:	iload_1
   3:	sipush	1000
   6:	if_icmpgt	15
   9:	iinc	1, 1
   12:	goto	2
   15:	ldc	#2; //int 30000000
   17:	newarray float
   19:	astore_1
   20:	invokestatic	#3; //Method java/lang/System.currentTimeMillis:()J
   23:	lstore_2
   24:	iconst_0
   25:	istore	4
   27:	iload	4
   29:	ldc	#2; //int 30000000
   31:	if_icmpge	51
   34:	aload_1
   35:	iload	4
   37:	iload	4
   39:	i2d
   40:	invokestatic	#4; //Method java/lang/Math.sqrt:(D)D
   43:	d2f
   44:	fastore
   45:	iinc	4, 1
   48:	goto	27
   51:	invokestatic	#3; //Method java/lang/System.currentTimeMillis:()J
   54:	lstore	4
   56:	getstatic	#5; //Field java/lang/System.out:Ljava/io/PrintStream;
   59:	lload	4
   61:	lload_2
   62:	lsub
   63:	invokevirtual	#6; //Method java/io/PrintStream.println:(J)V
   66:	return

Notice the loop from lines 3-12. I'd have thought that would have been optimized out, but there it is. That explains it, I suppose. So my mystery is simple enough.

What it doesn't explain, though, is the original question - why does increasing j (in the first loop) apparently increase the duration of the second loop? I really don't see any way for that result to come about, and I can't reproduce it here. I had to give myself a bigger heap, but it ran in 190 millis with j=1000 and 191 millis with j=10000000 - no difference, that is.

Are you sure you're running the code as posted? If your timer surrounded both loops, this would make some sense, but it doesn't make sense at all with the code you've posted.

[purijatin]

Interesting.. I was executing this code via NetBeans IDE. On an average it was giving the same results as i mentioned above ie 2nd loop took around 1300-1400 msec and with the 1st loop took around 2000-2100 msec.

But now I again tried it from the Command Prompt and bang; with or without an upperloop,it took almost the same time, with a marginal difference( that anyways can happen).

So I think somehow its got to do with the IDE, probably The thread priority assigned or something, or probably the difference is due to thread scheduling because netbeans threads are also vying for the processor.

[JamesCherrill]

The tests I ran, that confirmed your original findings, were in Eclipse, so maybe it's a result of using an IDE (any IDE?).

[purijatin]

Hmm may be, IDE is the reason for all these. LOL I was just thinking this criteria can also be added to justify which IDE is the best, as in the one which will give results independent of how much processing happened should be given more weight.

But again why is it happening every time, because as far as I think they would have given the IDE threads minimum priority when the program run's, why does the processing rate fluctuate's with time?

[jon.kiparsky]

purijatin - could you run javap on the class file that NetBeans gives you? javap -v Cache is the syntax you'll use. It'll give you a bunch of assembly-looking stuff, like what I posted above. I'd like to see if there's any difference between the two.

[purijatin]

Here is the Assembly code

Compiled from "Cache.java"
public class Cache extends java.lang.Object
  SourceFile: "Cache.java"
  minor version: 0
  major version: 50
  Constant pool:
const #1 = Method       #9.#20; //  java/lang/Object."<init>":()V
const #2 = int  1000000;
const #3 = Method       #21.#22;        //  java/lang/System.currentTimeMillis:
)J
const #4 = int  10000000;
const #5 = Method       #23.#24;        //  java/lang/Math.sqrt:(D)D
const #6 = Field        #21.#25;        //  java/lang/System.out:Ljava/io/Print
tream;
const #7 = Method       #26.#27;        //  java/io/PrintStream.println:(J)V
const #8 = class        #28;    //  Cache
const #9 = class        #29;    //  java/lang/Object
const #10 = Asciz       <init>;
const #11 = Asciz       ()V;
const #12 = Asciz       Code;
const #13 = Asciz       LineNumberTable;
const #14 = Asciz       main;
const #15 = Asciz       ([Ljava/lang/String;)V;
const #16 = Asciz       StackMapTable;
const #17 = class       #30;    //  "[F"
const #18 = Asciz       SourceFile;
const #19 = Asciz       Cache.java;
const #20 = NameAndType #10:#11;//  "<init>":()V
const #21 = class       #31;    //  java/lang/System
const #22 = NameAndType #32:#33;//  currentTimeMillis:()J
const #23 = class       #34;    //  java/lang/Math
const #24 = NameAndType #35:#36;//  sqrt:(D)D
const #25 = NameAndType #37:#38;//  out:Ljava/io/PrintStream;
const #26 = class       #39;    //  java/io/PrintStream
const #27 = NameAndType #40:#41;//  println:(J)V
const #28 = Asciz       Cache;
const #29 = Asciz       java/lang/Object;
const #30 = Asciz       [F;
const #31 = Asciz       java/lang/System;
const #32 = Asciz       currentTimeMillis;
const #33 = Asciz       ()J;
const #34 = Asciz       java/lang/Math;
const #35 = Asciz       sqrt;
const #36 = Asciz       (D)D;
const #37 = Asciz       out;
const #38 = Asciz       Ljava/io/PrintStream;;
const #39 = Asciz       java/io/PrintStream;
const #40 = Asciz       println;
const #41 = Asciz       (J)V;

{
public Cache();
  Code:
   Stack=1, Locals=1, Args_size=1
   0:   aload_0
   1:   invokespecial   #1; //Method java/lang/Object."<init>":()V
   4:   return
  LineNumberTable:
   line 6: 0


public static void main(java.lang.String[]);
  Code:
   Stack=5, Locals=7, Args_size=1
   0:   iconst_0
   1:   istore_1
   2:   iload_1
   3:   bipush  100
   5:   if_icmpgt       81
   8:   iconst_0
   9:   istore_2
   10:  iload_2
   11:  ldc     #2; //int 1000000
   13:  if_icmpgt       22
   16:  iinc    2, 1
   19:  goto    10
   22:  invokestatic    #3; //Method java/lang/System.currentTimeMillis:()J
   25:  lstore_2
   26:  ldc     #4; //int 10000000
   28:  newarray float
   30:  astore  4
   32:  iconst_0
   33:  istore  5
   35:  iload   5
   37:  ldc     #4; //int 10000000
   39:  if_icmpge       60
   42:  aload   4
   44:  iload   5
   46:  iload   5
   48:  i2d
   49:  invokestatic    #5; //Method java/lang/Math.sqrt:(D)D
   52:  d2f
   53:  fastore
   54:  iinc    5, 1
   57:  goto    35
   60:  invokestatic    #3; //Method java/lang/System.currentTimeMillis:()J
   63:  lstore  5
   65:  getstatic       #6; //Field java/lang/System.out:Ljava/io/PrintStream;
   68:  lload   5
   70:  lload_2
   71:  lsub
   72:  invokevirtual   #7; //Method java/io/PrintStream.println:(J)V
   75:  iinc    1, 1
   78:  goto    2
   81:  return
  LineNumberTable:
   line 10: 0
   line 13: 8
   line 17: 22
   line 18: 26
   line 19: 32
   line 21: 42
   line 19: 54
   line 23: 60
   line 24: 65
   line 10: 75
   line 25: 81

  StackMapTable: number_of_entries = 6
   frame_type = 252 /* append */
     offset_delta = 2
     locals = [ int ]
   frame_type = 252 /* append */
     offset_delta = 7
     locals = [ int ]
   frame_type = 250 /* chop */
     offset_delta = 11
   frame_type = 254 /* append */
     offset_delta = 12
     locals = [ long, class "[F", int ]
   frame_type = 250 /* chop */
     offset_delta = 24
   frame_type = 248 /* chop */
     offset_delta = 20


}