Multiple threads showing excepted value when System.out.println is presented in critical section

Question

I have following codes:

public class MyApp {
    public static void main(String[] args) throws InterruptedException {
        SharedResource sharedResource = new SharedResource();

        Runnable first = () -> {
            sharedResource.increment(10000);
        };

        Runnable second = () -> {
            sharedResource.increment(10000);
        };

        Thread thread = new Thread(first, "FirstThread");
        Thread thread2 = new Thread(second, "SecondThread");
        thread.start();
        thread2.start();
        thread.join();
        thread2.join();
        System.out.println("The value of counter is " + sharedResource.getCounter());
    }
}

Using this class:

public class SharedResource {
    private int counter;

    public void increment(int times) {
        for (int x=1; x<=times;x++) {
            counter++;
            // System.out.println(counter);
        }
    }

    public void decrement() {
        counter--;
    }

    public int getCounter() {
        return counter;
    }
}

I am curious why this happens all the time.

When System.out.println() is removed from the increment method, the total value of

System.out.println("The value of counter is " + sharedResource.getCounter());

is random - which is excepted because multiple threads are sharing the same counter.

However, when System.out.println(counter); is presented on the increment method, the code no longer seems to have the multi-threading issue.

The final result of counter is always 20,000 which is excepted as the code is lopping 10,000 times from each thread. Can anybody explain me why is this happening?

See also https://stackoverflow.com/questions/25425130/loop-doesnt-see-value-changed-by-other-thread-without-a-print-statement — Raedwald, Jan 10 '19 at 12:13

score 5 · Answer 1 · answered Jul 23 '17 at 17:54

It's due to very small race window.

Default system output is PrintStream which is thread safe:

public void println(int x) {
    synchronized (this) {
        print(x);
        newLine();
    }
}

So basically thread does the following:

Increments counter (~tens of ns)
Waits for previous thread to release the lock, acquires it and prints to console (~millisecond which is 1000 times slower)
Go to 1

When you have critical section which is 1000 times longer than non-critical one, your threads are basically serialized on it and probability of counter updates overlap becomes very small, there is nothing special in system out.

Ways to prove:

You can write not thread-safe implementation of PrintStream:

public class NullPrintStream extends PrintStream {
  public NullPrintStream() {
      // Utility constant from apache-commons
      super(NullOutputStream.NULL_OUTPUT_STREAM);
  }

  @Override
  public void println(int x) {
     // No synchronization here
  }
}

And then set it as system out via System.setOut(new NullPrintStream()) and result will start flapping again.

To provide larger race window in the beginning you can synchronize your runnables on latch so they start almost simultaneously:

CountDownLatch latch = new CountDownLatch(1);
Runnable first = () -> {
  try {
    latch.await();
    sharedResource.increment(10000);
  }
  catch (Exception e) {
  }
};
// ... start your threads here
latch.countDown();

Then if you run this sample couple of times you will see something like (note that I'm printing it to System.err because I've overridden System.out)

The value of counter is 20000

The value of counter is 19996

The value of counter is 19994

The value of counter is 19999

The value of counter is 20000

Multiple threads showing excepted value when System.out.println is presented in critical section

1 Answers1