[
http://jira.qos.ch/browse/LBCORE-99?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11168#action_11168
]
Ralph Goers edited comment on LBCORE-99 at 6/13/09 5:45 PM:
------------------------------------------------------------
I probably shouldn't speak for Joern, but I don't believe he prefers the option
attributed to him. I think we both understand that since the format operation
is currently not thread-safe that it a lock must be held while it is performed.
IIRC, this is due to the use of java.text.DateFormat. This was discussed in
LBCLASSIC-36 which was closed because locking is being performed rather than
using a thread-safe formatter.
If format was thread-safe there would be no reason to perform the operation
while holding the lock. As it stands, this deadlock would still likely occur if
the format operation is locked as it almost certainly invokes a class loader
somewhere within it.
With regards to the suggestions by Ceki, both assume that avoiding the deadlock
in this particular stack trace will solve the problem. It may not. Simply
avoiding the particular piece of code that is formatting the throwable is
likely to just move the problem to some other place during formatting where the
class loader is called. So I would probably call these options something else
besides "intellectually unsatisfactory".
The only sure way to avoid this problem immediately is to completely disable
logging for "org.mortbay.log".
was (Author: [email protected]):
I probably shouldn't speak for Joern, but I don't believe the prefers the
option attributed to him. I think we both understand that since the format
operation is currently not thread-safe that it a lock must be held while it is
performed. IIRC, this is due to the use of java.text.DateFormat. This was
discussed in LBCLASSIC-36 which was closed because locking is being performed
rather than using a thread-safe formatter.
If format was thread-safe there would be no reason to perform the operation
while holding the lock. As it stands, this deadlock would still likely occur if
the format operation is locked as it almost certainly invokes a class loader
somewhere within it.
With regards to the suggestions by Ceki, both assume that avoiding the deadlock
in this particular stack trace will solve the problem. It may not. Simply
avoiding the particular piece of code that is formatting the throwable is
likely to just move the problem to some other place during formatting where the
class loader is called. So I would probably call these options something else
besides "intellectually unsatisfactory".
The only sure way to avoid this problem immediately is to completely disable
logging for "org.mortbay.log".
> Deadlock in consoleappender using logback in jetty
> --------------------------------------------------
>
> Key: LBCORE-99
> URL: http://jira.qos.ch/browse/LBCORE-99
> Project: logback-core
> Issue Type: Bug
> Components: Appender
> Affects Versions: 0.9.15
> Environment: Maven 2.1.0 jetty plugin on ubuntu linux.
> maven dependencies list ...
> <dependency>
> <groupId>org.slf4j</groupId>
> <artifactId>slf4j-ext</artifactId>
> <version>1.5.8</version>
> <type>jar</type>
> </dependency>
> <dependency>
> <groupId>org.slf4j</groupId>
> <artifactId>jcl-over-slf4j</artifactId>
> <version>1.5.8</version>
> </dependency>
> <dependency>
> <groupId>ch.qos.logback</groupId>
> <artifactId>logback-core</artifactId>
> <version>0.9.15</version>
> <type>jar</type>
> </dependency>
> <dependency>
> <groupId>ch.qos.logback</groupId>
> <artifactId>logback-classic</artifactId>
> <version>0.9.15</version>
> <type>jar</type>
> </dependency>
> <dependency>
> <groupId>commons-logging</groupId>
> <artifactId>commons-logging</artifactId>
> <version>99.0-does-not-exist</version>
> </dependency
> Reporter: Sakib Mehasanewala
> Assignee: Ceki Gulcu
>
> I came across this deadlock while running jetty via plugin in maven to run
> functional tests...
> Found one Java-level deadlock:
> =============================
> "Shutdown":
> waiting to lock monitor 0xb52073c0 (object 0x7395a770, a
> ch.qos.logback.core.ConsoleAppender),
>
> which is held by "32900...@qtp0-0 - /cbs2/v1.0/ws/cbs2.wsdl"
>
> "32900...@qtp0-0 - /cbs2/v1.0/ws/cbs2.wsdl":
>
> waiting to lock monitor 0xb5209bfc (object 0x7391a760, a
> org.mortbay.jetty.webapp.WebAppClassLoader),
>
> which is held by "15510...@qtp0-2 - /cbs2/v1.0/ws/cbs2.wsdl"
>
> "15510...@qtp0-2 - /cbs2/v1.0/ws/cbs2.wsdl":
>
> waiting to lock monitor 0xb52073c0 (object 0x7395a770, a
> ch.qos.logback.core.ConsoleAppender),
>
> which is held by "32900...@qtp0-0 - /cbs2/v1.0/ws/cbs2.wsdl"
>
> Java stack information for the threads listed above:
> ===================================================
> "Shutdown":
> at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66)
> - waiting to lock <0x7395a770> (a ch.qos.logback.core.ConsoleAppender)
> at
> ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60)
>
> at
> ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
> at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
>
> at
> ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:439)
> at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:430)
>
> at ch.qos.logback.classic.Logger.info(Logger.java:605)
>
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
>
>
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>
> at java.lang.reflect.Method.invoke(Method.java:597)
>
> at org.mortbay.log.Slf4jLog.info(Slf4jLog.java:103)
>
> at org.mortbay.log.Log.info(Log.java:132)
>
> at org.mortbay.jetty.Server$ShutdownHookThread.run(Server.java:550)
>
> "32900...@qtp0-0 - /cbs2/v1.0/ws/cbs2.wsdl":
>
> at
> org.mortbay.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:341)
>
>
> - waiting to lock <0x7391a760> (a
> org.mortbay.jetty.webapp.WebAppClassLoader)
> at
> ch.qos.logback.classic.spi.PackagingDataCalculator.loadClass(PackagingDataCalculator.java:232)
>
> at
> ch.qos.logback.classic.spi.PackagingDataCalculator.bestEffortLoadClass(PackagingDataCalculator.java:257)
>
> at
> ch.qos.logback.classic.spi.PackagingDataCalculator.computeBySTEP(PackagingDataCalculator.java:166)
>
> at
> ch.qos.logback.classic.spi.PackagingDataCalculator.populateFrames(PackagingDataCalculator.java:97)
>
> at
> ch.qos.logback.classic.spi.PackagingDataCalculator.calculate(PackagingDataCalculator.java:61)
>
> at
> ch.qos.logback.classic.spi.ThrowableProxy.calculatePackagingData(ThrowableProxy.java:50)
>
> at
> ch.qos.logback.classic.pattern.ExtendedThrowableProxyConverter.prepareLoggingEvent(ExtendedThrowableProxyConverter.java:35)
>
> at
> ch.qos.logback.classic.pattern.ThrowableProxyConverter.convert(ThrowableProxyConverter.java:142)
>
> at
> ch.qos.logback.classic.pattern.ThrowableProxyConverter.convert(ThrowableProxyConverter.java:30)
>
> at
> ch.qos.logback.core.pattern.FormattingConverter.write(FormattingConverter.java:32)
>
>
> at
> ch.qos.logback.core.pattern.PatternLayoutBase.writeLoopOnConverters(PatternLayoutBase.java:110)
>
> at
> ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:132)
> at
> ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:51)
> at
> ch.qos.logback.core.WriterAppender.subAppend(WriterAppender.java:261)
> at ch.qos.logback.core.WriterAppender.append(WriterAppender.java:114)
>
> at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:87)
>
> - locked <0x7395a770> (a ch.qos.logback.core.ConsoleAppender)
>
> at
> ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60)
>
> at
> ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
> at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
>
> at
> ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:439)
> at
> ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:393)
> at ch.qos.logback.classic.Logger.warn(Logger.java:710)
>
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
>
>
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>
> at java.lang.reflect.Method.invoke(Method.java:597)
>
> at org.mortbay.log.Slf4jLog.warn(Slf4jLog.java:128)
>
> at org.mortbay.log.Log.warn(Log.java:181)
>
> at org.mortbay.log.Log.unwind(Log.java:216)
>
> at org.mortbay.log.Log.warn(Log.java:182)
>
> at org.mortbay.log.Log.unwind(Log.java:216)
>
> at org.mortbay.log.Log.warn(Log.java:182)
>
> at
> org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:414)
> at
> org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
> at
> org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
> at
> org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
> at
> org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)
> at
> org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
>
> at
> org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
>
>
> at
> org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
> at org.mortbay.jetty.Server.handle(Server.java:320)
>
> at
> org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534)
> at
> org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:864)
>
> at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:533)
>
> at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:207)
>
> at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403)
>
> at
> org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
> at
> org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:522)
>
>
> "15510...@qtp0-2 - /cbs2/v1.0/ws/cbs2.wsdl":
>
> at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66)
>
> - waiting to lock <0x7395a770> (a
> ch.qos.logback.core.ConsoleAppender)
> at
> ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60)
>
> at
> ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
> at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
>
> at
> ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:439)
> at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:430)
>
> at ch.qos.logback.classic.Logger.debug(Logger.java:508)
>
> at sun.reflect.GeneratedMethodAccessor15.invoke(Unknown Source)
>
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>
> at java.lang.reflect.Method.invoke(Method.java:597)
>
> at org.mortbay.log.Slf4jLog.debug(Slf4jLog.java:73)
>
> at org.mortbay.log.Log.debug(Log.java:90)
>
> at
> org.mortbay.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:388)
>
>
> - locked <0x7391a760> (a org.mortbay.jetty.webapp.WebAppClassLoader)
>
> at
> org.mortbay.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:341)
>
>
> - locked <0x7391a760> (a org.mortbay.jetty.webapp.WebAppClassLoader)
>
> at
> com.sun.org.apache.xerces.internal.parsers.ObjectFactory.findProviderClass(ObjectFactory.java:393)
>
> at
> com.sun.org.apache.xerces.internal.parsers.ObjectFactory.newInstance(ObjectFactory.java:348)
>
> at
> com.sun.org.apache.xerces.internal.parsers.ObjectFactory.createObject(ObjectFactory.java:154)
>
> at
> com.sun.org.apache.xerces.internal.parsers.ObjectFactory.createObject(ObjectFactory.java:97)
>
> at
> com.sun.org.apache.xerces.internal.parsers.DOMParser.<init>(DOMParser.java:125)
>
>
> at
> com.sun.org.apache.xerces.internal.parsers.DOMParser.<init>(DOMParser.java:109)
>
>
> at
> com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderImpl.<init>(DocumentBuilderImpl.java:115)
>
> at
> com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl.newDocumentBuilder(DocumentBuilderFactoryImpl.java:72)
>
> at
> com.sun.org.apache.xalan.internal.xsltc.trax.SAX2DOM.<init>(SAX2DOM.java:69)
> - locked <0x912b1278> (a java.lang.Class for
> com.sun.org.apache.xalan.internal.xsltc.trax.SAX2DOM)
>
> at
> com.sun.org.apache.xalan.internal.xsltc.runtime.output.TransletOutputHandlerFactory.getSerializationHandler(TransletOutputHandlerFactory.java:187)
>
> at
> com.sun.org.apache.xalan.internal.xsltc.trax.TransformerImpl.getOutputHandler(TransformerImpl.java:392)
>
> at
> com.sun.org.apache.xalan.internal.xsltc.trax.TransformerImpl.transform(TransformerImpl.java:298)
> at
> org.springframework.ws.transport.http.WsdlDefinitionHandlerAdapter.handle(WsdlDefinitionHandlerAdapter.java:125)
> at
> org.springframework.ws.transport.http.MessageDispatcherServlet.doService(MessageDispatcherServlet.java:222)
> at
> org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:613)
> at
> org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:525)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
> at
> org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
> at
> org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1124)
> at
> com.diginsite.services.cbs2.filter.ClearRequestContextFilter.doFilter(ClearRequestContextFilter.java:34)
> at
> org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1115)
> at
> org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:361)
> at
> org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
> at
> org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
> at
> org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
> at
> org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)
> at
> org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
> at
> org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
> at
> org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
> at org.mortbay.jetty.Server.handle(Server.java:320)
> at
> org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534)
> at
> org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:864)
> at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:533)
> at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:207)
> at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403)
> at
> org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
> at
> org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:522)
> Found 1 deadlock.
> Heap
> def new generation total 3904K, used 115K [0x70060000, 0x70490000,
> 0x727c0000)
> eden space 3520K, 3% used [0x70060000, 0x7007cda8, 0x703d0000)
> from space 384K, 0% used [0x703d0000, 0x703d0000, 0x70430000)
> to space 384K, 0% used [0x70430000, 0x70430000, 0x70490000)
> tenured generation total 50668K, used 26395K [0x727c0000, 0x7593b000,
> 0x90060000)
> the space 50668K, 52% used [0x727c0000, 0x74186f40, 0x74187000,
> 0x7593b000)
> compacting perm gen total 20736K, used 20517K [0x90060000, 0x914a0000,
> 0x94060000)
> the space 20736K, 98% used [0x90060000, 0x914697a0, 0x91469800,
> 0x914a0000)
> ro space 8192K, 74% used [0x94060000, 0x94658b48, 0x94658c00, 0x94860000)
> rw space 12288K, 58% used [0x94860000, 0x94f73df0, 0x94f73e00,
> 0x95460000)
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
http://jira.qos.ch/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
_______________________________________________
logback-dev mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-dev
