Search code examples
javamultithreadinggwtvisualvm

Thread dump showing lots of blocked processes


I am debugging a GWT web application that has been running out of permgen space after running for a while, and noticed in the thread dump in VisualVM that there are 248 processes waiting to lock the same StringBuffer, e.g.:

2013-02-27 10:56:30
Full thread dump Java HotSpot(TM) 64-Bit Server VM (23.3-b01 mixed mode):

"Attach Listener" daemon prio=10 tid=0x00007f3bdc00f000 nid=0x3bee waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"1301161716@qtp-1875293347-251" prio=10 tid=0x00007f3ba8209800 nid=0x301f waiting for monitor entry [0x00007f3b6a15f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.mortbay.log.StdErrLog.warn(StdErrLog.java:128)
    - waiting to lock <0x0000000087b405c8> (a java.lang.StringBuffer)
    at org.mortbay.jetty.handler.ContextHandler$SContext.log(ContextHandler.java:1424)
    at com.google.gwt.user.server.rpc.RPCServletUtils.writeResponseForUnexpectedFailure(RPCServletUtils.java:389)
    at com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doUnexpectedFailure(AbstractRemoteServiceServlet.java:110)
    at com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doPost(AbstractRemoteServiceServlet.java:67)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
    at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511)
    at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:401)
    at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
    at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182)
    at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
    at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:450)
    at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
    at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
    at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
    at org.mortbay.jetty.Server.handle(Server.java:326)
    at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542)
    at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:945)
    at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:756)
    at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218)
    at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
    at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:410)
    at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)

   Locked ownable synchronizers:
    - None

"182760474@qtp-1875293347-250" prio=10 tid=0x00007f3ba8207800 nid=0x2ff7 waiting for monitor entry [0x00007f3b6a260000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.mortbay.log.StdErrLog.warn(StdErrLog.java:128)
    - waiting to lock <0x0000000087b405c8> (a java.lang.StringBuffer)
    at org.mortbay.jetty.handler.ContextHandler$SContext.log(ContextHandler.java:1424)
    at com.google.gwt.user.server.rpc.RPCServletUtils.writeResponseForUnexpectedFailure(RPCServletUtils.java:389)
    at com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doUnexpectedFailure(AbstractRemoteServiceServlet.java:110)
    at com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doPost(AbstractRemoteServiceServlet.java:67)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
    at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511)
    at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:401)
    at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
    at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182)
    at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
    at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:450)
    at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
    at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
    at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
    at org.mortbay.jetty.Server.handle(Server.java:326)
    at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542)
    at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:945)
    at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:756)
    at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218)
    at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
    at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:410)
    at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)

   Locked ownable synchronizers:
    - None

"1468146634@qtp-1875293347-249" prio=10 tid=0x00007f3ba8205800 nid=0x2f89 waiting for monitor entry [0x00007f3b6a361000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.mortbay.log.StdErrLog.warn(StdErrLog.java:128)
    - waiting to lock <0x0000000087b405c8> (a java.lang.StringBuffer)
    at org.mortbay.jetty.handler.ContextHandler$SContext.log(ContextHandler.java:1424)
    at com.google.gwt.user.server.rpc.RPCServletUtils.writeResponseForUnexpectedFailure(RPCServletUtils.java:389)
    at com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doUnexpectedFailure(AbstractRemoteServiceServlet.java:110)
    at com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doPost(AbstractRemoteServiceServlet.java:67)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
    at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511)
    at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:401)
    at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
    at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182)
    at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
    at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:450)
    at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
    at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
    at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
    at org.mortbay.jetty.Server.handle(Server.java:326)
    at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542)
    at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:945)
    at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:756)
    at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218)
    at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
    at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:410)
    at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)

   Locked ownable synchronizers:
    - None

...etc...

Is this a problem? What could be causing this? The application is running on a development machine and I am the only one viewing it.


Solution

  • Short answer: There are some internal exception happens in your application, you need to check the server logs(jetty logs, access logs, application logs, etc.) to identify the root cause.


    Analysis:

    The StringBuffer is defined as an instance variable in org.mortbay.log.StdErrLog:

    public class StdErrLog implements Logger {    
      // ...
      StringBuffer _buffer = new StringBuffer();
      //...
    }
    

    And its use is wrapped in a synchronized block:

    public void warn(String msg,Object arg0, Object arg1)
    {
        String d=_dateCache.now();
        int ms=_dateCache.lastMs();
        synchronized(_buffer)
        {
            tag(d,ms,":WARN:");
            format(msg,arg0,arg1);
            System.err.println(_buffer.toString());
        }
    }
    

    Thus if there are multiple threads trying to invoke this method, only one thread would pass, others would have to wait(as in your thread stack).

    We can see this method is invoked from com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doUnexpectedFailure(), which means you have an internal exception in your internal code. Following are quoted from the JavaDoc of this method:

    This method is called only for exceptions or errors that are not part of the service method's signature, or that result from SecurityExceptions, SerializationExceptions, or other failures within the RPC framework.

    As there are so many threads blocking on this method and you are the only client access the server, my guess is there might be a bug in your client-side code, which sends a bunch of unexpected requests to the server. You need to check the server logs(jetty logs, access logs, application logs, etc.) to identify the root cause.