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.

Answer 2

Although it is hard to answer this question without seeing the code starting the threads, this does not seem to have anything to do with the behavior of System.out.printf(). The threads you are starting are waking up and sleeping independently from each other, so the order of the lines printed among the threads is dependent on the JVM running the code. If you need the statements in order, but you want to do the work in parallel, a CyclicBarrier could be used to coordinate the print statements.

Answer 3

System.out is a buffered stream. This mean that it doesn't fill the console synchroneously. While the printf() call is synchrone, the console output is not.

You can either:

• flush() System.out by calling System.out.flush();,
• use println() which auto-flushes the stream,
• use System.err which is not AFAIK buffered.

Not sure about the last one...

Note that your threads are executed concurrently (if you use .start()) Which means you cannot expect precisely any execution order without synchronization elements.