History | Log In     View a printable version of the current page.  
   HOME       BROWSE PROJECT       FIND ISSUES   
    QUICK SEARCH:  
 Consider professional SLF4J/logback support for prioritized handling of your bug reports.
Issue Details (XML | Word | Printable)

Key: LBCORE-96
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Major Major
Assignee: Logback dev list
Reporter: Lars Feistner
Votes: 0
Watchers: 3
Operations

If you were logged in you would be able to see more operations.
logback-core

Deadlock when running on multiple core processors

Created: 06/Apr/09 11:54 AM   Updated: 28/May/09 07:55 PM
Component/s: Appender
Affects Version/s: 0.9.15
Fix Version/s: None

File Attachments: 1. Text File AppenderBaseLock.patch (1 kb)
Environment:
Windows Vista
quad core
Apache Tomcat 6.0.18
JDK 1.6


 Description  « Hide
As Robert Dale mentioned on 23/Mar/09 04:05 PM
I'm getting that deadlock in logback core (0.9.14 and 0.9.15). No console plugin or socket appenders, just plain RollingFileAppender.

I am getting the deadlock using ConsoleAppender.

see attached thread dump:

2009-04-06 11:49:45
Full thread dump Java HotSpot(TM) Client VM (11.0-b12 mixed mode, sharing):

"http-8084-5" daemon prio=6 tid=0x04700c00 nid=0xc54 in Object.wait() [0x05d1f000..0x05d1fc68]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
at java.lang.Object.wait(Object.java:485)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416)
- locked <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442)
at java.lang.Thread.run(Thread.java:619)

"http-8084-4" daemon prio=6 tid=0x04700000 nid=0xe24 in Object.wait() [0x05c7f000..0x05c7fbe8]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
at java.lang.Object.wait(Object.java:485)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416)
- locked <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442)
at java.lang.Thread.run(Thread.java:619)

"http-8084-3" daemon prio=6 tid=0x04700400 nid=0x134c waiting for monitor entry [0x05c2f000..0x05c2fa68]
   java.lang.Thread.State: BLOCKED (on object monitor)
at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66)
- waiting to lock <0x23b16ac8> (a ch.qos.logback.core.ConsoleAppender)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:439)
at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:411)
at ch.qos.logback.classic.Logger.debug(Logger.java:504)
at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88)
at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390)
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:233)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
at java.lang.Thread.run(Thread.java:619)

"Thread-10" daemon prio=6 tid=0x046ff800 nid=0x122c runnable [0x05bdf000..0x05bdfb68]
   java.lang.Thread.State: RUNNABLE
at sun.net.dns.ResolverConfigurationImpl.notifyAddrChange0(Native Method)
at sun.net.dns.ResolverConfigurationImpl$AddressChangeListener.run(ResolverConfigurationImpl.java:125)

"http-8084-2" daemon prio=6 tid=0x046ff400 nid=0x17f4 waiting for monitor entry [0x05b8f000..0x05b8fa68]
   java.lang.Thread.State: BLOCKED (on object monitor)
at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66)
- waiting to lock <0x23b16ac8> (a ch.qos.logback.core.ConsoleAppender)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:439)
at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:411)
at ch.qos.logback.classic.Logger.debug(Logger.java:504)
at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88)
at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390)
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:233)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
at java.lang.Thread.run(Thread.java:619)

"TP-Monitor" daemon prio=6 tid=0x04a17400 nid=0x830 in Object.wait() [0x05b3f000..0x05b3fce8]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable)
at org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable.run(ThreadPool.java:565)
- locked <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable)
at java.lang.Thread.run(Thread.java:619)

"TP-Processor4" daemon prio=6 tid=0x0497a000 nid=0x11dc runnable [0x05a8f000..0x05a8fd68]
   java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
- locked <0x23e0a9b0> (a java.net.SocksSocketImpl)
at java.net.ServerSocket.implAccept(ServerSocket.java:453)
at java.net.ServerSocket.accept(ServerSocket.java:421)
at org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:306)
at org.apache.jk.common.ChannelSocket.acceptConnections(ChannelSocket.java:660)
at org.apache.jk.common.ChannelSocket$SocketAcceptor.runIt(ChannelSocket.java:870)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690)
at java.lang.Thread.run(Thread.java:619)

"TP-Processor3" daemon prio=6 tid=0x04979c00 nid=0xfe8 in Object.wait() [0x05a3f000..0x05a3f9e8]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
at java.lang.Object.wait(Object.java:485)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662)
- locked <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
at java.lang.Thread.run(Thread.java:619)

"TP-Processor2" daemon prio=6 tid=0x04982800 nid=0x10bc in Object.wait() [0x059ef000..0x059efa68]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
at java.lang.Object.wait(Object.java:485)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662)
- locked <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
at java.lang.Thread.run(Thread.java:619)

"TP-Processor1" daemon prio=6 tid=0x04982000 nid=0x131c in Object.wait() [0x0599f000..0x0599fae8]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
at java.lang.Object.wait(Object.java:485)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662)
- locked <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable)
at java.lang.Thread.run(Thread.java:619)

"http-8084-1" daemon prio=6 tid=0x04917000 nid=0x15f4 runnable [0x0594f000..0x0594fb68]
   java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:260)
at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105)
- locked <0x2395d280> (a java.io.BufferedOutputStream)
at java.io.PrintStream.write(PrintStream.java:430)
- locked <0x23951d08> (a java.io.PrintStream)
at org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:166)
at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202)
at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272)
at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276)
at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122)
- locked <0x23b1c1f0> (a java.io.OutputStreamWriter)
at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212)
at ch.qos.logback.core.WriterAppender.writerWrite(WriterAppender.java:245)
at ch.qos.logback.core.WriterAppender.subAppend(WriterAppender.java:261)
at ch.qos.logback.core.WriterAppender.append(WriterAppender.java:114)
at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:87)
- locked <0x23b16ac8> (a ch.qos.logback.core.ConsoleAppender)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:439)
at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:411)
at ch.qos.logback.classic.Logger.debug(Logger.java:504)
at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:92)
at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390)
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:233)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447)
at java.lang.Thread.run(Thread.java:619)

"http-8084-Acceptor-0" daemon prio=6 tid=0x049c2400 nid=0x129c runnable [0x058bf000..0x058bfbe8]
   java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
- locked <0x23a40168> (a java.net.SocksSocketImpl)
at java.net.ServerSocket.implAccept(ServerSocket.java:453)
at java.net.ServerSocket.accept(ServerSocket.java:421)
at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:61)
at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:310)
at java.lang.Thread.run(Thread.java:619)

"ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=6 tid=0x051c9800 nid=0x152c waiting on condition [0x0452f000..0x0452fc68]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1579)
at java.lang.Thread.run(Thread.java:619)

"Thread-1" daemon prio=2 tid=0x04638c00 nid=0x1360 in Object.wait() [0x044df000..0x044dfce8]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon)
at EDU.oswego.cs.dl.util.concurrent.ClockDaemon.nextTask(ClockDaemon.java:328)
- locked <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon)
at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:362)
at java.lang.Thread.run(Thread.java:619)

"ElementEventQueue.QProcessor-1" daemon prio=6 tid=0x050f2800 nid=0x17d0 in Object.wait() [0x0442f000..0x0442fd68]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x23b81398> (a java.lang.Object)
at java.lang.Object.wait(Object.java:485)
at org.apache.jcs.engine.control.event.ElementEventQueue.take(ElementEventQueue.java:181)
- locked <0x23b81398> (a java.lang.Object)
at org.apache.jcs.engine.control.event.ElementEventQueue.access$300(ElementEventQueue.java:35)
at org.apache.jcs.engine.control.event.ElementEventQueue$QProcessor.run(ElementEventQueue.java:245)

"Low Memory Detector" daemon prio=6 tid=0x0215c800 nid=0x1370 runnable [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x02156400 nid=0x758 waiting on condition [0x00000000..0x0433f890]
   java.lang.Thread.State: RUNNABLE

"Attach Listener" daemon prio=10 tid=0x02155400 nid=0x14f4 waiting on condition [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x0214ac00 nid=0x151c runnable [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=8 tid=0x02143000 nid=0x430 in Object.wait() [0x0424f000..0x0424fce8]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
- locked <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x02141000 nid=0x510 in Object.wait() [0x0091f000..0x0091fc68]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x2394e7e8> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:485)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0x2394e7e8> (a java.lang.ref.Reference$Lock)

"main" prio=6 tid=0x0020a800 nid=0xef4 runnable [0x0025f000..0x0025fe28]
   java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
- locked <0x23e18dc0> (a java.net.SocksSocketImpl)
at java.net.ServerSocket.implAccept(ServerSocket.java:453)
at java.net.ServerSocket.accept(ServerSocket.java:421)
at org.apache.catalina.core.StandardServer.await(StandardServer.java:389)
at org.apache.catalina.startup.Catalina.await(Catalina.java:642)
at org.apache.catalina.startup.Catalina.start(Catalina.java:602)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413)

"VM Thread" prio=10 tid=0x0213fc00 nid=0xdc0 runnable

"VM Periodic Task Thread" prio=10 tid=0x0215dc00 nid=0x1128 waiting on condition

JNI global references: 781

i also attach my logback configuration:
<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true">

<appender name="stdout"
class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<Pattern>
Operator %X{client}: %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n
</Pattern>
</layout>
</appender>

<!--
<appender name="file"
        class="ch.qos.logback.core.FileAppender" >
        <File>imsm-debug.log</File>
        <Append>false</Append>
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>
                %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n
            </Pattern>
        </layout>

    </appender>
-->
<logger name="net.sf.jguard.core" additivity="false">
<level value="INFO" />
<appender-ref ref="stdout" />
<!--<appender-ref ref="file" />-->
</logger>

<logger name="net.sf.jguard.core.authorization" additivity="false">
<level value="debug"/>
<appender-ref ref="stdout" />
       <!--<appender-ref ref="file" />-->
    </logger>

    <logger name="net.sf.jguard.core.filters" additivity="false">
       <level value="debug"/>
       <appender-ref ref="stdout" />
       <!--<appender-ref ref="file" />-->
    </logger>


<logger name="net.sf.jguard.ext" additivity="false">
<level value="INFO" />
<appender-ref ref="stdout" />
<!--<appender-ref ref="file" />-->
</logger>

<logger name="net.sf.jguard.jee" additivity="false">
<level value="INFO" />
<appender-ref ref="stdout" />
<!--<appender-ref ref="file" />-->
</logger>

<logger name="net.sf.ehcache" additivity="false">
<level value="INFO" />
<appender-ref ref="stdout" />
<!--<appender-ref ref="file" />-->
</logger>

<logger name="de.ims.core.db" additivity="false">
<level value="DEBUG" />
<appender-ref ref="stdout" />
<!--<appender-ref ref="file" />-->
</logger>

    <logger name="de.ims.core.db.util" additivity="false">
<level value="INFO" />
<appender-ref ref="stdout" />
<!--<appender-ref ref="file" />-->
</logger>

    <logger name="de.ims.core.db.jguard" additivity="false">
<level value="INFO" />
<appender-ref ref="stdout" />
<!--<appender-ref ref="file" />-->
</logger>

    <logger name="de.ims.core.db.DBUserImpl" additivity="false">
<level value="DEBUG" />
<appender-ref ref="stdout" />
<!--<appender-ref ref="file" />-->
</logger>
    <logger name="de.ims.core.db.DBGroupImpl" additivity="false">
<level value="DEBUG" />
<appender-ref ref="stdout" />
<!--<appender-ref ref="file" />-->
</logger>
    <logger name="de.ims.core.db.DBOperatorImpl" additivity="false">
<level value="INFO" />
<appender-ref ref="stdout" />
<!--<appender-ref ref="file" />-->
</logger>
    <logger name="de.ims.core.db.DBInstitutionImpl" additivity="false">
<level value="INFO" />
<appender-ref ref="stdout" />
<!--<appender-ref ref="file" />-->
</logger>

<logger name="org.apache.jcs" additivity="false">
<level value="WARN" />
       <appender-ref ref="stdout" />
       <!--<appender-ref ref="file" />-->
    </logger>

<root>
<!-- The following level element is not necessary since the -->
<!-- level of the root level is set to DEBUG by default. -->
<level value="DEBUG" />
<appender-ref ref="stdout" />
<!--<appender-ref ref="file" />-->
</root>
</configuration>

 All   Comments   Change History   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
[ Permlink | « Hide ]
Ralph Goers - 06/Apr/09 03:43 PM
The attached thread dump does NOT show a deadlock. Thread http-8084-1 is running. This thread dump does show the contention over the appender lock. This issue is a duplicate of LBCORE-62.

[ Permlink | « Hide ]
Ceki Gulcu - 16/Apr/09 04:11 PM
The configuration file has redundant appender references (appender-ref elements). See "appender additivity" in http://logback.qos.ch/manual/architecture.html .

Please let me know if removing redundant references solves this issue.

[ Permlink | « Hide ]
Joern Huxhorn - 19/May/09 06:01 PM
Hi guys,

Our webapp running on a 4-core solaris is suffering* the same problem as described in http://jira.qos.ch/browse/LBCORE-63 and http://jira.qos.ch/browse/LBCORE-96 and I think I have an idea about the reason behind this.
Threading policy has changed from 1.5 to 1.6. I can't give you a reference for this, it's purely based on observation. In 1.5, a thread waiting for a lock was somewhat preferred by the VM over threads that would arrive at the wait() at a later time. In 1.6, however, a thread that releases synchronization is much more likely to immediately obtain the object lock again if it's in a consumer/producer loop.

for(;;)
{
synchronized(obj)
{
// thread is likely to reobtain lock
}
}

The same is the case for wait/notifyAll combinations. One can not assume that a longer waiting thread will likely obtain the lock after notifyAll.

This is documented in http://java.sun.com/javase/6/docs/api/java/lang/Object.html#notifyAll() so the changed behavior between 1.5 and 1.6 is perfectly legal.

My assumption is that the perceived deadlock, which is actually a congestion/starvation problem, occurs if one thread is logging "like crazy" while the other thread is sluggish as hell because he can't obtain the lock.

This should be solvable by using a fair ReentrantLock
(See http://java.sun.com/javase/6/docs/api/java/util/concurrent/locks/ReentrantLock.html#ReentrantLock(boolean) )

From the javadoc:
"The constructor for this class accepts an optional fairness parameter. When set true, under contention, locks favor granting access to the longest-waiting thread. Otherwise this lock does not guarantee any particular access order. Programs using fair locks accessed by many threads may display lower overall throughput (i.e., are slower; often much slower) than those using the default setting, but have smaller variances in times to obtain locks and guarantee lack of starvation."

The guaranteed lack of starvation is what we are looking for, I think, This is something that pure synchronization simply can't provide.

I'd suggest to give the attached patch a try, I can't do so myself because I can't risk our webapp and I have no other chance to test this right now.

I'll crosspost this to both tickets cause I'm not sure which one is more "active" right now.

* The webapp shows that behavior in case of either console, file and/or lilith/socket appenders. It's just much more likely to happen with the lilith/socket appender in place since it takes significantly longer to send events over the wire than just writing them to disk or console.

[ Permlink | « Hide ]
Joern Huxhorn - 19/May/09 10:36 PM
I just did a test using the above example and it looks good with the patch applied.

Without the patch, threads are executed unevenly.

2009-05-19 22:21:49,481 DEBUG [pool-2-thread-1] [MAIN] - [EX2] 54803
2009-05-19 22:21:49,481 DEBUG [pool-4-thread-1] [MAIN] - [EX4] 54803
2009-05-19 22:21:49,481 DEBUG [pool-2-thread-1] [EX2] 54803
2009-05-19 22:21:49,481 DEBUG [pool-2-thread-1] [MAIN] - [EX2] 54803
2009-05-19 22:21:49,481 DEBUG [pool-4-thread-1] [EX4] 54803
2009-05-19 22:21:49,481 DEBUG [pool-3-thread-1] [EX3] 54803
2009-05-19 22:21:49,481 DEBUG [pool-1-thread-1] [MAIN] - [EX1] 54805
2009-05-19 22:21:49,481 DEBUG [pool-5-thread-1] [EX5] 54803
2009-05-19 22:21:49,482 DEBUG [pool-5-thread-1] [MAIN] - [EX5] 54804
2009-05-19 22:21:49,481 DEBUG [pool-4-thread-1] [MAIN] - [EX4] 54803
2009-05-19 22:21:49,482 DEBUG [pool-1-thread-1] [EX1] 54806
2009-05-19 22:21:49,481 DEBUG [pool-2-thread-1] [EX2] 54803
2009-05-19 22:21:49,481 DEBUG [pool-3-thread-1] [MAIN] - [EX3] 54803
2009-05-19 22:21:49,482 DEBUG [pool-5-thread-1] [EX5] 54804
2009-05-19 22:21:49,482 DEBUG [pool-4-thread-1] [EX4] 54804
2009-05-19 22:21:49,482 DEBUG [pool-1-thread-1] [MAIN] - [EX1] 54806
2009-05-19 22:21:49,482 DEBUG [pool-2-thread-1] [MAIN] - [EX2] 54804
2009-05-19 22:21:49,482 DEBUG [pool-3-thread-1] [EX3] 54804
2009-05-19 22:21:49,482 DEBUG [pool-5-thread-1] [MAIN] - [EX5] 54804
2009-05-19 22:21:49,482 DEBUG [pool-3-thread-1] [MAIN] - [EX3] 54804
2009-05-19 22:21:49,482 DEBUG [pool-1-thread-1] [EX1] 54806
2009-05-19 22:21:49,482 DEBUG [pool-1-thread-1] [MAIN] - [EX1] 54806
2009-05-19 22:21:49,482 DEBUG [pool-4-thread-1] [MAIN] - [EX4] 54804


With the patch they are running evenly as I'd expect it.

2009-05-19 22:03:14,520 DEBUG [pool-5-thread-1] [EX5] 5900
2009-05-19 22:03:14,520 DEBUG [pool-4-thread-1] [EX4] 5925
2009-05-19 22:03:14,520 DEBUG [pool-1-thread-1] [EX1] 5936
2009-05-19 22:03:14,520 DEBUG [pool-3-thread-1] [MAIN] - [EX3] 5925
2009-05-19 22:03:14,520 DEBUG [pool-2-thread-1] [EX2] 5926
2009-05-19 22:03:14,520 DEBUG [pool-5-thread-1] [MAIN] - [EX5] 5900
2009-05-19 22:03:14,520 DEBUG [pool-4-thread-1] [MAIN] - [EX4] 5925
2009-05-19 22:03:14,521 DEBUG [pool-1-thread-1] [MAIN] - [EX1] 5937
2009-05-19 22:03:14,521 DEBUG [pool-3-thread-1] [EX3] 5926
2009-05-19 22:03:14,521 DEBUG [pool-2-thread-1] [MAIN] - [EX2] 5927
2009-05-19 22:03:14,521 DEBUG [pool-5-thread-1] [EX5] 5901
2009-05-19 22:03:14,521 DEBUG [pool-4-thread-1] [EX4] 5926
2009-05-19 22:03:14,521 DEBUG [pool-1-thread-1] [EX1] 5937

What do you think?

[ Permlink | « Hide ]
Joern Huxhorn - 28/May/09 03:07 PM
I just wanted to point out that this is a very serious issue for us.
We are completely out of logs in our webapp atm because we can't risk a congestion...

[ Permlink | « Hide ]
Ceki Gulcu - 28/May/09 07:52 PM
Logback is using the standard synchronization mechanism found in the JDK. You are saying that that mechanism is unsuitable which, truth be told, sounds quite suspicious.

[ Permlink | « Hide ]
Ceki Gulcu - 28/May/09 07:53 PM
Without a test case, I can't reproduce the problem.

[ Permlink | « Hide ]
Ceki Gulcu - 28/May/09 07:55 PM
If you wish to have a deadlock related issue fixed, please open a new issue. Do not forget to supply a test case (if possible).


Powered by a free Atlassian JIRA open source license for logback. Try JIRA - bug tracking software for your team.
Atlassian JIRA the Professional Issue Tracker. (Enterprise Edition, Version: 3.12.3-#302) - Bug/feature request - Atlassian news - Contact Administrators