synchronized keyword is giving the expected output but not satisfied with the order in which the method is called by different threads

Question

Below are my 3 classes(threads) implementing Runnable interface:

public class Thread1 implements Runnable {
Shared s;

public Thread1(Shared s){
    this.s = s;
}

@Override   
public void run() {
    System.out.println("Sum of 10 and 20 by " + Thread.currentThread().getName() + " is "+ s.add(10, 20));
}

}

public class Thread2 implements Runnable {
Shared s;

public Thread2(Shared s){
    this.s = s;
}
    
@Override
public void run() {
    System.out.println("Sum of 100 and 200 by " + Thread.currentThread().getName() + " is " + s.add(100, 200));
}

}

public class Thread3 implements Runnable {
Shared s;

public Thread3(Shared s){
    this.s = s;
}
    
@Override
public void run() {
    System.out.println("Sum of 1000 and 2000 by " + Thread.currentThread().getName() + " is " + s.add(1000, 2000));
}

}

And below is the class whose object is shared among these threads:

public class Shared {
private int x;
private int y;

synchronized public int add(int a, int b) {
    x = a;
    y = b;

    try {
        System.out.println(Thread.currentThread().getName() + "is going into sleep state");
        Thread.sleep(1000);
    } catch (InterruptedException e) {
        e.printStackTrace();
    }
    return x + y;
}

}

And finally this is how I'm starting threads and passing Shared object:

    public static void main(String[] args) {
    Shared s = new Shared();
    Thread t1 = new Thread(new Thread1(s), "Thread-1");
    Thread t2 = new Thread(new Thread2(s), "Thread-2");
    Thread t3 = new Thread(new Thread3(s), "Thread-3");
    
    t1.start();
    t2.start();
    t3.start();
}

This is the output I'm getting which is correct:

      Thread-2is going into sleep state
      Thread-1is going into sleep state
      Sum of 100 and 200 by Thread-2 is 300
      Thread-3is going into sleep state
      Sum of 10 and 20 by Thread-1 is 30
      Sum of 1000 and 2000 by Thread-3 is 3000

But if you see here, Thread-1 started executing the add method(which is synchronized) before Thread-2 finished its job. Since Thread-2 went into sleep state so it also took the lock with itself and no other thread should be allowed to enter the add(...) method. Thread-1 or Thread-3 could only start executing add(...) method after Thread-2 is done. So, the output I was expecting was :

      Thread-2is going into sleep state
      Sum of 100 and 200 by Thread-2 is 300
      Thread-1is going into sleep state
      Sum of 10 and 20 by Thread-1 is 30
      Thread-3is going into sleep state
      Sum of 1000 and 2000 by Thread-3 is 3000

Please tell what I'm doing wrong or this is how the output will be, if yes, please tell why.

Answer 1

You need to synchronize s as shown below:

@Override
public void run() {
    synchronized (s) {
        System.out.println("Sum of 10 and 20 by " + Thread.currentThread().getName() + " is " + s.add(10, 20));
    }
}

Do this in the classes, Thread2 and Thread3 as well. Check this for an explanation.

Answer 2

The reason is that the System.out.println() is very slow.

You use it to send messages from both within the run() methods and also from within add(). There is no guarantee that the messages in sysout coincide.

I have rewritten Shared as follows:

public class Shared {
    private int x;
    private int y;

    synchronized public int add(int a, int b) {
        x = a;
        y = b;

        try {
            long now = System.currentTimeMillis() - start;

            Thread.sleep(1000);

            // notice FIRST sleep and THEN sysout
            System.out.println(Thread.currentThread().getName() + " calculation has taken place at time " + now);

        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        return x + y;
    }

    public static long start;

    public static void main(String[] args) {

        start = System.currentTimeMillis();

        Shared s = new Shared();
        Thread t1 = new Thread(new Thread1(s), "Thread-1");
        Thread t2 = new Thread(new Thread2(s), "Thread-2");
        Thread t3 = new Thread(new Thread3(s), "Thread-3");

        t1.start();
        t2.start();
        t3.start();
    }
}

with each of the threads now looking like:

public class Thread1 implements Runnable {
    Shared s;

    public Thread1(Shared s) {
        this.s = s;
    }

    @Override
    public void run() {
        int result = s.add(10, 20);
        long now= System.currentTimeMillis()-Shared.start;
        System.out.println("Sum of 10 and 20 by " + Thread.currentThread().getName() + " is " + result+ " found at "+ now);
    }
}

generating the following output:

Thread-1 calculation has taken place at time 2
Sum of 10 and 20 by Thread-1 is 30 found at 1005
Thread-2 calculation has taken place at time 1005
Sum of 100 and 200 by Thread-2 is 300 found at 2006
Thread-3 calculation has taken place at time 2006
Sum of 1000 and 2000 by Thread-3 is 3000 found at 3007

each thread blocked in add() as it should.

Only when later the result is displayed, the next thread has already started calculating.

Notice that add() now there is first the sysout (which is slow) and it happens during the sleep, which gives it enough time.