[logback-dev] [JIRA] Commented: (LBCLASSIC-154) All threads become blocked in ReconfigureOnChangeFilter when changing log level under load
Ralph Goers (JIRA)
noreply-jira at qos.ch
Thu Sep 24 15:26:44 CEST 2009
[ http://jira.qos.ch/browse/LBCLASSIC-154?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11317#action_11317 ]
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
More information about the logback-dev
mailing list