[ http://jira.qos.ch/browse/LBCLASSIC-154?page=com.atlassian.jira.plugin.syste... ] Ralph Goers edited comment on LBCLASSIC-154 at 9/24/09 9:01 AM: ---------------------------------------------------------------- Actually, it looks like thread 15 is waiting to obtain a reader lock (it is parking). It doesn't hold it. So thread 11 and 15 are waiting to obtain a lock, one for reading and one for writing and I don't see a thread already holding the lock. I have found some references that indicate that the stack trace doesn't show holders of read locks. However, notice http-0.0.0.0-8080-9. This is in AppenderAttachableImpl at line 60, so it must hold the read lock. But it is waiting for <0x00002aaabd743d58> because the Appender is calling a component that does logging. So thread 9 and thread 11 have created the deadlock because they are going after the locks in opposite order. was (Author: rgoers@apache.org): Actually, it looks like thread 15 is waiting to obtain a reader lock (it is parking). It doesn't hold it. So thread 11 and 15 are waiting to obtain a lock, one for reading and one for writing and I don't see a thread already holding the lock. I have found some references that indicate that the stack trace doesn't show holders of read locks. However, notice http-0.0.0.0-8080-9. This is in AppenderAttachableImpl at line 60, so it must hold the read lock. But it is waiting for <0x00002aaabd743d58> because the Appender is calling a component that does logging. So thread 9 and thread 11 have created the deadlock because they are going after the locks in opposite order. What would be the consequences of changing detachAndStopAllAppenders to public void detachAndStopAllAppenders() { List<Appender<E>> copy; w.lock(); try { copy = new ArrayList<Appender<E>>(appenderList); appenderList.clear(); } finally { w.unlock(); } for (Appender<E> a: copy) { a.stop(); } }
All threads become blocked in ReconfigureOnChangeFilter when changing log level under load ------------------------------------------------------------------------------------------
Key: LBCLASSIC-154 URL: http://jira.qos.ch/browse/LBCLASSIC-154 Project: logback-classic Issue Type: Bug Affects Versions: 0.917 Environment: Linux metro2a.star.dev.diginsite.com 2.6.18-128.1.1.el5 #1 SMP Mon Jan 26 13:58:24 EST 2009 x86_64 x86_64 x86_64 GNU/Linux Java(TM) SE Runtime Environment (build 1.6.0_11-b03) Java HotSpot(TM) 64-Bit Server VM (build 11.0-b16, mixed mode) Reporter: Andrew Perrine Assignee: Ceki Gulcu Attachments: stacktrace.log
We were testing logback's new <configuration scan="true"> feature and when we changed the logging level while our application was under load, all threads became blocked inside logback (full stack trace is very long, here are two examples): "http-0.0.0.0-8080-148" daemon prio=10 tid=0x00002aab58679800 nid=0x26ed waiting for monitor entry [0x000000004e617000..0x000000004e618c10] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.classic.turbo.ReconfigureOnChangeFilter.decide(ReconfigureOnChangeFilter.java:99) - waiting to lock <0x00002aaabd743d58> (a ch.qos.logback.classic.LoggerContext) at ch.qos.logback.classic.spi.TurboFilterList.getTurboFilterChainDecision(TurboFilterList.java:47) at ch.qos.logback.classic.LoggerContext.getTurboFilterChainDecision_0_3OrMore(LoggerContext.java:251) at ch.qos.logback.classic.Logger.callTurboFilters(Logger.java:770) at ch.qos.logback.classic.Logger.isDebugEnabled(Logger.java:488) at ch.qos.logback.classic.Logger.isDebugEnabled(Logger.java:484) at org.slf4j.ext.LoggerWrapper.debug(LoggerWrapper.java:238) at com.diginsite.product.ofx.presentation.CustomRequestWrapper.addCNtoOFXRequest(OFXFilter.java:191) at com.diginsite.product.ofx.presentation.CustomRequestWrapper.<init>(OFXFilter.java:153) at com.diginsite.product.ofx.presentation.OFXFilter.doFilter(OFXFilter.java:56) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.hyperic.hq.product.servlet.filter.JMXFilter.doFilter(JMXFilter.java:324) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:175) at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:182) at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:84) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:157) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:262) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:844) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:446) at java.lang.Thread.run(Thread.java:619) "http-0.0.0.0-8080-15" daemon prio=10 tid=0x00002aab600b0400 nid=0x5669 waiting on condition [0x0000000046799000..0x000000004679ac10] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00002aaabd755128> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:747) at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(AbstractQueuedSynchronizer.java:877) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1197) at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(ReentrantReadWriteLock.java:594) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:57) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:271) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:258) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:440) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:394) at ch.qos.logback.classic.Logger.log(Logger.java:813) at org.slf4j.ext.EventLogger.logEvent(EventLogger.java:36) at com.diginsite.services.logging.LoggerUtil.logEvent(LoggerUtil.java:29)
-- 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