Calling a synchronized from inside a non-synchronized method

Question

I'm experimenting with Threads and it's not working as expected, despite the fact I've applied Synchronization.

I have a method

private synchronized void printStatus(){
        System.out.println("\t\t\t" + Thread.currentThread().getName());
        System.out.println("\t\t\tCookies: " + contents);
}

and so I'm expecting, that when ever called, in the output I will get one line after another. But that is not what happens. My output looks like this:

            homerThread
            Cookies: 0
            margeThread
0 cookies were Removed
            Cookies: 0
            homerThread
3 cookies were Put
            Cookies: 3
0 cookies were Removed
            margeThread
            Cookies: 3
3 cookies were Put
            homerThread
            Cookies: 6
4 cookies were Removed
            margeThread
            Cookies: 2
1 cookies were Put
            homerThread
            Cookies: 3
3 cookies were Removed
                margeThread
                Cookies: 0
....

As you can see, there are a lot of lines that are not synchronized properly

Why is this happening?

---

I've included my entire code below for completeness;

Main.java class

public class Main {
    public static void main(String[] args) { 

        CookieJar jar = new CookieJar(); 

        Homer homer = new Homer(jar); 
        Marge marge = new Marge(jar); 

        Thread homerThread = new Thread(homer);
        homerThread.setName("homerThread");
        Thread margeThread = new Thread(marge);
        margeThread.setName("margeThread");

        homerThread.start();
        margeThread.start();
    } 

}

Homer.java

import java.util.Random;

public class Homer implements Runnable {

    CookieJar jar; 

    public Homer(CookieJar jar) { 
        this.jar = jar; 
    } 
    public void eat(int amnt) { 
        jar.getCookie(amnt); 
    } 
    public void run() { 
        Random random = new Random();
        for(int i = 0; i < 10; i++){
            eat(random.nextInt(5));
        } 
    } 
}

Marge

import java.util.Random;

public class Marge implements Runnable {
    CookieJar jar; 
    public Marge(CookieJar jar) { 
        this.jar = jar; 
    } 
    public void bake(int cookie) { 
        jar.putCookie(cookie); 
    } 
    public void run() { 
        Random random = new Random();
        for(int i = 0; i < 10; i++){
            bake(random.nextInt(5));
        }
    } 


}

CookieJar.java

public class CookieJar {
    int contents = 0; 
    boolean hasCookie = false; 

    public void putCookie(int amount) {  
        printStatus();
        contents += amount;
        System.out.println(amount + " cookies were Put");
    } 

    public void getCookie(int amount) { 
        printStatus();
        contents -= amount;
        System.out.println(amount + " cookies were Removed");
    }

    private synchronized void printStatus(){
        System.out.println("\t\t\t" + Thread.currentThread().getName());
        System.out.println("\t\t\tCookies: " + contents);
    }
}

*Note: Yes I realize that Homer might end up eating negative amount of cookies, which may or may not be possible.

Answer 1

OK, here's what synchronized does: It prevents two or more threads from synchronizing on the same object at the same time. It does not do anything else. It does not prevent two threads from entering the same synchronized method at the same time (the threads could be calling the same method on different instances). Synchronizing on an object does not prevent other threads from modifying that object. (The other threads might be in un-synchronized methods).

If you want to prevent other threads from printing messages between the two lines that printStatus() prints, then it is not enough to only synchronize printStatus(). You must synchronize every thread that can use System.out. Here's how I would do it:

private void printStatus() {
    synchronized (System.out) {
        System.out.println("\t\t\t" + Thread.currentThread().getName());
        System.out.println("\t\t\tCookies: " + contents);
    }
}

public void putCookie(int amount) {  
    printStatus();
    contents += amount;
    synchronized (System.out) {
        System.out.println(amount + " cookies were Put");
    }
}

...

I am synchronizing on System.out here to illustrate a point. System.out is the thing that I want to protect It does not matter what other threads and what other synchronization objects I have in my program, if every method that tries to write to System.out does so from inside synchronized (System.out), then the outputs will all be correctly interleaved.

---

Extra Credit:

In production code, I would have done this instead:

private static Object consoleLock = new Object();

...
    synchronized (consoleLock) {
        System.out.println(...);
        ...
    }
...

It will have the same effect as synchronizing on System.out as long as I consistently use consoleLock everywhere, but it has the advantage that the lock variable is private. That way, I know that no other programmer is going to be synchronizing on my lock for some other reason. (They'd have to be pretty crazy to synchronize on System.out for any other reason, but then there are some crazy developers out there.)

Also note: I made consoleLock static because System.out is static. There is only one System.out, so it's important that I have only one lock object.

Answer 2

You should also synchronize your getCookie and putCookie methods, otherwise they will interleave with the printStatus method.

Answer 3

The problem is that these lines:

System.out.println(amount + " cookies were Put");

System.out.println(amount + " cookies were Removed");

Are not synchronized on jar. If you look at only the xThread and Cookies: N output, which are synchronized, those are always properly ordered.