Understanding of coordination for Java volatile fields' reads & writes across threads

Question

I have the following code:

 private volatile boolean run = true;

 private Object lock =new Object();

.........

Thread newThread = new Thread(new Runnable() {

    @Override
        public void run() {
        try {
            Thread.sleep(2000);
        } catch (InterruptedException e) {

            e.printStackTrace();
        }
            synchronized (lock) {
                System.out.println(Thread.currentThread().getName()
                        + " run:" + run);

                System.out.println(Thread.currentThread().getName()
                        + " setting run to false");

                run = false;

                System.out.println(Thread.currentThread().getName()
                        + " run:" + run);
            }
        }});

newThread.start();

while(true) {//no synchronization, so no coordination guarantee
    System.out.println(Thread.currentThread().getName() + "* run: "+run);

    if(run == false) {
    System.out.println(Thread.currentThread().getName() + "** run: "+run+"\nExiting...");
    System.exit(0);
    }
}




which generates the following output:



main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
Thread-0 setting run to false
Thread-0 run:false
main* run: true    <- what causes this???
main** run: false
Exiting...

I'm trying to understand why in the main thread the aberration of main* run: true is occurring considering run is a volatile field and according to Java Memory Model spec, the volatile write in Thread-0 should be visible by the mainthread instantaneously. I'm aware that synchronization in the Thread-0 is extraneous here, but am confused about this behavior of a volatile. What am I missing here?

Another, even weirder run produced this:

main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main** run: false
Exiting...
Thread-0 run:false

Or is this behavior to be expected and if so, why? Thanks.

Edit: As asked in the comments, I'm updating the post with the expected output which I'm seeing sometimes but not all of the time:

main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
main* run: true
Thread-0 setting run to false
main* run: true
main* run: true
main* run: true
Thread-0 run:false
main** run: false
Exiting...

In other words, I don't want to see:

main* run: true 

to appear after

Thread-0 run:false

or

main** run: false
Exiting...

to appear before

Thread-0 run:false

Answer 1

If you just look at the reads and writes of the volatile variable, then they have to appear in the order:

1 - main: read run (run is true)
2 - Thread-0: write run (run is false)
3 - main: read run (run is false)

But the console outputs are separate actions that don't need to occur immediately after the read. The evaluation of the parameters to println and calling the method is not atomic. So we have something more like:

1 - main: read run (run is true)
2 - main: println("Run: true")

3 - Thread-0: write run (run is false)
4 - Thread-0: println("Run: false")

5 - main: read run (run is false)
6 - main: println("Run: false")

This allows an ordering which follows the first ordering like:

1 - main: read run (run is true)

3 - Thread-0: write run (run is false)
4 - Thread-0: println("Run: false")

2 - main: println("Run: true")

5 - main: read run (run is false)
6 - main: println("Run: false")

Based on the source code in PrintWriter, the line:

System.out.println(Thread.currentThread().getName() + " run:" + run);

could be inlined something like:

String x = Thread.currentThread().getName() + " run:" + run;
synchronized(System.out.lock) {
    System.out.print(x);
    System.out.println();
}

so there is synchronization within println but it doesn't include the read of run. This means that the value of run can change between it being read and it being output, resulting in the old value of run being output.

To get the output you're expecting, then the synchronized block would need to include the setting of run and the println statements together. And the reading of run and the println statements on the other thread would need to be in another synchronized block on the same lock.