Java 日志记录线程阻塞

Question

我的 java 记录器有问题，如下所示。我们的 tomcat 服务器将在运行大约 3 到 4 小时后挂起。 tomcat 重新启动后，它将再次运行大约 4 小时，然后再次挂起。就像 IVM 挂了一样。

在我得到线程转储后，它将显示如下代码。据我了解，它在日志记录锁定或硬盘读/写操作方面存在问题。任何人都知道这是 Java 1.6 问题还是会在 Java 7 中修复。

我正在使用 java 1.6.0_18 和 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类发布方法

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 );
}

Answer 1

您遇到了典型的死锁情况。线程 catalina-exec-49 持有 3 个锁(在 org.apache.tomcat.util.net.NioChannel、com.sun.xml.ws 上。 api.pipe.Fiber 和 it.codegen.tbx.ResourceManager)，它正在等待获取第 4 个(在 上输入同步 publish 方法code>it.codegen.logging.CGFileHandler.

问题是另一个线程已经获取了CGFileHandler 上的锁(可能是通过进入publish 方法，或同一实例上的另一个同步方法)，并且正在等待获取 catalina-exec-49 持有的锁之一。两个线程都不能前进，导致死锁。

没有看到详细的代码和堆栈转储等，我不能给你具体的建议，但通常你应该:

• 将同步块(synchronized block)的范围限制在最低限度
• 避免在持有锁的方法之外调用
• 构建您的代码，以便始终以特定顺序获取锁