[
http://jira.qos.ch/browse/LBCORE-99?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11169#action_11169
]
Joern Huxhorn commented on LBCORE-99:
-------------------------------------
The important part that I suggest is that
String s = format(event);
should already by thread-safe since
populateCertainPartsByMagic(event);
should have converted the message parameter Object[] to a String[] at that
point.
Ralph and I want the same thing.
My patch concerning LBCORE-97 is a short-term solution to prevent
starvation-effects while most appender implementations are still extending
AppenderBase.
I support his suggestion to change this (extending UnsynchronizedAppenderBase
instead of AppenderBase) step-by-step, one appender after the other, 100%,
though. The lazy formatting of the message, if actually required, should
ideally be done outside any locks as he suggests.
Also, lock(this) and unlock(this) is giving me a bit of a shiver...
It looks suspiciously like synchronized(this) {} and that's absolutely not what
I try to accomplish.
Even if we reduce locking, starvation can and will still occur if an unfair
locking scheme is used. Proving that it will or won't happen is like trying to
prove that there are no white crows. You'd have to look at every crow on the
planet in the worst case and still couldn't be sure if a white crow would show
up after the next breeding session...
Logging must be fair.
> 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
