[
http://jira.qos.ch/browse/LBCLASSIC-138?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11166#action_11166
]
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: [email protected]):
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 "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
