tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Pieter Temmerman <ptemmerman....@sadiel.es>
Subject RE: Thread dump analysis
Date Wed, 28 Jan 2009 09:42:57 GMT
Thanks to all for your helpful input.
As a result of trying to reproduce the problem on pre-production
servers, I used JMeter to generate some load.

Let me give some more specific information about the setup.
I have two Tomcat servers: 
  - Tomcat 5.5.7 (jdk 1.5.0_09) (I know, it's old. But this is the
version that is used in production. I don't administer the actual
production server, thus I'm not in the position to upgrade it).
  - Tomcat 6.0.16 (jdk 1.6.0_07)

On Tomcat 6.0 I'm running a webservice which is implemented using XFire
and connects to an Oracle 9i database. On Tomcat 5.5.7 I'm running web
application X which uses the webservice on Tomcat 6.

Normally, what we see on the production server is that Tomcat 5.5 is
hanging (CPU goes to 100%). However, this time when trying to reproduce
on the pre-production servers, it's Tomcat 6 which is going to 100%,
which on his turn makes the webapp on Tomcat 5.5 not to respond.

Ok, so I thought that the webservice on TC 6.0 crashed or something.
So I used SOAPUI to invoke a request to the webservice, just to be sure
whether the webservice was down. Strangely the webservice successfully
answered my request. 

>Have you found any java.lang.Thread.State: RUNNABLE threads? They are
>usually more interesting if it comes to a high cpu :-)

These are the RUNNABLE threads on Tomcat 6:

"RMI TCP Connection(42)-173.x.x.x" - Thread t@112
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:129)
	at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:237)
	- locked java.io.BufferedInputStream@32c1b3
	at java.io.FilterInputStream.read(FilterInputStream.java:66)
	at
sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:517)
	at sun.rmi.transport.tcp.TCPTransport
$ConnectionHandler.run0(TCPTransport.java:790)
	at sun.rmi.transport.tcp.TCPTransport
$ConnectionHandler.run(TCPTransport.java:649)
	at java.util.concurrent.ThreadPoolExecutor
$Worker.runTask(ThreadPoolExecutor.java:885)
	at java.util.concurrent.ThreadPoolExecutor
$Worker.run(ThreadPoolExecutor.java:907)
	at java.lang.Thread.run(Thread.java:619)

   Locked ownable synchronizers:
	- locked java.util.concurrent.locks.ReentrantLock$NonfairSync@4adf48


NOTE!: There are 6 more of those RMI threads


"http-8081-35" - Thread t@71
   java.lang.Thread.State: RUNNABLE
	at java.lang.String.equals(String.java:1018)
	at
com.sun.org.apache.xerces.internal.impl.XMLStreamReaderImpl.next(XMLStreamReaderImpl.java:554)
	at
org.codehaus.xfire.soap.handler.ReadHeadersHandler.invoke(ReadHeadersHandler.java:44)
	at
org.codehaus.xfire.handler.HandlerPipeline.invoke(HandlerPipeline.java:131)
	at
org.codehaus.xfire.transport.DefaultEndpoint.onReceive(DefaultEndpoint.java:64)
	at
org.codehaus.xfire.transport.AbstractChannel.receive(AbstractChannel.java:38)
	at
org.codehaus.xfire.transport.http.XFireServletController.invoke(XFireServletController.java:304)
	at
org.codehaus.xfire.transport.http.XFireServletController.doService(XFireServletController.java:129)
	at
org.codehaus.xfire.transport.http.XFireServlet.doPost(XFireServlet.java:116)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:710)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
	at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
	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:175)
	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:844)
	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)

   Locked ownable synchronizers:
	- None

"http-8081-34" - Thread t@70
   java.lang.Thread.State: WAITING on
org.apache.tomcat.util.net.JIoEndpoint$Worker@186f141
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:485)
	at org.apache.tomcat.util.net.JIoEndpoint
$Worker.await(JIoEndpoint.java:416)
	at org.apache.tomcat.util.net.JIoEndpoint
$Worker.run(JIoEndpoint.java:442)
	at java.lang.Thread.run(Thread.java:619)

   Locked ownable synchronizers:
	- None

"http-8081-33" - Thread t@69
   java.lang.Thread.State: WAITING on
org.apache.tomcat.util.net.JIoEndpoint$Worker@cb9c42
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:485)
	at org.apache.tomcat.util.net.JIoEndpoint
$Worker.await(JIoEndpoint.java:416)
	at org.apache.tomcat.util.net.JIoEndpoint
$Worker.run(JIoEndpoint.java:442)
	at java.lang.Thread.run(Thread.java:619)

   Locked ownable synchronizers:
	- None

"http-8081-32" - Thread t@68
   java.lang.Thread.State: WAITING on
org.apache.tomcat.util.net.JIoEndpoint$Worker@11bdde
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:485)
	at org.apache.tomcat.util.net.JIoEndpoint
$Worker.await(JIoEndpoint.java:416)
	at org.apache.tomcat.util.net.JIoEndpoint
$Worker.run(JIoEndpoint.java:442)
	at java.lang.Thread.run(Thread.java:619)

   Locked ownable synchronizers:
	- None

"http-8081-31" - Thread t@67
   java.lang.Thread.State: RUNNABLE
	at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl
$PrologDriver.next(XMLDocumentScannerImpl.java:930)
	at
com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(XMLDocumentScannerImpl.java:648)
	at
com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.next(XMLNSDocumentScannerImpl.java:140)
	at
com.sun.org.apache.xerces.internal.impl.XMLStreamReaderImpl.next(XMLStreamReaderImpl.java:548)
	at
org.codehaus.xfire.soap.handler.ReadHeadersHandler.invoke(ReadHeadersHandler.java:44)
	at
org.codehaus.xfire.handler.HandlerPipeline.invoke(HandlerPipeline.java:131)
	at
org.codehaus.xfire.transport.DefaultEndpoint.onReceive(DefaultEndpoint.java:64)
	at
org.codehaus.xfire.transport.AbstractChannel.receive(AbstractChannel.java:38)
	at
org.codehaus.xfire.transport.http.XFireServletController.invoke(XFireServletController.java:304)
	at
org.codehaus.xfire.transport.http.XFireServletController.doService(XFireServletController.java:129)
	at
org.codehaus.xfire.transport.http.XFireServlet.doPost(XFireServlet.java:116)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:710)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
	at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
	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:175)
	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:844)
	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)

   Locked ownable synchronizers:
	- None


NOTE!: There are more of those HTTP threads (both waiting and running),
but all containing more or less the same.


The Tomcat 5.5 webapp which connects to the webservice is not
responding. I saw the following thread on Tomcat 5.5 which may be the
connection to the webservice:

"http-8081-Processor13" - Thread t@41
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:129)
        at
java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
        at
java.io.BufferedInputStream.read(BufferedInputStream.java:235)
        at
org.apache.commons.httpclient.HttpParser.readRawLine(HttpParser.java:77)
        at
org.apache.commons.httpclient.HttpParser.readLine(HttpParser.java:105)
        at
org.apache.commons.httpclient.HttpConnection.readLine(HttpConnection.java:1115)
        at
org.apache.commons.httpclient.MultiThreadedHttpConnectionManager
$HttpConnectionAdapter.readLine(MultiThreadedHttpConnectionManager.java:1373)
        at
org.apache.commons.httpclient.HttpMethodBase.readStatusLine(HttpMethodBase.java:1832)
        at
org.apache.commons.httpclient.HttpMethodBase.readResponse(HttpMethodBase.java:1590)
        at
org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java:995)
        at
org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:397)
        at
org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:170)
        at
org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:396)
        at
org.codehaus.xfire.transport.http.CommonsHttpMessageSender.send(CommonsHttpMessageSender.java:369)
        at
org.codehaus.xfire.transport.http.HttpChannel.sendViaClient(HttpChannel.java:123)
        at
org.codehaus.xfire.transport.http.HttpChannel.send(HttpChannel.java:48)
        at
org.codehaus.xfire.handler.OutMessageSender.invoke(OutMessageSender.java:26)
        at
org.codehaus.xfire.handler.HandlerPipeline.invoke(HandlerPipeline.java:131)
        at
org.codehaus.xfire.client.Invocation.invoke(Invocation.java:79)
        at
org.codehaus.xfire.client.Invocation.invoke(Invocation.java:114)
        at org.codehaus.xfire.client.Client.invoke(Client.java:336)
        at
org.codehaus.xfire.client.XFireProxy.handleRequest(XFireProxy.java:77)
        at
org.codehaus.xfire.client.XFireProxy.invoke(XFireProxy.java:57)
        at $Proxy13.obtenerHashProcedimientos(Unknown Source)
        at
es.feluco.webservices.clientes.ProcedimientosServicioMOADImpl.obtenerHashProcedimientos(ProcedimientosServicioFELUCOImpl.java:70)
        at
es.feluco.negocio.impl.ProcedimientoManagerImpl.obtenerHashProcedimientos(ProcedimientoManagerImpl.java:77)
        at
es.feluco.negocio.impl.DatosAplicacionManagerImpl.refrescarProcedimientos(DatosAplicacionManagerImpl.java:239)
        at
es.feluco.struts.actions.ListadoProcedimientosAction.unspecified(ListadoProcedimientosAction.java:144)
        at sun.reflect.GeneratedMethodAccessor543.invoke(Unknown Source)
        at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at
org.apache.struts.actions.DispatchAction.dispatchMethod(DispatchAction.java:270)
        at
org.apache.struts.actions.DispatchAction.execute(DispatchAction.java:187)
        at
org.springframework.web.struts.DelegatingActionProxy.execute(DelegatingActionProxy.java:110)
        at
org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:431)
        at
org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:236)
        at
org.apache.struts.action.ActionServlet.process(ActionServlet.java:1196)
        at
org.apache.struts.action.ActionServlet.doPost(ActionServlet.java:432)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at
org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:673)
        at
org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:464)
        at
org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:399)
        at
org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:302)
        at
org.apache.struts.action.RequestProcessor.doForward(RequestProcessor.java:1085)
        at
org.apache.struts.tiles.TilesRequestProcessor.doForward(TilesRequestProcessor.java:263)
        at
org.apache.struts.action.RequestProcessor.processForwardConfig(RequestProcessor.java:398)
        at
org.apache.struts.tiles.TilesRequestProcessor.processForwardConfig(TilesRequestProcessor.java:318)
        at
org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:241)
        at
org.apache.struts.action.ActionServlet.process(ActionServlet.java:1196)
        at
org.apache.struts.action.ActionServlet.doPost(ActionServlet.java:432)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at
org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:673)
        at
org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:464)
        at
org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:399)
        at
org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:302)
        at
org.apache.struts.action.RequestProcessor.doForward(RequestProcessor.java:1085)
        at
org.apache.struts.tiles.TilesRequestProcessor.doForward(TilesRequestProcessor.java:263)
        at
org.apache.struts.action.RequestProcessor.processForwardConfig(RequestProcessor.java:398)
        at
org.apache.struts.tiles.TilesRequestProcessor.processForwardConfig(TilesRequestProcessor.java:318)
        at
org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:241)
        at
org.apache.struts.action.ActionServlet.process(ActionServlet.java:1196)
        at
org.apache.struts.action.ActionServlet.doPost(ActionServlet.java:432)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:214)
        at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
        at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
        at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
        at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
        at
org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:526)
        at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
        at
org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:825)
        at org.apache.coyote.http11.Http11Protocol
$Http11ConnectionHandler.processConnection(Http11Protocol.java:738)
        at
org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:526)
        at
org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
        at org.apache.tomcat.util.threads.ThreadPool
$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)


The fact that it's reading from a socket, which I think it the
connection to the webservice, may explain why the application is not
doing anything.

>Also, as David posted, what is the HEAP usage? it's usually at the end
>of the dump.

vdebian2:/usr/local/jdk1.6.0_07/bin# ./jmap 8100
Attaching to process ID 8100, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 10.0-b23

using thread-local object allocation.
Parallel GC with 2 thread(s)

Heap Configuration:
   MinHeapFreeRatio = 40
   MaxHeapFreeRatio = 70
   MaxHeapSize      = 1073741824 (1024.0MB)
   NewSize          = 1048576 (1.0MB)
   MaxNewSize       = 4294901760 (4095.9375MB)
   OldSize          = 4194304 (4.0MB)
   NewRatio         = 8
   SurvivorRatio    = 8
   PermSize         = 16777216 (16.0MB)
   MaxPermSize      = 268435456 (256.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 58851328 (56.125MB)
   used     = 18383664 (17.532028198242188MB)
   free     = 40467664 (38.59297180175781MB)
   31.237466722925948% used
>>From Space:
   capacity = 327680 (0.3125MB)
   used     = 131072 (0.125MB)
   free     = 196608 (0.1875MB)
   40.0% used
To Space:
   capacity = 393216 (0.375MB)
   used     = 0 (0.0MB)
   free     = 393216 (0.375MB)
   0.0% used
PS Old Generation
   capacity = 477233152 (455.125MB)
   used     = 86499376 (82.49223327636719MB)
   free     = 390733776 (372.6327667236328MB)
   18.125181714115286% used
PS Perm Generation
   capacity = 81395712 (77.625MB)
   used     = 62345160 (59.45697784423828MB)
   free     = 19050552 (18.16802215576172MB)
   76.59514054008152% used

I'm quite sure that one of the RUNNING threads of Tomcat 6 is the
problem, which will probably be related to the webservice.
But I'm puzzled with wath the problem might be.

Sorry for the long response, I tried to be as complete as possible.

Thanks in advance for any pointers you are able to give me.


On Mon, 2009-01-26 at 11:33 -0600, Caldarale, Charles R wrote:
> > From: Pieter Temmerman [mailto:ptemmerman.ext@sadiel.es]
> > Subject: Thread dump analysis
> >
> > Memory usage looks healthy, but CPU usage goes sky high (mainly caused
> > by the Java Tomcat process).
> 
> If you're truly out of memory, the GC thread(s) may be running almost continuously. 
However, with modern JVMs (you didn't bother to tell us what JVM you're using, nor what platform
you're on), that's a pretty rare occurrence; it's more likely an application thread that's
looping.  As Leon suggested, look for threads in the runnable state and check the state of
the heap.
> 
> > org.apache.commons.dbcp.PoolingDataSource.getConnection(Poolin
> > gDataSource.java:96)
> 
> This shows that indeed the thread is waiting for a DB connection.  Note that the connection
pool here is managed by the webapp, not Tomcat; the class names are different for Tomcat.
> 
> > My first question is, what is a TP-Processor exactly? Is each client
> > connection to Tomcat being assigned a TP-Processor or am I wrong?
> 
> You're not wrong; each request (not client) is handled by a TP-Processor thread.  When
processing for that request completes, the thread goes back to the thread pool to wait for
another request from any client.
> 
> > So my guess is that the freeze is being caused by a database
> > connection pool that is out of open connections
> 
> You seem to have two symptoms: high CPU usage, and running out of DB connections.  It
is quite likely the two are related, perhaps the webapp gets in an infinite loop and therefore
never releases DB connections back to the pool.
> 
> > Note the line "locked <0x00002aabadaabff8>" and "waiting on
> > <0x00002aabadaabff8>" later on. So first it's locking that
> > "thing" and then it's waiting on that "thing".
> 
> That "thing" is just a plain java.lang.Object, which is here serving the purpose of being
a synchronization point.  Java synchronization semantics require that an object be locked
before it can be waited on; the wait() releases the lock until someone other thread calls
notify() on that object.
> 
> > Is that normal behavior?
> 
> Yes.
> 
> > Is there any way to know what the 0x00002aabadaabff8 means?
> 
> It's the virtual address of the object being waited on.  Not terribly useful other than
as an identifier for the object at a given point in time.  The object can move during a garbage
collection.
> 
> You really should move up to something a bit newer than 5.5.7; it's over four years old
and lots of bug fixes have gone into the 5.5 line since then.  5.5.27 is the current level
for that leg.
> 
>  - Chuck
> 
> 
> THIS COMMUNICATION MAY CONTAIN CONFIDENTIAL AND/OR OTHERWISE PROPRIETARY MATERIAL and
is thus for use only by the intended recipient. If you received this in error, please contact
the sender and delete the e-mail and its attachments from all computers.
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
> 
-- 
Pieter Temmerman
email: ptemmerman.ext@sadiel.es
skype: ptemmerman.sadiel

SADIEL TECNOLOGÍAS DE LA INFORMACIÓN, S.A. http://www.sadiel.es.




---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org


Mime
View raw message