Thread blocked on println statement in Java

Question

We have running multiple instances of application ( one per tomcat server ) on single physical host. Application do decent logging. Recently we have observed that some applications getting slower or hang and need to be restarted. In thread dump, it is found that all thread were BLOCKED on log statement, waiting for lock on println object. and some other object has already taken lock on println. But i couldn't figure out why other thread not released lock on println object ? I pasting some thread dump snapshots :

BLOCKED Thread dump :

java.lang.Thread.State: BLOCKED (on object monitor)
    at java.io.PrintStream.println(PrintStream.java:755)
    - waiting to lock <0x00000007830097e0> (a java.io.PrintStream)
    at org.apache.tomcat.util.log.SystemLogHandler.println(SystemLogHandler.java:238)
    at com.webaroo.smsnew.common.SMSUtils.log(SMSUtils.java:167)
    at com.webaroo.smsnew.common.SMSUtils.log(SMSUtils.java:113)

Thread dump of thread who taken log of println.

java.lang.Thread.State: BLOCKED (on object monitor)
    at java.nio.CharBuffer.wrap(CharBuffer.java:350)
    at sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:246)
    at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:106)
    - locked <0x00000007830098f0> (a java.io.OutputStreamWriter)
    at java.io.OutputStreamWriter.write(OutputStreamWriter.java:190)
    at java.io.BufferedWriter.flushBuffer(BufferedWriter.java:111)
    - locked <0x00000007830098f0> (a java.io.OutputStreamWriter)
    at java.io.PrintStream.write(PrintStream.java:476)
    - locked <0x00000007830097e0> (a java.io.PrintStream)
    at java.io.PrintStream.print(PrintStream.java:619)
    at java.io.PrintStream.println(PrintStream.java:756)
    - locked <0x00000007830097e0> (a java.io.PrintStream)
    at org.apache.tomcat.util.log.SystemLogHandler.println(SystemLogHandler.java:238)

Answer 1

it is found that all thread were BLOCKED on log statement, waiting for lock on println object. and some other object has already taken lock on println.

The PrintStream class, which is System.out and System.err, are both synchronized classes. Any println(...) method locks before they do the print so that multiple threads don't get overlapping output lines.

Just because the thread dump shows a thread blocked at that location doesn't mean that it is hung. It may just mean that its the slowest part of your application. More thread dumps will show that other threads are making it into the println() but also getting blocked there. If a number of threads are blocked there then the output IO (maybe to the console) is what is slowing your application. You should reduce the number of log methods or reduce the amount of information in each message. If this doesn't help then you are going to have to consider other output mechanisms.

If you need the output then each thread could write to its own BufferedWriter wrapping a FileWriter for example. Or you could have a single thread do the actual output with all other threads adding their messages to a BlockingQueue and the one writer dequeueing a message and then writing it to the BufferedWriter which doesn't lock and buffers its I/O.

private final BlockingQueue<String> messageQueue
      = new ArrayBlockingQueue<String>();
...
// add a message to the queue
messageQueue.add("some log output here: " + someValue);
...
// writer thread
private class LogThread implements Runnable {
    public void run() {
       BufferedWriter writer =
            new BufferedWriter(new FileWriter("/var/log/some_log_file.txt"));
       try {
          while (!Thread.currentThread().isInterrupted()) {
             String msg = messageQueue.take();
             writer.write(msg);
          }
       } finally {
          writer.close();
       }
    }
}

However, you may find that even if you have one thread writing through a buffered stream that you are exceeding the IO bandwidth of your hard-disk. You could try a gziped stream at that point but typically a reevaluation of the output is in order. Can you reduce the number of output lines? Can you keep some sort of counters in memory and dump it every so often. If you really need the log output then you may have to consider increasing the speed of your drive by moving to a SSD.