is System.out.printf() statement asynchronous?

Question

I am printing information to test Threads using Reentrant locks. I am creating fair locks using statement new ReentrantLock(true).

In one of the object method where I am using lock, I am using method e.g.

method() {
    for (int n = 0; n < 3; n++) {
       System.out.printf("%s: processing data \n",
            Thread.currentThread().getName(), data.get());
       TimeUnit.SECONDS.sleep(1);
    }
}

I am creating 10 threads and all threads should executing same statement 3 times where this console print statement is executed. however, I am not getting output where I see every thread showing the print in same sequence. e.g.

Thread 1: processing data hjjjj
Thread 2: processing data ghhjj
Thread 3: processing  data uiyiii
Thread 2: processing data ghfrtu
......
......

whereas I was expecting as below:

Thread 1: processing data hjjjj
Thread 2: processing data ghhjj
Thread 3: processing  data uiyiii
Thread 1: processing data uiyuii

is it because fairness is at play but system.out.println is not printing in same sequence as sequence of print commands issued?

Here are my classes..

public class PriceInfo {
    private double price1 =1d, price2=2d;
    ReadWriteLock lock = new ReentrantReadWriteLock(true);

    public double getPrice1() {
        lock.readLock().lock();
        try{
            return price1;
        }finally{
            lock.readLock().unlock();
        }
    }

    public double getPrice2() {
        lock.readLock().lock();
        try{
            return price2;
        }finally{
            lock.readLock().unlock();
        }
    }

    public void getPrices() {
        lock.readLock().lock();
        try{
            synchronized (System.out) {
                System.out.printf("%s: price1 = %f and price2 = %f \n",        Thread.currentThread().getName(), price1, price2);
                System.out.flush();
            }
        }finally{
            lock.readLock().unlock();
        }
    }

    public void setPrices(double p1, double p2) {
        lock.writeLock().lock();
        try{
            System.out.println(Thread.currentThread().getName() + ": starting to set new prices ");
            price1 = p1;
            price2 = p2;
            System.out.println(Thread.currentThread().getName() + ": prices changed to price1:"+ p1 + "price2: "+ p2);
        }finally{
            lock.writeLock().unlock();
        }
    }
}

Now there is another class..

public class Reader implements Runnable {

    private PriceInfo info;
    public Reader(PriceInfo inf) {
        info = inf;
    }
    @Override
    public void run() {
        for (int i=0; i<2; i++) {
            info.getPrices();
        }
     }
}

And finally, we have writer thread and main class..

public class Writer implements Runnable{

    private PriceInfo info;
    public Writer(PriceInfo inf) {
        info = inf;
    }
    @Override
    public void run() {
        for (int i=0; i<2; i++) {
                info.setPrices(new Double(Math.random()*10).doubleValue(), new Double(Math.random()*9).doubleValue());
            try {
                    Thread.sleep(2);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
        }
    }

    public static void main(String[] args) {

        PriceInfo pricesInfo=new PriceInfo();

        // create 5 threads and 5 readers
        Reader readers[]=new Reader[5];
        Thread threadsReader[]=new Thread[5];
        for (int i=0; i<5; i++){
            readers[i]=new Reader(pricesInfo);
            threadsReader[i]=new Thread(readers[i],("Thread" + i));
        }

        // create  writer thread

        Writer writer=new Writer(pricesInfo);
        Thread threadWriter=new Thread(writer,"WriterThread");

        for (int i=0; i<5; i++){
                threadsReader[i].start();
            }
            threadWriter.start();
    }
}

I am getting following output..

   Thread0: price1 = 1.000000 and price2 = 2.000000 
   Thread4: price1 = 1.000000 and price2 = 2.000000 
   Thread3: price1 = 1.000000 and price2 = 2.000000 
   Thread2: price1 = 1.000000 and price2 = 2.000000 
   Thread1: price1 = 1.000000 and price2 = 2.000000 
   WriterThread: starting to set new prices 
   WriterThread: prices changed to price1:3.971662648848391price2: 8.604830021768233
   Thread0: price1 = 3.971663 and price2 = 8.604830 
   Thread1: price1 = 3.971663 and price2 = 8.604830 
   Thread2: price1 = 3.971663 and price2 = 8.604830 
   Thread3: price1 = 3.971663 and price2 = 8.604830 
   Thread4: price1 = 3.971663 and price2 = 8.604830 
   WriterThread: starting to set new prices 
   WriterThread: prices changed to price1:3.0036555312769297price2: 5.15672274505239

so, as you can see that sequence of threads executing are thread0, thread4,3,2,1,writer,0,1,2,3,4 whereas i am expecting as per fair policy that we should have same sequence such as 0,4,3,2,1 0,4,3,2,1.

is something wrong with my code or is it that fair policy is not strict?

Answer 1

I am creating 10 threads and all threads should executing same statement 3 times where this console print statement is executed. however, I am not getting output where I see every thread showing the print in same sequence. e.g.

A specific sequence of output is hard (and unnecessary) to get with threads. System.out.printf(...) is a synchronized operation so the output will never overlap each other, but the order of the output lines is unpredictable because of the race conditions inherent in running multiple threads at one time. In terms of asynchronous (which has nothing to do with thread synchronization), by default System.out has auto-flush enabled, so all writes to a PrintStream get flushed on every write.

Specific order of output of threaded applications is a FAQ. See my answer here: unwanted output in multithreading

To quote from the answer, the order that threads run cannot be predicted due to hardware, race-conditions, time-slicing randomness, and other factors.