JVM reports timer taking longer than it should...

[westloar]

I posted not too long ago with code for a timer (that counts to 25s) which was broken, I fixed the issues, but now the JVM reports it taking longer (1 second longer) than it should run for, although the code prints out the time taken, which reports that it works fine, here's the code:

1   2   3   4   5   6   7   8   9   10   11   12   13   14   15   16   17   18   19   20   21   22   23   24   25   26   27   28   29   30   31   32   33   34   35   36   37   38   39   40   41   42   43   44   45   46

public static void main(String[] args) {         Runnable ticker = new Timer();         Thread t = new Thread(ticker);         t.start();     } } class Timer implements Runnable {     long oneClock;     long twoClock;     int gameLength = 26; //+1 of required time (zeroth degree)     long diff;     long beforeTime;     long afterTime;     long realTime;     boolean loop = false;    public void run () {         beforeTime = System.nanoTime()/1000000000;         while (gameLength > 0){             oneClock = System.nanoTime()/1000000000;             loop = true;                         while (loop) {                 try {                 Thread.sleep(10); } catch (InterruptedException ex) {ex.printStackTrace(); }                 twoClock = System.nanoTime()/1000000000;                 diff = twoClock - oneClock;                 if (diff >= 1) {                 gameLength -= diff;                 System.out.println (this.gameLength) ;                 loop = false;                 } //second while close             }        } // 1st while close         afterTime = System.nanoTime()/1000000000;         realTime = afterTime - beforeTime;         System.out.println("The end of the clock");         System.out.println("The clock took" + realTime + "seconds to finish");     } }

the result is:

1   2   3   4   5   6   7   8   9   10   11   12   13   14   15   16   17   18   19   20   21   22   23   24   25   26   27   28   29   30

run: 25 24 23 22 21 20 19 18 17 16 15 14 13 12 11 10 9 8 7 6 5 4 3 2 1 0 The end of the clock The clock took26seconds to finish BUILD SUCCESSFUL (total time: 26 seconds)

if you can point out the obvious mistake I'll give you a virtual sticker, especially because it's not obvious to me

[Captain Awesome]

I have read your code and if I'm correct, every second gameLength is subtracted by one and then sent to System.out.println().
The gameLength has been outputted 26 times which means that is has taken 26 seconds to complete. Why isn't gameLength starting at 25 like it should?

[westloar]

changing the gamelength to 25 confusingly means the program runs for 24 seconds :|

Games published by our own members! Check 'em out!

[Captain Awesome]

Huh, that's kinda weird. I'll try to run the code and see what happens

[philfrei]

?!

One second is consumed before 25 is printed, yes?
And 1 second before 1 is printed (after 2), yes?

So, all the way from 25 to 1 is 25 seconds (one second per number). Then you spend another second progressing down to 0.

Classic "off by one" error?

[westloar]

after reading your posts I just wanted to double check that changing the gameLength didn't priduce the right results, it doesn't.

Changing it to 25 makes the clock run for 24 seconds.

Changing it to 26 makes it run for 26.

Can someone please tell me what's going on here!?

[Riven]

Rounding way too soon...
oneClock = System.nanoTime()/1000000000;
twoClock = System.nanoTime()/1000000000;

You should never round it, until you print and even then you might want to round to millis, not seconds.

[westloar]

surely it doesn't matter when I round it as the variable remains the same until the next iteration of the loop? So rounding it at the beggining or the end of the loop wouldn't make a difference?

[philfrei]

I ran your code with 25 and it takes 26.
I ran your code with 24 and it takes 25.

Copying the code to Eclipse was a little messy as it did not cut-and-paste into my system cleanly. I moved a few things around a bit but I think I did so accurately, didn't change the way the code functions. You can check my listing and output.

1   2   3   4   5   6   7   8   9   10   11   12   13   14   15   16   17   18   19   20   21   22   23   24   25   26   27   28   29   30   31   32   33   34   35   36   37   38   39   40   41   42   43   44   45   46   47   48   49   50   51   52

package westloar; public class Timer implements Runnable {     long oneClock;     long twoClock;     int gameLength = 25; //+1 of required time (zeroth degree)         long diff;         long beforeTime;         long afterTime;         long realTime;         boolean loop = false;         public static void main(String[] args)     {    Runnable ticker = new Timer();    Thread t = new Thread(ticker);    t.start();       }         public void run ()     {        beforeTime = System.nanoTime()/1000000000;        while (gameLength > 0)        {           oneClock = System.nanoTime()/1000000000;           loop = true;           while (loop)           {              try              {                 Thread.sleep(10);              }              catch (InterruptedException ex) {                 ex.printStackTrace();              }              twoClock = System.nanoTime()/1000000000;              diff = twoClock - oneClock;              if (diff >= 1)              {                 gameLength -= diff;                 System.out.println (this.gameLength) ;                 loop = false;              } //second while close                             } // 1st while close                }    afterTime = System.nanoTime()/1000000000;    realTime = afterTime - beforeTime;    System.out.println("The end of the clock");            System.out.println("The clock took" + realTime + "seconds to finish");         } }

24
23
22
21
20
19
18
17
16
15
14
13
12
11
10
9
8
7
6
5
4
3
2
1
0
The end of the clock
The clock took25seconds to finish

[philfrei]

I just wanted to add, (and the previous post was getting rather long) that if there is some sort of timing creep, I think it must be happening with the setting of the variable oneClock.

Potentially, each time you set it, it might have slipped as much as 10msec (timer increment) plus any residual time that the timer might consume. I've seen some places where a timer is set to X but the actual value comes out to X+4msec, give or take a little. Also, the time taken to execute the loop will be part of the slip.

So let's see, 25 x 15 msecs gives 375 msecs, yes? That's not quite enough for a full second's slippage, but maybe that is a good start in trying to find it. (Other comments about rounding & such may also be relevent.)

In any case, I think you should tie your timer tests to the first "beforeTime" rather than "oneClock". Thus, instead of "diff = twoClock - oneClock;" do this sort of thing:

1   2   3   4   5   6   7   8   9   10   11   12   13   14

int i; while (loop)     {         try         {             Thread.sleep(10);         }         catch (InterruptedException ex)         {             ex.printStackTrace();         }         twoClock = System.nanoTime()/1000000000;         diff = twoClock - ( beforeTime +  i++ );;         if (diff >= 1)

This way, if there is slippage, at least it won't "accumulate".
Hope that helps!

Games published by our own members! Check 'em out!

[philfrei]

Back again after testing my fix. 

For the code to work, the declaration of int i = 1; has to happen right with the setting of "beforeTime" and only be incremented as part of the outer while loop.

But the principle remains the same. Tie you testing to a single moment in time.

details...

[Roquen]

Rounding way too soon...

That's generous.  I'd call it tossing way most of the significant information. 

[westloar]

cheers Philfrei, that's really helpful and makes a lot of sense to compare it to a static point in time

Rounding way too soon...

That's generous.  I'd call it tossing way most of the significant information. 

losing information isn't a problem if you're not using it and in a larger application has memory advantages...

[westloar]

ok so using a static time to test with works, but setting gameLength to 25 still produces 26 secs whereas setting it to 24 actually produces 25 now

but still,doesn't work properly, I'm using netbeans IDE, any known problems with that?

[philfrei]

On you first output, you printed 25..0. That's 26 numbers. Each one took a second, because you print numbers after sleeping.

Classic "off by one" error. I have a special fondness for them. They always remind me of the wedding card we got from my father: "Happy 0th Anniversary!"

[loom_weaver]

cheers Philfrei, that's really helpful and makes a lot of sense to compare it to a static point in time

Rounding way too soon...

That's generous.  I'd call it tossing way most of the significant information.  

losing information isn't a problem if you're not using it and in a larger application has memory advantages...

Heh, but it does matter if you want your program to calculate correct results.  When it comes to numbers, precision, etc. Roquen may be terse but he knows his stuff.

To the original poster, don't do any of the dividing until you're ready to calculate your final result and definitely don't divide any values you intend to accumulate.

[Roquen]

I frequently make posts when I'm in a rush (heavy round-off error).  I hope that someone will read my mind and translate what I'm saying...and sometimes it works!  For those who wish to test their mind reading skills what I (and Riven) meant was:

Digitial clocks are (effectively) square waves.  Their associated counters track how many transistions (a stairstep function WRT time) that have occured (taking into account any overflow) since it was last reset.  So when you pretend that a given counter measures realtime, you have to remember that your result has an error bound of twice (+/-1) of the resolution.  By dividing first, you effectively divide the clock frequency, so if you divide down to one second resoultion, then the error WRT to realtime is +/- 1 second.  That's what I meant by:  "tossing way most of the significant information"  Using two of these as timestamps compounds the error of the two samples.

Example of the error range (using milliseconds for shortness)

1   2   3   4   5   6   7   8   9

int t0= 999;     int t1=1000;     int t2=1999;     int a0 = t0/1000;     int a1 = t1/1000;     int a2 = t2/1000;         System.out.printf("%d %d %d\n", a1, a1-a0, (t1-t0+500)/1000);     System.out.printf("%d %d %d\n", a2, a2-a1, (t2-t1+500)/1000);

Dividing early gives more importance to the exact values of the low bits that your throwing away.

[westloar]

sorry for the late reply Roquen, haven't been back to this site for a while, joys of being a father

thanks for that explanation, that makes a lot of sense and I wasn't aware of that so cheers

[cylab]

sorry for the late reply Roquen, haven't been back to this site for a while, joys of being a father

Have a good time! We celebrated the first birthday of my daughter yesterday.