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