Why is this print statement changing how this loop executes?

Question

This is the run method from my game loop thread (a modified version of another SO answer). The running boolean is basically there as a way to pause and unpause the game, and it works just fine normally. I tried to add a constructor that lets the game start out as paused, or running == false and it didn't work. The game would never start, despite successfully setting running to true. I added some print statements to figure out what was going on. Then a weird thing happened. The addition of the print statement fixed the problem.

private void reset() {
    initialTime = System.nanoTime();
    deltaU = 0; deltaF = 0;
    frames = 0; ticks = 0;
    timer = System.currentTimeMillis();
}
public void run() {
    Thread.currentThread().setPriority(Thread.MAX_PRIORITY);

    reset();
    boolean wasRunning=false;
    while (true) {
        System.out.println("in loop");
        if (running) {
            System.out.println("running");
            if(!wasRunning){
                wasRunning=true;
                reset();
            }
            long currentTime = System.nanoTime();
            deltaU += (currentTime - initialTime) / timeU;
            deltaF += (currentTime - initialTime) / timeF;
            initialTime = currentTime;

            if (deltaU >= 1) {
                update();
                ticks++;
                deltaU--;
            }

            if (deltaF >= 1) {
                render();
                frames++;
                deltaF--;
            }

            if (System.currentTimeMillis() - timer > 1000) { //prints warning if dropped frames
                if (printTime) {
                    System.out.println(String.format("UPS: %s, FPS: %s", ticks, frames));
                }
                if(ticks!=60 || frames!=60)
                    System.out.println(String.format("UPS: %s, FPS: %s", ticks, frames));
                frames = 0;
                ticks = 0;
                timer += 1000;
            }
        }
        else
            wasRunning=false;
    }
}

the output is

in loop
running
in loop
running
in loop
running...

And the game runs with a lot of studder (though the fps warning is oddly silent). when I comment out the System.out.println("in loop"), there is no output, and setting running to true does nothing.

So the fact that there is a print statement is actually causing the loop to execute, but omitting it causes it to fail.

Note that if running is set to true at first, the print statements are removed, the pause and unpause functionality works as expected.

I also tried renaming running to running2 just to make sure it wasn't overriding anything.

@KevinDiTraglia No, thats legal in java. I added them just now for readability, but if there's only one line in the statement they aren't required. — user3236716, May 05 '15 at 17:54
The slowness introduced by System.out.println might be giving your variables enough time to set to appropriate value? (Just a thought) — Farhan Syed, May 05 '15 at 17:55
This isn't the entire class, just the part I thought was relevant. It's an instance variable that is set in the constructor. I have setters and getters for it. — user3236716, May 05 '15 at 17:58
You said "setting running to true causes it...", which implies you have control over its value in some other thread. Is `running` marked `volatile`? — Ryan J, May 05 '15 at 17:59
This is a very bad way to implement a pause. If you want to go into a pause, you should put the thread to sleep or some other kind of wait which will not waste CPU cycles on an empty `while` loop. — RealSkeptic, May 05 '15 at 18:00
This is true, however it was the first thing I thought of and it worked. Since its just a stupid little game that is never meant to be running in the background it's not a big deal, but I will make that change. Thanks for the idea. — user3236716, May 05 '15 at 18:08
Just an FYI on Thread.sleep(): you are not guaranteed that the sleep time will be exactly what you request. That's something that is a bit of a gotcha for somebody using it for the first time. — pens-fan-69, May 05 '15 at 18:10

Peter · Accepted Answer · 2015-05-05T18:17:10.557

tl;dr: You should try marking running as volatile.

I assume that running is set from another thread? If that's the case, if running is initially false and is only set to true by another thread, then it's likely a race-condition.

The addition of the println() call before the if statement adds enough time for the other thread to modify running to true before it's checked. Removing the println() call causes running to be checked before the other thread can set it to true.

If this is the case, you really should restructure your code to avoid this race condition. Not being able to see it all, it's hard to make a recommendation as to how you'd approach this.

EDIT: After reading the comment below, it appears like the infinite while loop would "catch" the change to running, however this may not be the case if running was not marked as volatile.

volatile has defined semantics in Java, and one of them is that the variable is never thread-locally cached, i.e. accesses to a volatile variable always go to main memory and will always reflect the current state, even if updated by other threads.

See here for more information on the volatile keyword.

EDIT: Added tl;dr.

EDIT: Quick/layman's explanation of volatile: The JVM can be pretty hard-core in the number of optimizations it makes for efficiency.

For a non-volatile field access in a method, the JVM may make assumptions that no other threads are accessing it; in doing so, it may make a thread-local copy of that field so it can modify it without having to deal with the contention of accessing "main memory". This increases performance but has the drawback we've seen: If another thread modifies running, the current thread won't see it, because it's using a copy that's local/contextual to just itself.

Marking the field as volatile fixes it because the semantics of the volatile under the current Java Memory Model basically ensure that all reads/writes of volatile fields go back to "main memory", establishing a happens-before relationship.

So why not just mark everything as volatile? Or for that matter, why isn't everything implicitly volatile instead of the other way around? The answer is performance: A volatile access is generally going to be a lot slower than a non-volatile access, so the Java language designers have decided to make its usage optional, only when you know you need the safety. (Same goes for synchronized accesses)

That shouldn't be a problem because it's in an infinite while loop and it will catch the change on the next loop. — pens-fan-69, May 05 '15 at 17:59
This likely depends on whether `running` was marked as volatile. I'll update my post, thanks for the catch. — Peter, May 05 '15 at 18:00
Exactly. Running is passed into the constructor (there are multiple constructors, but I am referring to the one where running is passed as an argument) which sets the instance variable as the value passed in. I don't really see where a race condition could occur, because the while loop should constantly be running and check every time. — user3236716, May 05 '15 at 18:02
setting it to volatile fixed it. As you can probably tell, I am a bit of a noob and honestly I have never used it before. Thanks! — user3236716, May 05 '15 at 18:05

Why is this print statement changing how this loop executes?

1 Answers1