GageTimer question

Tzan · February 5, 2005, 4:51pm

With all the talk of timing lately I took another look at mine and was trying to figure out why it was still a bit jittery. I’m not complaining, just wondering if this is normal behavior of the Gage timer.

I get fairly consistent results over many frames so here is whats happening:

I’m ping/ponging a box back and forth and when it gets to one location I print timing to System.out. This takes about 400 frames.

frame cap at 60 FPS
ticksPerFrame = 19866 t

normal frame render = 3000 t (max good frame render = 12000 t )
bad frames due to update/render = 0 out of 400

bad frames due to timer 12 out of 400 ( 3% )
normal max bad timer ticks = 31000 t (instead of 19866 t) this measures the worst timer error in 400 frames

So you can see that calls to Gage are doing the job just fine 97% of the time and occasionally blowing the timing. Adding an extra 50% onto the normal frame time.

So the question is, is this a normal error rate, or something wierd in my system.

win 98
PIII 700

jbanes · February 6, 2005, 2:35pm

I suppose that depends on what you mean by “bad frames due to timer?” Are you saying that 3% of the frames go over their expected render time? If so, how did you determine that it is the timer’s fault? Also, how can you tell that the System.out is not blocking and introducing the jitter you’re seeing? In short, I need more info about what you’re doing and why you’re pointing the finger at the timer.

FWIW, timing is a very difficult thing on non-realtime hardware. The less precise the timer is, the more accurate it can be. The more precise it is, then the more likely it will jitter all over the map. A lot of this has to do with the difficulty in producing an ultra-high speed clock, and the metastabiliy of various processor components. Of particular interest is that many super-precise clocks (e.g. multi-GHz) actually have to run on a slower clock. Each clock tick is then subdivided by the use of a capacitor. The capacitor is designed to charge/discharge is a period that approximates the desired clock frequency. It works pretty well, and is far cheaper than a faster crystal, but it’s also as inaccurate as they come. :-/

Another possibility is that the OS is occasionally not scheduling the game in a timely manner. This might happen if some other process of a higher priority decides it suddenly needs time. (Especially something in kernel space.)

Tzan · February 7, 2005, 3:41pm

I really hope I’m doing something wrong

I do the following in my game loop

update()
render()
Thread.yeild()

then I check the elapsed time and this results in 0 frames over time (most of the time)

Then I do the frame rate capping loop.
It doesnt matter how I do this. I have tried several methods.

I used the normal Gage way of using the sleep method you have that loops on a yeild
I wrote my own that loops on nothing, an empty while loop. (thats why there is a yeild just after the render)
The results were the same

After the timer loop I check the elapsed time again so I can see how long that took

I also count frames that are under time and over time as a result of rendering
and also as a result of timing.

I know the system.out can cause trouble here. So I only print to System.out once in 400 frames. I collect The max timer results and print them, I also print the current results for the frame, so after doing this for a while you can see what a typical frame vs max frame is doing


while(running)
    {

      lastTime = gageTimer.getClockTicks();
    
      timeModifier = 1;
      //allows for dynamically altering the FPSTarget
      ticksPerFrame=ticksPerSecond/(int)FPSTarget;

      while(!paused)
      {    
         update(timeModifier);
         render2();
        Thread.yield();
     
        elapsedTime = (gageTimer.getClockTicks() - lastTime);

        if (elapsedTime < ticksPerFrame)
        {
       
          //gageTimer.sleep(ticksPerFrame - elapsedTime);    //use this
  
          while(gageTimer.getClockTicks() < (lastTime +  ticksPerFrame) )  // or this
          {
            //do nothing
          }

          elapse2 =  gageTimer.getClockTicks()- lastTime;

          if (elapse2 > (ticksPerFrame * 1.1)) // frame is now more than 10% over time due to timer
          {
            elapseBegin = elapsedTime;        // this records the last overtime frame before printing
            elapseAfter = elapse2;                   // this records the last overtime frame before printing
            badCount1++;
          }
          else                                                     //frame is ok after timer
          {
              goodElapseBegin = elapsedTime;    // this records the last good frame before printing
              goodElapseAfter = elapse2;               // this records the last good frame before printing
          }

         underTime++;   //counts frames that should be undertime
        }
        else
        {
            overTime++;  //counts frames that are overtime due to update/render/yeild
        }

        time = gageTimer.getClockTicks();
     
        timeModifier = ((float)(time - lastTime)) / (float)ticksPerFrame;
        //timeModifier = 1;
        lastTime = time;

      }

      //Game PAUSED, Sleep to stop using CPU at 100%
      try
      {
        Thread.sleep(10);
      }
      catch (InterruptedException e)
      {}
    }

    gameLoopStopped=true;
  }

Portion of my render method


//This saves the highest timeModifier
      if (timeModifier > 1.1f)
      {
       
        if(timeModifier>maxAnimM)
        {
          maxAnimM = timeModifier;
        }

      }
     
//This records the highest elapsed time just after the timer of a bad frame caused by the timer
      if(elapse2>maxElapse2)
      {
                maxElapse2=elapse2;
        }
//this records the highest elapsed time on a good frame
      if(elapsedTime>maxElapsed)
      {
        maxElapsed = elapsedTime;
      }

       if (i > 400)     // I increment the x and y directions by i, so the box moves diagonal
      {
        forward = false;

        System.out.println("badCount1: "+badCount1+" | total frames: "+count+" | over: "+overTime+" | under: "+underTime+" | MaxAnim: "+maxAnimM);
       
        System.out.println("elapseBegin: "+elapseBegin+" | elapseAfter: "+elapseAfter+" | max Elapse2: "+maxElapse2);

        System.out.println("goodElapseBegin: "+goodElapseBegin+" | goodElapseAfter: "+goodElapseAfter+" | max elapsedTime: "+maxElapsed);

        System.out.println();

        count=0;
        badCount=0;
        badCount1=0;
        overTime =0;
        underTime=0;
        maxAnimM=0;
        maxElapsed=0;
        maxElapse2=0;

        elapseBegin = 0;
        elapseAfter =0;
        //loopCount = 0;
        loops =0;
        goodElapseBegin = 0;
        goodElapseAfter =0;
        //loopCount = 0;
        goodLoops =0;

      }
      if (i < 60)
      {
        forward = true;

      }

Output

Sometimes the badCount varies a bit, this run just happened to be elevens.
Sometimes the over variable is 1-3 when the yeild kicks in longer or the hard drive runs

The over variable (update/render/yeild) numbers increase when running Jbuilder or a browser. The numbers above are after a reboot with no programs running (other than the startup stuff).

The max elapse2, a bad frame from the timer is (mostly) consistantly between 31,000 - 37,000 ticks, regardless of other running programs.

Yields (just after render) due to other programs vary quite a bit.

I did go through my msconfig>startup last year and cleared out a few things and checked again this morning, but saw nothing bad in there. I did shut off many taskbar programs and even shut off my cable modem, but nothing changed.

I can also remark out all but one System.out call and it still reports the same error.

So I’ll just assume my machine is doing something odd, deep down inside

jbanes · February 8, 2005, 12:09pm

Well, the fact that the use of various sleep methods makes no difference tells me that the problem is probably not the timer. The data you’ve shown is interesting, but I can’t quite put my finger on what’s going on.

If I can make a suggestion, can you try profiling each area of the code? i.e. Figure out how much time elapses for the update, render, and sleep. If we can figure out exactly where the lost time is showing up, we might be able to find what’s going on.

Thanks,
Jerason

Tzan · February 8, 2005, 4:44pm

Apparently my ten line response was too long, I’ll try later.
I’m getting a forum error

Tzan · February 9, 2005, 1:45pm

[quote]Well, the fact that the use of various sleep methods makes no difference tells me that the problem is probably not the timer. The data you’ve shown is interesting, but I can’t quite put my finger on what’s going on.
[/quote]
The two sleep methods both use gage timer.
The first one uses the gage sleep() and timer and loops on a yield.
The second uses the gage timer but loops on nothing.

I already do this.

elapsedTime, elapseBegin and goodElapseBegin all record the update+render+(1) yeild.
Both good and bad frames update+render+(1) yield in 3200 ticks

maxElapsed records the largest elapsedTime on update+render+(1)yield this is usually 9000 -11000
its higher than 3100 when the yield kicks in.

Good Frames:
goodElapseAfter records the ticks after the timer works correctly and is about 19895. A frame is 19866. Its probably over because of the extra call to get the time.

Bad Frames:
elapseAfter records the last bad frame due to the timer pausing the thead too long ~ 31000 ticks
Or some system thing that effects the timer.

maxElapse2 records the largest of the elapseAfter stats 31000 -37000 ticks

If you meant you wanted to see an -Xprof I could do that.

jbanes · February 9, 2005, 2:14pm

[quote]The two sleep methods both use gage timer.
The first one uses the gage sleep() and timer and loops on a yield.
The second uses the gage timer but loops on nothing.
[/quote]
Exactly my point. You’re using the GAGETimer for timing in the second case, so it should be internally consistent when using the loop method. That would have pointed to a problem with GAGETimer sleeping. But without using the sleep() methods, it just becomes another variable you can check.

[quote]I already do this.
[/quote]
Ok, sorry. I guess I didn’t understand those variables. When I get the chance, I’ll have to run the tests on my machine to see if I can reproduce the behavior. I’m guessing it’s probably Windows failing to return to execution in a timely manner.

Tzan · February 9, 2005, 3:42pm

Ok, thanks for your time

Tzan · October 4, 2005, 3:30pm

I just got a new machine.

P4 2.8
2gig memory
geforce 6800
win XP home

The program runs just fine with GAGE now. So it must have been something wonky with the old machine.