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:* [email protected] [mailto:[email protected]] *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 <[email protected]>
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
[email protected] <mailto:[email protected]>
http://www.slf4j.org/mailman/listinfo/user
------------------------------------------------------------------------
_______________________________________________
user mailing list
[email protected]
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
_______________________________________________
user mailing list
[email protected]
http://www.slf4j.org/mailman/listinfo/user
