Hi all,
I was wondering if anyone could give me their opinion on this deadlock
that we've encountered when using log4j. The process that is using the
logger is a multithreaded messaging service running on the VisiBroker
orb. Log4j is configured to "catch" any output so it tries to print out
the stack trace of an exception that has been thrown by the orb. At the
same time, we are debugging some information to the log. The two calls
seem to colide.
As I understand it, the object 0x43a0eca8 has been locked by the first
thread, which is debugging that a call is being invoked on a remote
object. The first thread is waiting for the stream (object 0x43a0b278)
to become free so it can write the message to the log. The second thread
is waiting for object 0x43a0eca8 and has the stream object 0x43a0b0278
locked. The result is this deadlock. I can provide a full threaddump of
the process if required.
I am looking for advice in two areas :
1) If anyone has seen this before, or knows what the problem could be
then any information will be greatly appreciated.
2) I am attempting to recreate the problem with a simple multithreaded
program that logs messages to a file at the same time as throwing
exceptions and printing their stack traces. The problem doesn't occur in
my test program, despite the expectation that this deadlock would be
more likely to occur in a program with a higher density of calls. Any
ideas?
Deadlock information from java
Java(TM) 2 Runtime Environment, Standard Edition (build 1.3.1_04-b02)
Java HotSpot(TM) Client VM (build 1.3.1_04-b02, mixed mode)
-------------------------------------------------------------------------------------
FOUND A JAVA LEVEL DEADLOCK:
----------------------------
"VBJ ThreadPool Worker":
waiting to lock monitor 0x8090784 (object 0x43a0b278, a
java.io.PrintStream),
which is locked by "VBJ ThreadPool Worker"
"VBJ ThreadPool Worker":
waiting to lock monitor 0x809074c (object 0x43a0eca8, a
org.apache.log4j.spi.RootCategory),
which is locked by "VBJ ThreadPool Worker"
JAVA STACK INFORMATION FOR THREADS LISTED ABOVE:
------------------------------------------------
Java Stack for "VBJ ThreadPool Worker":
==========
at java.io.PrintStream.println(PrintStream.java:544)
- waiting to lock <43a0b278> (a java.io.PrintStream)
at org.apache.log4j.helpers.LogLog.error(LogLog.java:134)
at
org.apache.log4j.helpers.OnlyOnceErrorHandler.error(OnlyOnceErrorHandler.java:69)
at
org.apache.log4j.helpers.OnlyOnceErrorHandler.error(OnlyOnceErrorHandler.java:59)
at
org.apache.log4j.helpers.QuietWriter.write(QuietWriter.java:41)
at
org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:292)
at
org.apache.log4j.WriterAppender.append(WriterAppender.java:150)
at
org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:221)
at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57)
at org.apache.log4j.Category.callAppenders(Category.java:187)
at org.apache.log4j.Category.forcedLog(Category.java:372)
at org.apache.log4j.Category.debug(Category.java:241)
at com.prismt.util.Debug.debug(Debug.java:143)
at
com.prismt.orb.portable.PersistentLocator.preinvoke(PersistentLocator.java:39)
at
com.inprise.vbroker.poa.POAImpl.preinvokeLocator(POAImpl.java:1906)
at com.inprise.vbroker.poa.POAImpl.preinvoke(POAImpl.java:2104)
at
com.inprise.vbroker.ProtocolEngine.ServerEngineImpl.preinvoke(ServerEngineImpl.java:248)
at
com.inprise.vbroker.GIOP.GiopProtocolAdapter.doRequest(GiopProtocolAdapter.java:390)
at
com.inprise.vbroker.GIOP.GiopProtocolAdapter.dispatchMessage(GiopProtocolAdapter.java:527)
at
com.inprise.vbroker.orb.TPDispatcherImpl$TPDispatcher.run(TPDispatcherImpl.java:100)
at
com.inprise.vbroker.orb.ThreadPool$PoolWorker.run(ThreadPool.java:76)
Java Stack for "VBJ ThreadPool Worker":
==========
at org.apache.log4j.Category.callAppenders(Category.java:185)
at org.apache.log4j.Category.forcedLog(Category.java:372)
at org.apache.log4j.Category.error(Category.java:286)
at com.prismt.util.Debug$DiagStream.write(Debug.java:266)
- locked <43a0b238> (a com.prismt.util.Debug$DiagStream)
at java.io.PrintStream.write(PrintStream.java:217)
- locked <43a0b278> (a java.io.PrintStream)
at java.io.OutputStreamWriter.write(OutputStreamWriter.java:179)
at java.io.BufferedWriter.flushBuffer(BufferedWriter.java:109)
- locked <43a0b728> (a java.io.OutputStreamWriter)
at java.io.BufferedWriter.write(BufferedWriter.java:204)
- locked <43a0b728> (a java.io.OutputStreamWriter)
at java.io.Writer.write(Writer.java:124)
at java.io.PrintStream.write(PrintStream.java:262)
- locked <43a0b278> (a java.io.PrintStream)
at java.io.PrintStream.print(PrintStream.java:421)
at java.io.PrintStream.println(PrintStream.java:558)
- locked <43a0b278> (a java.io.PrintStream)
at java.lang.Throwable.printStackTrace(Throwable.java:176)
- locked <43a0b278> (a java.io.PrintStream)
at
com.inprise.vbroker.GIOP.GiopProtocolAdapter.doRequest(GiopProtocolAdapter.java:469)
at
com.inprise.vbroker.GIOP.GiopProtocolAdapter.dispatchMessage(GiopProtocolAdapter.java:527)
at
com.inprise.vbroker.orb.TPDispatcherImpl$TPDispatcher.run(TPDispatcherImpl.java:100)
at
com.inprise.vbroker.orb.ThreadPool$PoolWorker.run(ThreadPool.java:76)
Found 1 deadlock.
Thanks,
Paul
--
Paul Graham
Software Engineer
Prismtech Ltd, UK
http://www.prismtechnologies.com
--
To unsubscribe, e-mail: <mailto:[EMAIL PROTECTED]>
For additional commands, e-mail: <mailto:[EMAIL PROTECTED]>
