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

first, i believe log4j writes to files and the console serially or else all your logs would be corrupted. so while one thread is writing another thread that wants to write has to wait until the other one is finished. also, stdout can block if whatever is attached to it on the other end is not draining it.

in unix there is a special file descriptor called stdout. when you start applications in the console stdout will be attached to the console. you can also redirect stdout to other files. ex: java Blah > /dev/null. chances are you have stdout pointing to a file that is filling up. for example a pipe is a file and if the program at the other end isn't draining the pipe then the program that is writing to the pipe will eventually block.

Answer 2

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.