[JIRA] Created: (LBCLASSIC-154) All threads become blocked in ReconfigureOnChangeFilter when changing log level under load
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: Logback dev list 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
[ http://jira.qos.ch/browse/LBCLASSIC-154?page=com.atlassian.jira.plugin.syste... ] Andrew Perrine updated LBCLASSIC-154: ------------------------------------- Attachment: stacktrace.log Full stack trace
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: Logback dev list 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
[ http://jira.qos.ch/browse/LBCLASSIC-154?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu commented on LBCLASSIC-154: -------------------------------------- Thank you for this bug report. The deadlock you are reporting is unlike any other I've seen before. Here is a summary I extracted from the stack trace you provided. "http-0.0.0.0-8080-14" daemon prio=10 tid=0x00002aab606c9400 nid=0x5668 waiting for monitor entry [0x0000000046696000..0x0000000046699b90] 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.isTraceEnabled(Logger.java:642) at org.slf4j.ext.XLogger.exit(XLogger.java:125) at com.diginsite.services.integration.dao.slave.client.DIISTransaction.processRequest(DIISTransaction.java:69) at com.diginsite.services.integration.dao.slave.client.DIISBrokerAccess.processRequest(DIISBrokerAccess.java:104) at com.diginsite.services.integration.dao.slave.client.DIISBrokerAccess.processRequest(DIISBrokerAccess.java:74) at com.diginsite.services.integration.dao.slave.BrokerAccessDaoConnection.process(BrokerAccessDaoConnection.java:204) at com.diginsite.services.integration.logging.IAALogHandler.publish(IAALogHandler.java:226) at com.diginsite.services.integration.logging.logback.IAALogAppender.append(IAALogAppender.java:131) at com.diginsite.services.integration.logging.logback.IAALogAppender.append(IAALogAppender.java:23) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:89) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60) 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) tens of similar threads waiting on object monitor <0x00002aaabd743d58> omitted "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) at com.diginsite.product.common.services.security.jaas.LoginAdapter.authenticate(LoginAdapter.java:110) at com.diginsite.product.ofx.facade.security.OFXSecurityFacadeBean.authenticate(OFXSecurityFacadeBean.java:114) at com.diginsite.product.ofx.busdelegate.SecurityOFXBusinessDelegate.authenticate(SecurityOFXBusinessDelegate.java:78) "http-0.0.0.0-8080-11" daemon prio=10 tid=0x00002aab60e5fc00 nid=0x5662 waiting on condition [0x0000000046192000..0x0000000046194c90] 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.acquireQueued(AbstractQueuedSynchronizer.java:778) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1114) at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:807) at ch.qos.logback.core.spi.AppenderAttachableImpl.detachAndStopAllAppenders(AppenderAttachableImpl.java:142) at ch.qos.logback.classic.Logger.detachAndStopAllAppenders(Logger.java:207) at ch.qos.logback.classic.Logger.recursiveReset(Logger.java:335) at ch.qos.logback.classic.Logger.recursiveReset(Logger.java:342) at ch.qos.logback.classic.LoggerContext.reset(LoggerContext.java:212) at ch.qos.logback.classic.turbo.ReconfigureOnChangeFilter.reconfigure(ReconfigureOnChangeFilter.java:149) at ch.qos.logback.classic.turbo.ReconfigureOnChangeFilter.decide(ReconfigureOnChangeFilter.java:105) - locked <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.isTraceEnabled(Logger.java:642) at org.slf4j.ext.XLogger.exit(XLogger.java:125) at com.diginsite.product.common.entity.businessclient.BusinessClientImpl.getCredentialValidator(BusinessClientImpl.java:1046) at com.diginsite.product.common.services.security.jaas.LoginAdapter.authenticate(LoginAdapter.java:209) at com.diginsite.product.ofx.facade.security.OFXSecurityFacadeBean.authenticate(OFXSecurityFacadeBean.java:114) at com.diginsite.product.ofx.busdelegate.SecurityOFXBusinessDelegate.authenticate(SecurityOFXBusinessDelegate.java:78) at com.diginsite.product.ofx.presentation.BasePreProcessor.authenticate(BasePreProcessor.java:121) at com.diginsite.product.ofx.presentation.BankingPreProcessorHandler.execute(BankingPreProcessorHandler.java:108) at com.eei.cmr.RequestProcessorMgr.do(Unknown Source) at com.eei.cmr.RequestProcessorMgr.a(Unknown Source) at com.eei.cmr.PFMMediator.a(Unknown Source) at com.eei.cmr.CMRServlet.a(Unknown Source) at com.eei.cmr.CMRServlet.doPost(Unknown Source) at javax.servlet.http.HttpServlet.service(HttpServlet.java:710) It looks like there are tens of threads blocked on <0x00002aaabd743d58> (a ch.qos.logback.classic.LoggerContext), and the holder of that lock, thread "http-0.0.0.0-8080-11" which is parked waiting for <0x00002aaabd755128>, and another thread namely "http-0.0.0.0-8080-15" which holds a reader lock on <0x00002aaabd755128>, all of which in theory should work fine without causing a deadlock.
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
[ http://jira.qos.ch/browse/LBCLASSIC-154?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu commented on LBCLASSIC-154: -------------------------------------- How easy/hard is it for you to reproduce this issue?
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
[ http://jira.qos.ch/browse/LBCLASSIC-154?page=com.atlassian.jira.plugin.syste... ] Andrew Perrine commented on LBCLASSIC-154: ------------------------------------------ Very easily, it happens every time when we setup jmeter to run ten threads continuously against our application and then while that's running, go in and add a <logger> definition to kick up the logging level to debug on a package or class.
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
[ http://jira.qos.ch/browse/LBCLASSIC-154?page=com.atlassian.jira.plugin.syste... ] Ralph Goers commented on LBCLASSIC-154: --------------------------------------- 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.
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
[ 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:00 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. 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(); } } 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.
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
[ 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
[ http://jira.qos.ch/browse/LBCLASSIC-154?page=com.atlassian.jira.plugin.syste... ] JIRA Administrator commented on LBCLASSIC-154: ---------------------------------------------- I had not noticed thread "http-0.0.0.0-8080-9" holding the readlock. Good call. Here is the stack trace: "http-0.0.0.0-8080-9" daemon prio=10 tid=0x00002aab60c13c00 nid=0x5629 waiting for monitor entry [0x0000000044878000..0x000000004487bc10] 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.isDebugEnabled(LoggerWrapper.java:209) at com.diginsite.services.integration.dao.slave.client.DIISBrokerAccess.processRequest(DIISBrokerAccess.java:106) at com.diginsite.services.integration.dao.slave.client.DIISBrokerAccess.processRequest(DIISBrokerAccess.java:74) at com.diginsite.services.integration.dao.slave.BrokerAccessDaoConnection.process(BrokerAccessDaoConnection.java:204) at com.diginsite.services.integration.logging.IAALogHandler.publish(IAALogHandler.java:226) at com.diginsite.services.integration.logging.logback.IAALogAppender.append(IAALogAppender.java:131) at com.diginsite.services.integration.logging.logback.IAALogAppender.append(IAALogAppender.java:23) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:89) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60) 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) It looks like an appender is logging from within itself. Can you prevent DIISBrokerAccess from logging?
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
[ http://jira.qos.ch/browse/LBCLASSIC-154?page=com.atlassian.jira.plugin.syste... ] Ralph Goers commented on LBCLASSIC-154: --------------------------------------- No. The only possibility there would be to make the appender asynchronous so that the calls to DIISBrokerAccess were on a different thread. But taking that approach would essentially mean that all custom appenders would need to be asynchronous to prevent this kind of behavior. For example, if someone wanted to build a Hibernate appender similar to https://www.hibernate.org/97.html and commons logging is mapped to SLF4J then this same problem would occur. In LBCLASSIC-153 I proposed putting the checking and reconfiguration in its own thread. As the yourkit profile shows, this will definitely improve performance and it should also remove this deadlock potential.
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
[ http://jira.qos.ch/browse/LBCLASSIC-154?page=com.atlassian.jira.plugin.syste... ] Ralph Goers edited comment on LBCLASSIC-154 at 9/24/09 3:34 PM: ---------------------------------------------------------------- No. The only possibility there would be to make the appender asynchronous so that the calls to DIISBrokerAccess were on a different thread. But taking that approach would essentially mean that all custom appenders would need to be asynchronous to prevent this kind of behavior. For example, if someone wanted to build a Hibernate appender similar to https://www.hibernate.org/97.html and commons logging is mapped to SLF4J then this same problem would occur. In LBCLASSIC-153 I proposed putting the checking and reconfiguration in its own thread. As the yourkit profile shows, this will definitely improve performance and it should also remove this deadlock potential. Now that the scenario is identified I would imagine it would be pretty easy to duplicate this behavior with a pretty simple Appender under a load test? was (Author: rgoers@apache.org): No. The only possibility there would be to make the appender asynchronous so that the calls to DIISBrokerAccess were on a different thread. But taking that approach would essentially mean that all custom appenders would need to be asynchronous to prevent this kind of behavior. For example, if someone wanted to build a Hibernate appender similar to https://www.hibernate.org/97.html and commons logging is mapped to SLF4J then this same problem would occur. In LBCLASSIC-153 I proposed putting the checking and reconfiguration in its own thread. As the yourkit profile shows, this will definitely improve performance and it should also remove this deadlock potential.
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
[ http://jira.qos.ch/browse/LBCLASSIC-154?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu commented on LBCLASSIC-154: -------------------------------------- For clarity, I am reproducing the stack traces for "http-0.0.0.0-8080-9" and "http-0.0.0.0-8080-11" which are sufficient to illustrate the deadlock condition. "http-0.0.0.0-8080-9" daemon prio=10 tid=0x00002aab60c13c00 nid=0x5629 waiting for monitor entry [0x0000000044878000..0x000000004487bc10] 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.isDebugEnabled(LoggerWrapper.java:209) at com.diginsite.services.integration.dao.slave.client.DIISBrokerAccess.processRequest(DIISBrokerAccess.java:106) at com.diginsite.services.integration.dao.slave.client.DIISBrokerAccess.processRequest(DIISBrokerAccess.java:74) at com.diginsite.services.integration.dao.slave.BrokerAccessDaoConnection.process(BrokerAccessDaoConnection.java:204) at com.diginsite.services.integration.logging.IAALogHandler.publish(IAALogHandler.java:226) at com.diginsite.services.integration.logging.logback.IAALogAppender.append(IAALogAppender.java:131) at com.diginsite.services.integration.logging.logback.IAALogAppender.append(IAALogAppender.java:23) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:89) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60) 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) "http-0.0.0.0-8080-11" daemon prio=10 tid=0x00002aab60e5fc00 nid=0x5662 waiting on condition [0x0000000046192000..0x0000000046194c90] 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.acquireQueued(AbstractQueuedSynchronizer.java:778) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1114) at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:807) at ch.qos.logback.core.spi.AppenderAttachableImpl.detachAndStopAllAppenders(AppenderAttachableImpl.java:142) at ch.qos.logback.classic.Logger.detachAndStopAllAppenders(Logger.java:207) at ch.qos.logback.classic.Logger.recursiveReset(Logger.java:335) at ch.qos.logback.classic.Logger.recursiveReset(Logger.java:342) at ch.qos.logback.classic.LoggerContext.reset(LoggerContext.java:212) at ch.qos.logback.classic.turbo.ReconfigureOnChangeFilter.reconfigure(ReconfigureOnChangeFilter.java:149) at ch.qos.logback.classic.turbo.ReconfigureOnChangeFilter.decide(ReconfigureOnChangeFilter.java:105) - locked <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.isTraceEnabled(Logger.java:642) at org.slf4j.ext.XLogger.exit(XLogger.java:125) In "http-0.0.0.0-8080-11" ReconfigureOnChangeFilter obtains the LoggerContext lock and then attempts to detachAndStopAllAppenders() which requires a write lock (in AppenderAttachableImpl). In "http-0.0.0.0-8080-9", while doing "simple" logging, obtains the reader lock in AppenderAttachableImpl, and one the invoked appenders, namely IAALogAppender, attempts to log from within itself. This causes ReconfigureOnChangeFilter to be invoked which is then blocked waiting for the LoggerContext lock. Deadlock... ReconfigureOnChangeFilter does in-thread reconfiguration in order to avoid the creation of threads which need to be managed, at least closed when the application re-cycles. Such thread management has proven to be troublesome in the past and I would like to avoid it if possible. I agree with you comment about allowing appenders to log from within. Recursive logging may not always be preventable. The next step is to duplicate this behavior in a unit test.
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
[ http://jira.qos.ch/browse/LBCLASSIC-154?page=com.atlassian.jira.plugin.syste... ] Ralph Goers commented on LBCLASSIC-154: --------------------------------------- I modified the test to duplicate this behavior and have fixed it. The fix is at git://github.com/rgoers/logback.git which also includes the fixes for LBCLASSIC-116. This should also improve LBCLASSIC-153 simply because at least one line of code was removed from the synchronized block.
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
[ http://jira.qos.ch/browse/LBCLASSIC-154?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu updated LBCLASSIC-154: --------------------------------- Priority: Critical (was: Major)
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 Priority: Critical 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
[ http://jira.qos.ch/browse/LBCLASSIC-154?page=com.atlassian.jira.plugin.syste... ] Ceki Gulcu resolved LBCLASSIC-154. ---------------------------------- Fix Version/s: 0.9.18 Resolution: Fixed Hi Ralph, The idea of detaching a new thread for the purposes of reconfiguration is very good. It has been applied in [1] which should solve this bug. [1] http://github.com/ceki/logback/commit/3f49ee7c4b0e444dc6748509442a1ea1e6f4c5...
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 Priority: Critical Fix For: 0.9.18
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
participants (4)
-
Andrew Perrine (JIRA) -
Ceki Gulcu (JIRA)
-
JIRA Administrator (JIRA)
-
Ralph Goers (JIRA)