[slf4j-user] deadlock in slf4j-log4j12 ?
Ceki Gulcu
ceki at qos.ch
Tue Feb 10 19:46:34 CET 2009
Given that slf4j has very little synchronized code, and certainly not on the
path exercised by the code Patrick has shown, I am quite skeptical about claims
that using SLF4J (delegating to log4j) or using log4j directly has any influence
on deadlocks or other concurrency problems.
Had SLF4J been using synchronization primitives extensively (which it
does not), adding an additional layer such as SLF4J would not help
solving synchronization problems but potentially exacerbate them.
However, if the change seems to help consistently, then the difference in
synchronization behavior may be attributed to the differences in the client API
between SLF4J and log4j. In log4j, print methods such as debug, info, etc take
parameters of type of Object whereas SLF4J is stricter, only parameters of type
String are allowed. This difference may actually avoid synchronization problems
and constitutes one of reasons for SLF4J's choice of parameter types.
Finding out the lines of code which lock sun.misc.Launcher$AppClassLoader
instances is another, possibly better way of dealing with this problem.
In summary, I beleive that one should not extrapolate an essentially
unidentified problem in Patrick's environment into another unrelated environment.
Paul French wrote:
> Is this something to be concerned about? We have legacy code that uses
> log4j directly and we also have code that uses the slf4j api +
> slf4jlog4j implementation.
>
> I haven't seen any problems to date but we are only in a testing phase.
> I'm wondering if we have just been lucky so far to miss the problem below?
>
> Cheers
> Paul
>
> ------------------------------------------------------------------------
> *From:* user-bounces at slf4j.org [mailto:user-bounces at slf4j.org] *On
> Behalf Of *Patrick Hancke
> *Sent:* 10 February 2009 15:58
> *To:* User list for the slf4j project
> *Subject:* Re: [slf4j-user] deadlock in slf4j-log4j12 ?
>
> It seems I've found the deadlock issue. Our code base consistently uses
> slf4j except in a MessageHandler which is registered with AspectJ and
> takes care of logging AspectJ related messages. That MessageHandler was
> still using the log4j API directly which most probably caused a
> deadlock. The solution is quite simple: I've written an slf4j
> MessageHandler and the deadlock seems gone.
>
> Thanks for your help,
> Patrick Hancke
>
> 2009/2/10 Ceki Gulcu <ceki at qos.ch>
>
> Hello Patrick,
>
> Looking at the stack trace, it seems that pool-2-thread-2 after
> obtaining a lock on the RootLogger tries to obtain a lock on an
> sun.misc.Launcher$AppClassLoader instance within the
> org.jmock.api.ExpectationError.toString() method.
> Another thread namely, pool-1-thread-3, after obtaining a lock on
> the aforementioned sun.misc.Launcher$AppClassLoader instance tries
> to obtain a lock on RootLogger, hence the deadlock.
>
> Not knowing more about RetryConnectingToSocketTask, I can't suggest
> a solution, However, I am pretty confident that the problem is not
> SLF4J related. Log4j's threading model might be at cause although I
> doubt it. You should try to identify the place where
> sun.misc.Launcher$AppClassLoader is locked.
>
> HTH,
>
>
> Patrick Hancke wrote:
>
> I'm using slf4j version 1.5.6 in combination with log4j version
> 1.2.15. Java version is 1.6.0.
>
> In my unit tests, I'm experiencing a deadlock which seems related to
> slf4j / log4j. Below is a thread dump. Anybody experienced similar
> problems?
> ---------------
>
>
> [snip]
>
>
> JNI global references: 973
>
>
> Found one Java-level deadlock:
> =============================
> "pool-2-thread-2":
> waiting to lock monitor 0x09d17be0 (object 0x94d51000, a
> sun.misc.Launcher$AppClassLoader),
> which is held by "pool-1-thread-3"
> "pool-1-thread-3":
> waiting to lock monitor 0x09beebac (object 0x94dcf218, a
> org.apache.log4j.spi.RootLogger),
> which is held by "pool-2-thread-2"
>
> Java stack information for the threads listed above:
> ===================================================
> "pool-2-thread-2":
> at
> org.jmock.api.ExpectationError.toString(ExpectationError.java:32)
> at java.lang.String.valueOf(String.java:2827)
> at java.io.PrintWriter.println(PrintWriter.java:710)
> at java.lang.Throwable.printStackTrace(Throwable.java:509)
> - locked <0xb170f1b0> (a java.io.PrintWriter)
> at
> org.apache.log4j.spi.ThrowableInformation.getThrowableStrRep(ThrowableInformation.java:76)
> at
> org.apache.log4j.spi.LoggingEvent.getThrowableStrRep(LoggingEvent.java:407)
> at
> org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:305)
> at
> org.apache.log4j.WriterAppender.append(WriterAppender.java:160)
> at
> org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
> - locked <0x94d92c40> (a org.apache.log4j.ConsoleAppender)
> at
> org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
> at org.apache.log4j.Category.callAppenders(Category.java:206)
> - locked <0x94dcf218> (a org.apache.log4j.spi.RootLogger)
> at org.apache.log4j.Category.forcedLog(Category.java:391)
> at org.apache.log4j.Category.log(Category.java:856)
> at
> org.slf4j.impl.Log4jLoggerAdapter.error(Log4jLoggerAdapter.java:571)
> at
> com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSocketTask.call(RetryConnectingToSocketTask.java:187)
> at
> com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSocketTask.call(RetryConnectingToSocketTask.java:42)
> at
> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> at java.lang.Thread.run(Thread.java:619)
> "pool-1-thread-3":
> at org.apache.log4j.Category.callAppenders(Category.java:205)
> - waiting to lock <0x94dcf218> (a
> org.apache.log4j.spi.RootLogger)
> at org.apache.log4j.Category.forcedLog(Category.java:391)
> at org.apache.log4j.Category.debug(Category.java:260)
> at
> com.traficon.util.logging.Log4JMessageHandler.handleMessage(Log4JMessageHandler.java:61)
> at
> org.aspectj.weaver.tools.WeavingAdaptor$WeavingAdaptorMessageHolder.handleMessage(WeavingAdaptor.java:615)
> at org.aspectj.bridge.MessageUtil.debug(MessageUtil.java:92)
> at
> org.aspectj.weaver.tools.WeavingAdaptor.debug(WeavingAdaptor.java:459)
> at
> org.aspectj.weaver.tools.WeavingAdaptor.weaveClass(WeavingAdaptor.java:280)
> at org.aspectj.weaver.loadtime.Aj.preProcess(Aj.java:95)
> - locked <0x94d51000> (a sun.misc.Launcher$AppClassLoader)
> at
> org.aspectj.weaver.loadtime.ClassPreProcessorAgentAdapter.transform(ClassPreProcessorAgentAdapter.java:52)
> at
> sun.instrument.TransformerManager.transform(TransformerManager.java:169)
> at
> sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:365)
> at java.lang.ClassLoader.defineClass1(Native Method)
> at java.lang.ClassLoader.defineClass(ClassLoader.java:621)
> at
> java.security.SecureClassLoader.defineClass(SecureClassLoader.java:124)
> at
> java.net.URLClassLoader.defineClass(URLClassLoader.java:260)
> at java.net.URLClassLoader.access$000(URLClassLoader.java:56)
> at java.net.URLClassLoader$1.run(URLClassLoader.java:195)
> at java.security.AccessController.doPrivileged(Native Method)
> at java.net.URLClassLoader.findClass(URLClassLoader.java:188)
> at java.lang.ClassLoader.loadClass(ClassLoader.java:307)
> - locked <0x94d51000> (a sun.misc.Launcher$AppClassLoader)
> at
> sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:301)
> - locked <0x94d51000> (a sun.misc.Launcher$AppClassLoader)
> at java.lang.ClassLoader.loadClass(ClassLoader.java:252)
> at
> java.lang.ClassLoader.loadClassInternal(ClassLoader.java:320)
> - locked <0x94d51000> (a sun.misc.Launcher$AppClassLoader)
> at
> com.traficon.domain.message.impl.xml2.event.Xml2EventMessageGenerator.generateEventMessage(Xml2EventMessageGenerator.java:75)
> at
> com.traficon.tmsng.server.inputgrid.detector.sockettask.GridCommunicationStateSendingListener.sendCommError(GridCommunicationStateSendingListener.java:112)
> at
> com.traficon.tmsng.server.inputgrid.detector.sockettask.GridCommunicationStateSendingListener.connectionFailed(GridCommunicationStateSendingListener.java:74)
> at
> com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSocketTask.call(RetryConnectingToSocketTask.java:153)
> at
> com.traficon.tmsng.server.inputgrid.detector.sockettask.RetryConnectingToSocketTask.call(RetryConnectingToSocketTask.java:42)
> at
> java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> at java.lang.Thread.run(Thread.java:619)
>
> Found 1 deadlock.
>
>
> --
> Ceki Gülcü
> Logback: The reliable, generic, fast and flexible logging framework
> for Java.
> http://logback.qos.ch
> _______________________________________________
> user mailing list
> user at slf4j.org <mailto:user at slf4j.org>
> http://www.slf4j.org/mailman/listinfo/user
>
>
>
> ------------------------------------------------------------------------
>
> _______________________________________________
> user mailing list
> user at slf4j.org
> http://www.slf4j.org/mailman/listinfo/user
--
Ceki Gülcü
Logback: The reliable, generic, fast and flexible logging framework for Java.
http://logback.qos.ch
More information about the slf4j-user
mailing list