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)

Paul Whelan
  • 16,574
  • 12
  • 50
  • 83
  • 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 '09 at 11:20
  • thanks carson I have added more detail to the question – Paul Whelan Mar 11 '09 at 11:27
  • +1 for "...remove it based on this knowledge..." – Marty Pitt Sep 08 '11 at 08: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 02 '12 at 13:10
  • See http://stackoverflow.com/a/13144054/603516 for some links to related log4j issues. – Vadzim Oct 30 '12 at 17:02

2 Answers2

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.

siddhadev
  • 16,501
  • 2
  • 28
  • 35
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.

  • You are correct however I am at a loss as to why the console appender is hanging like it is. Thanks – Paul Whelan Mar 11 '09 at 11:29
  • You're logging too much. Try to reduce the log level for some stuff which you're not interested in. – Aaron Digulla Mar 11 '09 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? –  Mar 11 '09 at 11:37
  • 1
    ConsoleAppender writes to System.out which writes to stdout by default. where is stdout going? –  Mar 11 '09 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. –  Mar 11 '09 at 12:23
  • Sorry STDOUT which is FD 1 on my linux system. – Paul Whelan Mar 11 '09 at 12:27
  • Yes, now where is STDOUT/FD 1 directed to? Is it going to the console, or to a file, or to a pipe? – Douglas Leeder Mar 11 '09 at 12:39
  • console as far as I am aware how can I check? – Paul Whelan Mar 11 '09 at 12:49
  • if it is printing out on the screen then that would be a console. i would redirect to a file: java MyApp > file and see if it still blocks up. i'm tempted to blame the console application but you would think that other people would have run into the same issue and it would have been fixed by now. –  Mar 11 '09 at 12:58
  • erickson give us a break its a pity we are not all experts like you. – Paul Whelan Mar 12 '09 at 09:19
  • I ended up removing Console Appender and extending DailingRollingFileAppender to a custom class that place log messages on a queue and discarded messages if things got very busy.. Works nicely now thanks to drscroogemcduck for all the help. – Paul Whelan Mar 24 '09 at 11:44