Java MultiThreading output seemingly ambiguous on thread-safe System.out

Question

Here is my code:

class Question extends Thread    {
    static String info;

    public Question(String info )    {
        this.info = info;
    }
    private void inProtected () {
        synchronized ( info )       {
            System.out.println("--> " + info +  " Hi");
            System.out.println("<-- " + info +  " Hi");
        }
    }

    public void run () {
        inProtected();
    }
    public static void main (String args []) {
        new Question("a").start();
        try {
            sleep(1);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        new Question("ab").start();

    }
}

This code produces sometimes, an output like this:

--> ab Hi
--> a Hi //Wait a second, what? How can "a" print after "ab"?
<-- ab Hi
<-- ab Hi

I've looked at the code of System.out and several answers on StackOverflow and I know for a fact that System.out is thread safe. Then, how is this execution order possible, given info is static, and the main thread creates the two threads (with "a" and "ab") in order?

Edit: I am perfectly aware that the method inProtected is not synchronized since the value is changed by the different threads. My question is, how is it possible that "a" prints after "ab", since the main thread creates the threads in order, which consequently modify the static variable info?

`System.out` may be thread safe, but there is nothing in your code that would synchronize multiple calls _to_ `System.out`. — Marvin, Oct 31 '18 at 16:10
Yes, "thread safe" does not mean sequential. Threads run asynchronously, so the output could really occur in any order. — markspace, Oct 31 '18 at 16:10
You are replacing your string, which is static, on each `new Question`.. but are locking on it. You have different entities locked. — Dragonthoughts, Oct 31 '18 at 16:11

Illyes Istvan · Accepted Answer · 2018-10-31T17:58:33.183

2

This is what happens in you example:

Main thread:

create first thread: info = "a" (1)
start Thread1 (2)
sleep 1 millisecond (3)
create second thread: info = "ab" (4)
start Thread2 (5)

Thread1:

prints first line: "a" (7) -> even though info was already changed to "ab" by Main thread, it is not yet visible to Thread1
prints second line: "ab" (8)

Thread2:

prints first line: "ab" (6)
prints second line: "ab" (9)

Observations

Calling sleep does not offer any contract that Thread1 will start execution before Thread2. It is up to the thread scheduler of the OperatingSystem to decide which thread will start execution first and there is no deterministic ordering between them in this case.
Thread1 can read a stale value from info, since there is no happens before relation on memory actions for this field.

Volatile

To avoid seeing a stale value of the info field, one could declare it as volatile. This will ensure that a write to this field 'happens before; any subsequent read.

More about happens before relations and memory visibility here: Memory Consistency Properties

edited Oct 31 '18 at 17:58

answered Oct 31 '18 at 16:12

Illyes Istvan

569
7
19

4

More importantly, since the lock object is `static`, the OP replaces the lock half way through and the lock object is lost entirely. It's almost always a good idea to declare any locks as `final` just to make sure this doesn't happen on accident. – markspace Oct 31 '18 at 16:19
@markspace You are correct. However, it depends on what the OP is trying to achieve here: 1. mutual exclusion for isProtected across different instances of Question or 2. mutual exclusion for isProtected inside the same instance of Question. Looking at his example, I think it's the first. – Illyes Istvan Oct 31 '18 at 16:23
This does not answer my question. I am aware that the method inProtected is not synchronized. My question is, how is it possible that "a" prints after "ab", since the main thread creates the threads in order, which consequently modify the static variable info. – a3y3 Oct 31 '18 at 16:27
@a3y3 see the sequence of events on my answer – Illyes Istvan Oct 31 '18 at 16:34
Thanks @IllyesIstvan, but according to your order, when Thread 1 prints first line (3), it will print "a", not "ab", because second Thread hasn't yet been started. – a3y3 Oct 31 '18 at 16:35
1

@a3y3 You are right. Will update the answer. Thread2 executing first is also a valid scenario in this case, because there is no assurance that Thread1 will start before the sleep is executed. However, this is rare. – Illyes Istvan Oct 31 '18 at 16:38
"... even though info was changed to "ab", it is not yet visible to Thread1" Why can this happen? Is it because the earlier value is cached somewhere? – a3y3 Oct 31 '18 at 16:55
1

You can think of it as "caching" but more fundamentally the Java language spec does not guarantee visibility unless you synchronize somehow. Since the field `info` itself is not synchronized, threads will not see updated values. (They'll see changes made before calls to `Thread.start()` because `.start()` does guarantee visibility.) – markspace Oct 31 '18 at 17:12
@markspace sounds great. If you could please add this as an answer with a link to thread visibilities, I will mark your answer as accepted :) – a3y3 Oct 31 '18 at 17:23
1

@aey3 more about memory visibility here: https://docs.oracle.com/javase/6/docs/api/java/util/concurrent/package-summary.html#MemoryVisibility – Illyes Istvan Oct 31 '18 at 17:30

Oleksandr Pyrohov · Answer 2 · 2018-11-01T10:03:59.967

The System.out.print in the synchronized block isn't protected by the same lock ("a" and "ab" are different String objects), therefore inProtected isn't actually protected.

Also, the order in which the threads are executed is determined by the operating system. There are no guarantees that new Question("a") will be started before new Question("ab").

Update:

The weird thing is, I can't replicate the behavior if I remove the sleep in the main method.

the presence of the try { sleep(1) } gives the first thread a possibility to start and read/cache the string "a" prior to the execution of the new Question("ab"), where the value changes to "ab".

By the way, you can replace:

try { sleep(1); } catch (Exception e) { }

with something like:

for (int i = 0; i < 1_000_000; i++);

and you will get a similar behavior as with sleep.

Java MultiThreading output seemingly ambiguous on thread-safe System.out

2 Answers2