java - Log4j is hanging my application what am I doing wrong?

Question

First some background on the application. I have an application processing many independent tasks in parallel via a thread pool. The thread pool is now hanging.

The following is an snippet from my thread dumps, all my Threads in pool-2 are BLOCKED by "pool-2-thread-78". It seems to be locked trying to write to the console which I find extremely odd. Can anyone shed any light on the situation for me?

EDIT: Platform details java version "1.6.0_07" Java(TM) SE Runtime Environment (build 1.6.0_07-b06) Java HotSpot(TM) Client VM (build 10.0-b23, mixed mode, sharing)

Ubuntu Linux server dual quad core machine.

It seems to lock when writing to the printstream, I have considered just removing the console appender however I would rather know why it is blocking and remove it based on this knowledge. In the past the remove and see if it works has come back to bite me :)

relevant section from my log4j

log4j.rootLogger=DEBUG, STDOUT log4j.logger.com.blah=INFO, LOG log4j.appender.STDOUT=org.apache.log4j.ConsoleAppender log4j.appender.LOG=org.apache.log4j.FileAppender

Thread dump extract

"pool-2-thread-79" Id=149 BLOCKED on org.apache.log4j.spi.RootLogger@6c3ba437 owned by "pool-2-thread-78" Id=148 at org.apache.log4j.Category.callAppenders(Category.java:201) at org.apache.log4j.Category.forcedLog(Category.java:388) at org.apache.log4j.Category.error(Category.java:302) at com.blah.MessageProcessTask.run(MessageProcessTask.java:103) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask/java:268) at java.util.concurrent.FutureTask.run(FutureTask/java:54) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907) at java.lang.Thread.run(Thread.java:619)

"pool-2-thread-78" Id=148 RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:260) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105) - locked <0x6f314ba4> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:430) - locked <0xd5d3504> (a java.io.PrintStream) at org.apache.log4j.ConsoleAppender$SystemOutStream.write(ConsoleAppender.java:173) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276) at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122) - locked <0x6243a076> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212) at org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:57) at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:315) at org.apache.log4j.WriterAppender.append(WriterAppender.java:159) at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230) - locked <0x45dbd560> (a org.apache.log4j.ConsoleAppender) at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65) at org.apache.log4j.Category.callAppenders(Category.java:203) - locked <0x6c3ba437> (a org.apache.log4j.spi.RootLogger) at org.apache.log4j.Category.forcedLog(Category.java:388) at org.apache.log4j.Category.error(Category.java:302) at com.blah.MessageProcessTask.run(MessageProcessTask.java:103) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441) at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask/java:268) at java.util.concurrent.FutureTask.run(FutureTask/java:54) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907) at java.lang.Thread.run(Thread.java:619)

Answer 1

You could use the AsyncAppender to better detach the logger from the appenders.

On Windows, if you click in the console window, this will pause the console, e.g. the stdout buffer will fill up, and as the console appender writes serially, your application will hang until you release the console (press enter or so).

Consider using AsyncAppender with log4j - most of the time it is good idea - the only problem beeing - the AsynAppender buffer is not flushed completely on exit.