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)

How do you know it is not releasing the lock, but is only holding the lock long enough for you to see it in the snapshot? I would log as little to the screen as possible. Ideally nothing at all. Write everything to a file. — Peter Lawrey, Nov 03 '13 at 20:38
locking and unlocking should be done in try {} finally {}. Also the code where it logs would help too — ata, Nov 03 '13 at 21:02
Terminology please. They aren't 'waiting for [a] lock on the println object'. They are waiting for some common lock in the println() method. — user207421, Nov 03 '13 at 22:37
@Ata These are synchronization locks. Try and finally have nothing to do with it. — user207421, Nov 03 '13 at 22:38
If you have too many threads, and shared resources guarded by locks, there will be contention for the resources and therefore blocking threads. — Raedwald, Nov 04 '13 at 13:28

Gray · Answer 1 · 2019-05-22T15:55:31.767

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.

thanks, I added one missing log from thread dump as below : `Thread-71 daemon prio=10 tid=0x00007f367c0db000 nid=0x3a9b waiting for monitor entry [0x00007f35d837c000] java.lang.Thread.State: BLOCKED (on object monitor) at java.nio.CharBuffer.wrap(CharBuffer.java:350) at What may reason for above lock is not released ? and any other Async logging framework available for higher logging application ? — Pramod, Nov 03 '13 at 20:06
@Pramod You have no evidence that the lock is not being released. Make several snapshots and each time you'll see a different thread holding the lock. You just have high lock contention, that's all. — Marko Topolnik, Nov 03 '13 at 20:42
Marko is right @Pramod. Just because a snapshot shows a thread at that location doesn't mean that it is hung. It just means 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. Can you reduce the size or the number of the messages? You could try log4j or other log packages. You may find however, that you are just exceeding the IO bandwidth of the drive. You might need to move to a SSD. — Gray, Nov 03 '13 at 21:29
@Gray , I took thread dump once application was hang/halt for around 1 hr. and application was running in tomcat server hence logs will be available in log/catalina.out file. — Pramod, Nov 05 '13 at 06:05

Thread blocked on println statement in Java

1 Answers1