Java logging thread blocking

Question

I have a problem with java logger as given below. Our tomcat sever will be hang after running around 3 to 4 hours. After tomcat restart it will run again another around 4 hours then again hangs. It is like IVM is hanging.

After I got thread dump it will show as given below code. As my understanding it has issue with logging locking or hard disk read/write operation. Anyone knows is this java 1.6 issue or it will fix in java 7.

I am using java 1.6.0_18 and apache-tomcat-7.0.25.

catalina-exec-49" daemon prio=10 tid=0x00007f2fb000f800 nid=0x2a29 waiting for monitor entry [0x00007f2f6d4d2000]
 java.lang.Thread.State: BLOCKED (on object monitor)
 at it.codegen.logging.CGFileHandler.publish(CGFileHandler.java:684)
 - waiting to lock <0x00007f32dfc56400> (a it.codegen.logging.CGFileHandler)
 at java.util.logging.Logger.log(Logger.java:458)
 at java.util.logging.Logger.doLog(Logger.java:480)
 at java.util.logging.Logger.log(Logger.java:503)
 at it.codegen.tbx.ResourceManager.startResourceManager(ResourceManager.java:246)
 - locked < 0x00007f32f031ad60> (a it.codegen.tbx.ResourceManager)
 at it.codegen.tbx.ResourceManager.createSession(ResourceManager.java:265)
 at it.codegen.tbx.search.service.TravelBoxSearch.createSessionEx(TravelBoxSearch.java:3667)
 at it.codegen.tbx.search.service.TravelBoxSearch.search(TravelBoxSearch.java:3943)
 at sun.reflect.GeneratedMethodAccessor105.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:597)
 at com.sun.xml.ws.api.server.InstanceResolver$1.invoke(InstanceResolver.java:246)
 at com.sun.xml.ws.server.InvokerTube$2.invoke(InvokerTube.java:146)
 at com.sun.xml.ws.server.sei.EndpointMethodHandler.invoke(EndpointMethodHandler.java:257)
 at com.sun.xml.ws.server.sei.SEIInvokerTube.processRequest(SEIInvokerTube.java:95)
 at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java:629)
 at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java:588)
 at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java:573)
 at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java:470)
 - locked < 0x00007f30b6f5f208> (a com.sun.xml.ws.api.pipe.Fiber)
 at com.sun.xml.ws.server.WSEndpointImpl$2.process(WSEndpointImpl.java:295)
 at com.sun.xml.ws.transport.http.HttpAdapter$HttpToolkit.handle(HttpAdapter.java:515)
 at com.sun.xml.ws.transport.http.HttpAdapter.handle(HttpAdapter.java:285)
 at com.sun.xml.ws.transport.http.servlet.ServletAdapter.handle(ServletAdapter.java:143)
 at com.sun.xml.ws.transport.http.servlet.WSServletDelegate.doGet(WSServletDelegate.java:155)
 at com.sun.xml.ws.transport.http.servlet.WSServletDelegate.doPost(WSServletDelegate.java:189)
 at com.sun.xml.ws.transport.http.servlet.WSServlet.doPost(WSServlet.java:76)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:641)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:722)
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
 at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
 at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:224)
 at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:169)
 at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:168)
 at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)
 at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:927)
 at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
 at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:407)
 at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:987)
 at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:579)
 at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1600)
 - locked < 0x00007f32744cd100> (a org.apache.tomcat.util.net.NioChannel)
 at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
 at java.lang.Thread.run(Thread.java:619)

//CGFileHandler class publish method

public synchronized void publish( LogRecord record )
{
    int startPos = meter.written;
    if( !isLoggable( record ) )
    {
        return;
    }
    super.publish( record );
    flush();
    int endPos = meter.written;
    setFileNameAndPossistions( startPos, endPos );
    if( limit > 0 && meter.written >= limit )
    {            
        AccessController.doPrivileged( new PrivilegedAction()
        {
            public Object run()
            {
                rotate();
                return null;
            }
        } );
     }
 }

private void setFileNameAndPossistions( int startPos, int endPos )
{
    String additionalKey = ":" + loggerName + ":"+String.valueOf(    
Thread.currentThread().getId() );

    SoapUtility.setContextData( Loggable.FILE_NAME + additionalKey, currentFileName );
    SoapUtility.setContextData( Loggable.START_POS + additionalKey, startPos );
    SoapUtility.setContextData( Loggable.END_POS + additionalKey, endPos );
}

Looks like you are using a custom logging handler, CGFileHandler... have you looked at this? It may include synchronized blocks or what-not. — jimjim
– jimjim, Commented Sep 11, 2013 at 8:56
@dngamage Please add the code for CGFileHandler, there has to be something in there... — ppeterka
– ppeterka, Commented Sep 13, 2013 at 8:08
waiting to lock <0x00007f32dfc56400> (a it.codegen.logging.CGFileHandler) indicates that your logger is indeed waiting on a lock. Synchronization in loggers means anything that logs can block anything else that logs. You're better off with a logger that locklessly queues log messages and writes on a background thread. The question is, what are other threads in the system doing? Are any of them holding one of the locks you see in that thread dump? A simple test if CGFileHandler is your problem: Reconfigure logging to do plain old stdout logging, and see if the problem goes away. — Tim Boudreau
– Tim Boudreau, Commented Sep 16, 2013 at 19:00
I wonder if you have: public void publish(LogRecord record) { super.publish(record); } or public synchronized void publish(LogRecord record) { // TODO Auto-generated method stub super.publish(record); } — Pawel Solarski
– Pawel Solarski, Commented Sep 17, 2013 at 15:31

rxg · Accepted Answer · 2013-09-27 19:14:17Z

You have a classic deadlock situation. Thread catalina-exec-49 holds 3 locks (on a org.apache.tomcat.util.net.NioChannel, a com.sun.xml.ws.api.pipe.Fiber and a it.codegen.tbx.ResourceManager) and it's waiting to acquire a 4th (to enter the synchronized publish method on a it.codegen.logging.CGFileHandler.

The problem is that another thread has already acquired the lock on the CGFileHandler (maybe by entering the publish method, or another synchronized method on the same instance), and is waiting to acquire one of the locks that catalina-exec-49 holds. Neither thread can advance, leading to deadlock.

Without seeing detailed code and stack dumps, etc., I can't give you specific advice, but generally you should:

limit the extent of synchronized blocks to the bare minimum
avoid calling outside a method holding a lock
structure your code so that locks are always acquired in a specific order

Collectives™ on Stack Overflow

Java logging thread blocking

1 Answer 1

Comments

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

1 Answer 1

Comments

Your Answer

Sign up or log in

Post as a guest

Related