[ http://jira.qos.ch/browse/LBCLASSIC-138?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu edited comment on LBCLASSIC-138 at 7/1/09 11:39 PM: --------------------------------------------------------------- Here is a rough view of what happens when logback writes out to a single appender. LoggingEvent event = createLoggingEvent(); Appender.doAppend(event) { lock(this); // lock the appender populateLoggingEventFieldsLazily(event); String s = format(event); writeOutToTarget(s); unlock(this); } This bug (LBCORE-99) could be solved in several ways. Option A: Reduce locking scope LoggingEvent event = createLoggingEvent(); Appender.doAppend(event) { populateLoggingEventFieldsLazily(event); String s = format(event); lock(this); // lock the appender writeOutToTarget(s); unlock(this); } Option B: Same locking scope, but without lazy fields initialization. // populate all fields at creation time LoggingEvent event = createLoggingEvent(); Appender.doAppend(event) { lock(this); // lock the appender String s = format(event); writeOutToTarget(s); unlock(this); } Option C: apply both options A and B which are not mutually exlusive Option A makes the code more complex as formatting done in pattern converters also will need to be thread safe using distinct locks per converter. So instead of dealing with a single lock during the execution of the doAppend method, we would have to deal with 4 or more, with each lock having a small scope. Since there are more locks, I don't think performance would be improved. Test results indicate that there would be even a small (but measurable) degradation in performance. Option B, if implemented to its bitter end, would solve all the deadlock problems that have surfaced in relation to the doAppend method. However, we would also loose lazy initialization of LoggingEvent fields. Looking more closely, as of revision 2174 dated February 27th 2009 ThrowableProxy was no longer initialized lazily. So this particular deadlock problem would not occur after revision 2174. Presently, there are 3 fields which are initialized lazily, namely CallerData, FormattedMessage and ThreadName, the latter two are fast to compute and are used in a large majority of configurations. Initializing them at LoggingEvent creation would be a non-issue. On the contrary, CallerData is both expensive to compute and is used in a small number of configurations. It must be computed lazily. Even if option A has been applied (as of revision 2310 dated June 29th), I am wondering if option B would not be a simpler solution. Thus, I am hesitating between option B and option C. was (Author: noreply.ceki@qos.ch): Here is a very rough view of what happens when logback writes out to a single appender. LoggingEvent event = createLoggingEvent(); Appender.doAppend(event) { lock(this); // lock the appender populateCertainPartsByMagic(event); String s = format(event); writeOutToTarget(s); unlock(this); } This bug (LBCORE-99) could be solved in several ways. As Ralph suggests: LoggingEvent event = createLoggingEvent(); Appender.doAppend(event) { populateCertainPartsByMagic(event); String s = format(event); lock(this); // lock the appender writeOutToTarget(s); unlock(this); } As suggested by Joern LoggingEvent event = createLoggingEvent(); populateCertainPartsByMagic(event); Appender.doAppend(event) { lock(this); // lock the appender String s = format(event); writeOutToTarget(s); unlock(this); } There are cons to each approach as there are pros, e.g. the resolution of this bug.
Deadlock in consoleappender using logback in jetty --------------------------------------------------
Key: LBCLASSIC-138 URL: http://jira.qos.ch/browse/LBCLASSIC-138 Project: logback-classic Issue Type: Sub-task 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 "32900144@qtp0-0 - /cbs2/v1.0/ws/cbs2.wsdl" "32900144@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 "15510444@qtp0-2 - /cbs2/v1.0/ws/cbs2.wsdl" "15510444@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 "32900144@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) "32900144@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) "15510444@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