Game Loop - Elements get faster the longer they exist

Question

In my game, I have multiple threads. One thread sends signals to the calculation-threads, after this thread receives signals, it also renders the game.

The main thread looks like this, which I adapted from some other game-loop I've seen:

while(isRunning) {
    long now = System.nanoTime();
    float elapsed = (now - mStartTime) / 1000000000f;
    mStartTime = now;


    try {
        Log.d("GameThread", "setElapsed = "+elapsed);
        mController.setElapsedTime(elapsed);

        // send signal to logic barrier to start logic-threads
        BaseThread.LogicBarrier.await(); // 1/4

        // logic done!
        BaseThread.AfterLogicBarrier.await(); // 1/4

        // render!
        Log.d("GameThread", "RENDERING! -> localTime="+localTime+", Options.TIMESTEP="+Options.TIMESTEP+", interpol = "+(Options.TIMESTEP / localTime));



        mController.render((localTime / Options.TIMESTEP));

    } catch (InterruptedException e) {
        e.printStackTrace();
    } catch (BrokenBarrierException e) {
        e.printStackTrace();
    }

    // sleep maybe
    diff = System.nanoTime() - mStartTime;
    mController.fireGameDataChange(GameDataListener.FPS, (int) 1000000000/diff);
    if (1000000000 * Options.TIMESTEP - (diff) > 1000000) {
        try {
            Thread.sleep(0, 999999);
        } catch (InterruptedException ex) {
        }
    }
}

The rendering function, for each ViewObject existing, looks like this:

mMatrix.reset();
mMatrix.setTranslate(view.getX() - view.getVelocityX()  * interpolation), view.getY() + view.getVelocityY)) * interpolation));
mMatrix.preScale((1.0f * view.getWidth() / mBitmap.getWidth()), (1.0f * view.getHeight() / mBitmap.getHeight()));
mMatrix.postRotate(view.getRotation(), view.getX() + view.getWidth()/2f, view.getY()  + view.getHeight()/2f);
mCanvas.drawBitmap(mBitmap, mMatrix, mBasicPaint);

This is what's happening in the logic-thread:

while(isRunning) {
    try {
        BaseThread.LogicBarrier.await(); // 3/4
        int numSubSteps = 0;
        if (Options.SKIP_TICKS != 0) {
            // fixed timestep with interpolation
            localTime += mController.getElapsedTime();
            Log.e("Environment", "localTime="+localTime+" >= "+Options.TIMESTEP+", from elapsed = "+mController.getElapsedTime());
            if (localTime >= Options.TIMESTEP) {
                //numSubSteps = (int) (localTime/Options.TIMESTEP);
                numSubSteps = (int) (localTime/Options.TIMESTEP);
                localTime -= numSubSteps * Options.TIMESTEP;
            }
        }
        Log.e("EnvironmentThread", "localTime="+localTime+", numSub="+numSubSteps);
        if (numSubSteps != 0) {
            // clamp the number of substeps, to prevent simulation grinding spiralling down to a halt
            int clampedSubSteps = (numSubSteps > Options.SKIP_TICKS) ? Options.SKIP_TICKS: numSubSteps;
            for (int i = 0; i < clampedSubSteps; i++) {
                // todo: update game logic -> in time step so no interpolation
                mController.refresh(1);
            }
        }
        BaseThread.AfterLogicBarrier.await(); // 3/4
    } catch (InterruptedException e) {
        e.printStackTrace();
    } catch (BrokenBarrierException e) {
        e.printStackTrace();
    }
}

The process of synchronizing threads etc. works just fine, if I limit the frames to 60, I get 60 refresh's per second and as many rendering as possible. But there is one problem, which I'm trying to solve since yesterday - without success.

View Objects are speeding up. They do not have an acceleration, they simple gain from the velocity. But the longer they exist, the faster they get. Does anyone have an idea why this is happening? The render-function should not be interfering with the view's position/speed at all, as it's only using the getter methods to get the bitmap, current position and speed.

So my thought was that this is due to the interpolation, which I would find kind of confusing, as it's not a recurring sinus-kind of speed increase, but instead increasing over the life-cycle of EACH view object.

Any help, any ideas, would be very appreciated.

Here's some LogCat output from both the logic- and main-thread showing the interpolation and at which timings everything is done:

08-29 17:09:57.603  26183-26207/com.example.pckg E/EnvironmentThread: localTime=0.017999122 >= 0.033333335, from elapsed = 0.017043
08-29 17:09:57.603  26183-26207/com.example.pckg E/EnvironmentThread: numSubSteps = 0.0
08-29 17:09:57.603  26183-26207/com.example.pckg E/EnvironmentThread: localTime=0.017999122, numSub=0
08-29 17:09:57.603  26183-26204/com.example.pckg D/GameThread: RENDERING! -> localTime=0.017999122, Options.TIMESTEP=0.033333335, interpol = 1.8519423
08-29 17:09:57.623  26183-26204/com.example.pckg D/GameThread: setElapsed = 0.017807
08-29 17:09:57.623  26183-26207/com.example.pckg E/EnvironmentThread: localTime=0.03580612 >= 0.033333335, from elapsed = 0.017807
08-29 17:09:57.623  26183-26207/com.example.pckg E/EnvironmentThread: numSubSteps = 0.0
08-29 17:09:57.623  26183-26207/com.example.pckg E/EnvironmentThread: localTime=0.0024727844, numSub=1
08-29 17:09:57.623  26183-26204/com.example.pckg D/GameThread: RENDERING! -> localTime=0.0024727844, Options.TIMESTEP=0.033333335, interpol = 13.480082
08-29 17:09:57.633  26183-26204/com.example.pckg D/GameThread: setElapsed = 0.013305
08-29 17:09:57.633  26183-26207/com.example.pckg E/EnvironmentThread: localTime=0.015777785 >= 0.033333335, from elapsed = 0.013305
08-29 17:09:57.633  26183-26207/com.example.pckg E/EnvironmentThread: numSubSteps = 0.0
08-29 17:09:57.633  26183-26207/com.example.pckg E/EnvironmentThread: localTime=0.015777785, numSub=0
08-29 17:09:57.633  26183-26204/com.example.pckg D/GameThread: RENDERING! -> localTime=0.015777785, Options.TIMESTEP=0.033333335, interpol = 2.1126752
08-29 17:09:57.653  26183-26204/com.example.pckg D/GameThread: setElapsed = 0.018212
08-29 17:09:57.653  26183-26207/com.example.pckg E/EnvironmentThread: localTime=0.033989787 >= 0.033333335, from elapsed = 0.018212
08-29 17:09:57.653  26183-26207/com.example.pckg E/EnvironmentThread: numSubSteps = 0.0
08-29 17:09:57.653  26183-26207/com.example.pckg E/EnvironmentThread: localTime=6.5645203E-4, numSub=1
08-29 17:09:57.653  26183-26204/com.example.pckg D/GameThread: RENDERING! -> localTime=6.5645203E-4, Options.TIMESTEP=0.033333335, interpol = 50.778023
08-29 17:09:57.673  26183-26204/com.example.pckg D/GameThread: setElapsed = 0.01754
08-29 17:09:57.673  26183-26207/com.example.pckg E/EnvironmentThread: localTime=0.018196452 >= 0.033333335, from elapsed = 0.01754
08-29 17:09:57.673  26183-26207/com.example.pckg E/EnvironmentThread: numSubSteps = 0.0
08-29 17:09:57.673  26183-26207/com.example.pckg E/EnvironmentThread: localTime=0.018196452, numSub=0
08-29 17:09:57.673  26183-26204/com.example.pckg D/GameThread: RENDERING! -> localTime=0.018196452, Options.TIMESTEP=0.033333335, interpol = 1.831859
08-29 17:09:57.683  26183-26204/com.example.pckg D/GameThread: setElapsed = 0.014516
08-29 17:09:57.683  26183-26207/com.example.pckg E/EnvironmentThread: localTime=0.032712452 >= 0.033333335, from elapsed = 0.014516
08-29 17:09:57.683  26183-26207/com.example.pckg E/EnvironmentThread: numSubSteps = 0.0
08-29 17:09:57.683  26183-26207/com.example.pckg E/EnvironmentThread: localTime=0.032712452, numSub=0
08-29 17:09:57.683  26183-26204/com.example.pckg D/GameThread: RENDERING! -> localTime=0.032712452, Options.TIMESTEP=0.033333335, interpol = 1.01898
08-29 17:09:57.703  26183-26204/com.example.pckg D/GameThread: setElapsed = 0.017108
08-29 17:09:57.703  26183-26207/com.example.pckg E/EnvironmentThread: localTime=0.049820453 >= 0.033333335, from elapsed = 0.017108
08-29 17:09:57.703  26183-26207/com.example.pckg E/EnvironmentThread: numSubSteps = 0.0
08-29 17:09:57.703  26183-26207/com.example.pckg E/EnvironmentThread: localTime=0.016487118, numSub=1

Unfortunately my brain is lagging right now and I do not understand what I'm doing wrong at this point.

EDIT:

Thanks for pushing my brain. Found the mistake after adding even more debug statements. No math error, no thread mis-synchronization, but instead a simple "List.clear()" was missing in the logic part (refresh() method), which resulted in the list never being cleared, resulting in the same object being moved more often with each calculation frame - which I didn't even post here as I did not expect the error to be there.

Thank you anyways.

Answer 1

Maybe that's the Just-In-Time compiler??? It makes methods faster by compiling them to native code. But this happens not before many invocations of the same method.

-> Turn the JIT-Compiler off and check the behaviour. Using Oracle's Java SE this can be done by adding the parameter -Djava.compiler=NONE

Have a look at http://artiomg.blogspot.de/2011/10/just-in-time-compiler-jit-in-hotspot.html

Answer 2

Have written more game loops than you can shake a stick at, I think you're going about it all wrong.

You need two loops. One loops is your game loop. This steps forward the game state by one iteration. Things move, things die, things collide, things change direction, etc.

The second loop is your render loop. This just takes the game state and spits out an image of it.

If you turn the render loop off, the screen goes black, but the game still progresses in the game loop.

If you turn the game loop off, the screen doesn't change until you turn the game loop back on because it continues to render the same (unchanged) state.

Right now, it looks like you don't actually have a game loop. You have a render loop that attempts to simulate the game loop a little bit at a time, and Admiral Ackbar has a thing or two (actually just one) to say about that.

So make a proper game loop that is entirely independent of your render loop and this problem (and a dozen others) will go away. It will also be much easier to add new features in general.

Answer 3

I recommend you take a look at the LWJGL. Minecraft is based on that and it can shed some light in some topics for you.

The usual "Game Loop" per se involves a list of steps, mainly consisting in:

1. Initialize: First setup.
2. Load: Load the game content to use
3. Update: I think this is what you call your game logic. Here, elements are updated (movement, collisions and alike).
4. Draw: (render)
5. If you're not done GoTo 3
6. Unload: Free the memory you consumed by allocating diverse resources (textures, spritesheets, sound effects or bgms, for example).

As you do it now, you have two threads one to render and the other to update. If the update thread is going nuts, then your game will render nonsensical stuff like, for example, accelerated sprites.

Taking some existing frameworks as an example (say, the soon-to-be-deprecated XNA Game Studio, its successor-in-spirit MonoGame or PSM), they handle the Game Loop at a macro level, having components (a Level, for example) that execute the very same steps included of the loop.

With this said, the loop itself is "executed on" every element (in particular Update and Render), infusing the Game Loop upon a Level object.