13

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)

5
  • Can you post more information about your environment? I've seen this happen under windows when running in a cmd shell while trying to watch the logging.
    – carson
    Mar 11, 2009 at 11:20
  • thanks carson I have added more detail to the question Mar 11, 2009 at 11:27
  • +1 for "...remove it based on this knowledge..."
    – Marty Pitt
    Sep 8, 2011 at 8:11
  • I've seen this identical deadlock on similar linux hardware; the java process in my case was started on a remote server via ssh. Approximately 1.4MB of logs had been written when the process deadlocked; other identical processes with similar log quantity started the same way on other identical hardware continued normal processing.
    – Ryan
    Jun 2, 2012 at 13:10
  • See stackoverflow.com/a/13144054/603516 for some links to related log4j issues.
    – Vadzim
    Oct 30, 2012 at 17:02

2 Answers 2

13

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.

1
  • Thanks siddhadev i used my own AsyncAppender and stopped using the console appender things working better now. Mar 24, 2009 at 11:45
11

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.

11
  • You are correct however I am at a loss as to why the console appender is hanging like it is. Thanks Mar 11, 2009 at 11:29
  • You're logging too much. Try to reduce the log level for some stuff which you're not interested in. Mar 11, 2009 at 11:34
  • 1
    how do you have stdout attached? is it pointing to a file? to a console? does it still happen if you point it at /dev/null?
    – drscroogemcduck
    Mar 11, 2009 at 11:37
  • 1
    ConsoleAppender writes to System.out which writes to stdout by default. where is stdout going?
    – drscroogemcduck
    Mar 11, 2009 at 12:06
  • System.out is java. Do you mean it is writing to your console? Your console is probably getting filled up. Redirect to a file and see if you still get the problem.
    – drscroogemcduck
    Mar 11, 2009 at 12:23

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.