Mailing-List: contact users-help@tomcat.apache.org; run by ezmlm
Precedence: bulk
Reply-To: "Tomcat Users List" <users@tomcat.apache.org>
Received-SPF: pass (nike.apache.org: domain of mike.wertheim@gmail.com
 designates 74.125.82.43 as permitted sender)
MIME-Version: 1.0
Sender: mike.wertheim@gmail.com
In-Reply-To: 
 <CAPvtZeedatMvbz2VG4ztC1-JxSEx3CXA8PSii6p3n9W+Oz7e2Q@mail.gmail.com>
References: 
 <CAPvtZefXrtuh53avmnYrX8KdpopU72hKv_UGj5vQpB2LpyZKmA@mail.gmail.com>
	<4F023919.3050305@christopherschultz.net>
	<CAPvtZeedatMvbz2VG4ztC1-JxSEx3CXA8PSii6p3n9W+Oz7e2Q@mail.gmail.com>
Date: Tue, 3 Jan 2012 17:04:47 -0800
Message-ID: 
 <CAPvtZeeLyOc3mB7ioN4_OBP8Lb1rnumW=mx0CCcJVbF19zkK=A@mail.gmail.com>
Subject: Re: help analyzing thread dump for Tomcat 7.0.23 issue
From: Mike Wertheim <mw@hyperreal.org>
To: Tomcat Users List <users@tomcat.apache.org>
Content-Type: text/plain; charset=ISO-8859-1
Content-Transfer-Encoding: quoted-printable

On Mon, Jan 2, 2012 at 6:55 PM, Mike Wertheim <mw@hyperreal.org> wrote:
> On Mon, Jan 2, 2012 at 3:09 PM, Christopher Schultz
> <chris@christopherschultz.net> wrote:
>> -----BEGIN PGP SIGNED MESSAGE-----
>> Hash: SHA1
>>
>> Mike,
>>
>> On 12/29/11 9:01 PM, Mike Wertheim wrote:
>>> I did a stack dump on 7.0.23 when it was in its messed up state.
>>> No threads are blocked on critical sections of my app.
>>
>> That's good.
>>
>>> For the port 8080 connector, there are 196 threads in "waiting on
>>> condition" and 4 threads in "runnable".
>>
>> What were those 4 RUNNABLE threads doing?
>
> They were processing POST requests from the client with a somewhat
> large data payload.
>
> Here's the stack from one of them:
> "http-apr-8080-exec-169" daemon prio=3D10 tid=3D0x00002aaabc893000
> nid=3D0x5253 runnable [0x00000000451a9000]
> =A0 java.lang.Thread.State: RUNNABLE
> =A0 =A0 =A0 =A0at org.apache.tomcat.jni.Socket.recvbb(Native Method)
> =A0 =A0 =A0 =A0at org.apache.coyote.http11.InternalAprInputBuffer.fill(In=
ternalAprInputBuffer.java:614)
> =A0 =A0 =A0 =A0at org.apache.coyote.http11.InternalAprInputBuffer$SocketI=
nputBuffer.doRead(InternalAprInputBuffer.java:656)
> =A0 =A0 =A0 =A0at org.apache.coyote.http11.filters.IdentityInputFilter.do=
Read(IdentityInputFilter.java:118)
> =A0 =A0 =A0 =A0at org.apache.coyote.http11.InternalAprInputBuffer.doRead(=
InternalAprInputBuffer.java:548)
> =A0 =A0 =A0 =A0at org.apache.coyote.Request.doRead(Request.java:422)
> =A0 =A0 =A0 =A0at org.apache.catalina.connector.InputBuffer.realReadBytes=
(InputBuffer.java:290)
> =A0 =A0 =A0 =A0at org.apache.tomcat.util.buf.ByteChunk.substract(ByteChun=
k.java:429)
> =A0 =A0 =A0 =A0at org.apache.catalina.connector.InputBuffer.read(InputBuf=
fer.java:315)
> =A0 =A0 =A0 =A0at org.apache.catalina.connector.CoyoteInputStream.read(Co=
yoteInputStream.java:200)
> =A0 =A0 =A0 =A0at org.apache.catalina.connector.Request.readPostBody(Requ=
est.java:3096)
> =A0 =A0 =A0 =A0at org.apache.catalina.connector.Request.parseParameters(R=
equest.java:3049)
> =A0 =A0 =A0 =A0at org.apache.catalina.connector.Request.getParameter(Requ=
est.java:1139)
> =A0 =A0 =A0 =A0at org.apache.catalina.connector.RequestFacade.getParamete=
r(RequestFacade.java:382)
> =A0 =A0 =A0 =A0at com.mycompany.UploadServlet.service(UploadServlet.java:=
29)
> =A0 =A0 =A0 =A0at javax.servlet.http.HttpServlet.service(HttpServlet.java=
:722)
> =A0 =A0 =A0 =A0at org.apache.catalina.core.ApplicationFilterChain.interna=
lDoFilter(ApplicationFilterChain.java:305)
> =A0 =A0 =A0 =A0at org.apache.catalina.core.ApplicationFilterChain.doFilte=
r(ApplicationFilterChain.java:210)
> =A0 =A0 =A0 =A0at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFi=
lter(UrlRewriteFilter.java:738)
> =A0 =A0 =A0 =A0at org.apache.catalina.core.ApplicationFilterChain.interna=
lDoFilter(ApplicationFilterChain.java:243)
> =A0 =A0 =A0 =A0at org.apache.catalina.core.ApplicationFilterChain.doFilte=
r(ApplicationFilterChain.java:210)
> =A0 =A0 =A0 =A0at org.apache.catalina.core.StandardWrapperValve.invoke(St=
andardWrapperValve.java:207)
> =A0 =A0 =A0 =A0at org.apache.catalina.core.StandardContextValve.invoke(St=
andardContextValve.java:169)
> =A0 =A0 =A0 =A0at org.apache.catalina.authenticator.AuthenticatorBase.inv=
oke(AuthenticatorBase.java:472)
> =A0 =A0 =A0 =A0at org.apache.catalina.core.StandardHostValve.invoke(Stand=
ardHostValve.java:168)
> =A0 =A0 =A0 =A0at org.apache.catalina.valves.ErrorReportValve.invoke(Erro=
rReportValve.java:98)
> =A0 =A0 =A0 =A0at org.apache.catalina.core.StandardEngineValve.invoke(Sta=
ndardEngineValve.java:118)
> =A0 =A0 =A0 =A0at org.apache.catalina.connector.CoyoteAdapter.service(Coy=
oteAdapter.java:407)
> =A0 =A0 =A0 =A0at org.apache.coyote.http11.AbstractHttp11Processor.proces=
s(AbstractHttp11Processor.java:987)
> =A0 =A0 =A0 =A0at org.apache.coyote.AbstractProtocol$AbstractConnectionHa=
ndler.process(AbstractProtocol.java:539)
> =A0 =A0 =A0 =A0at org.apache.tomcat.util.net.AprEndpoint$SocketWithOption=
sProcessor.run(AprEndpoint.java:1773)
> =A0 =A0 =A0 =A0- locked <0x00000006680fdee8> (a
> org.apache.tomcat.util.net.SocketWrapper)
> =A0 =A0 =A0 =A0at java.util.concurrent.ThreadPoolExecutor.runWorker(Threa=
dPoolExecutor.java:1110)
> =A0 =A0 =A0 =A0at java.util.concurrent.ThreadPoolExecutor$Worker.run(Thre=
adPoolExecutor.java:603)
> =A0 =A0 =A0 =A0at java.lang.Thread.run(Thread.java:722)
>
>
>
>>
>>> For the port 8443 connector, there are 81 threads in "waiting on
>>> condition" and 119 threads in "runnable".
>>
>> Well, that looks like it might be a problem. What about the stack
>> traces for THOSE threads?
>
> They mostly look like this:
>
> "http-apr-8443-exec-200" daemon prio=3D10 tid=3D0x00002aaac8132800
> nid=3D0x520f runnable [0x0000000044fba000]
> =A0 java.lang.Thread.State: RUNNABLE
> =A0 =A0 =A0 =A0at org.apache.tomcat.jni.SSLSocket.handshake(Native Method=
)
> =A0 =A0 =A0 =A0at org.apache.tomcat.util.net.AprEndpoint.setSocketOptions=
(AprEndpoint.java:751)
> =A0 =A0 =A0 =A0at org.apache.tomcat.util.net.AprEndpoint$SocketWithOption=
sProcessor.run(AprEndpoint.java:1766)
> =A0 =A0 =A0 =A0- locked <0x000000067f3101e0> (a
> org.apache.tomcat.util.net.SocketWrapper)
> =A0 =A0 =A0 =A0at java.util.concurrent.ThreadPoolExecutor.runWorker(Threa=
dPoolExecutor.java:1110)
> =A0 =A0 =A0 =A0at java.util.concurrent.ThreadPoolExecutor$Worker.run(Thre=
adPoolExecutor.java:603)
> =A0 =A0 =A0 =A0at java.lang.Thread.run(Thread.java:722)
>
>
>> When you say "slowly grinds to a halt" do you mean that there's point
>> where you can no longer accept HTTP requests? How about HTTPS? When
>> you get stuck, what does 'top' show? Do the threads look idle or are
>> you burning up your CPU?
>
> It definitely stops accepting some (but not all) http requests. =A0To
> answer the other questions, I'd have to run the test again (and it
> takes a day to fail).

To follow up on this... I just ran the experiment again.  The CPUs are
very idle.

Currently, the system is not rejecting any requests.  Both http and
https are working.  (But in the past when I did this experiment, it
definitely was rejecting requests.  Maybe that will happen if I let it
run a little longer.)


>>> I don't know how to interpret this data, since I'm not really clear
>>> on what the difference is between "runnable" and "waiting on
>>> condition".
>>
>> "Waiting on condition" means that the thread is asleep, waiting for a
>> notify() signal from another thread telling it to re-attempt a monitor
>> lock (i.e. enter a synchronized block). "Runnable" means that the
>> thread is actually doing something.
>>
>>> Do these numbers seem normal, or are they perhaps giving a clue as
>>> to what the underlying problem might be?
>>
>> If those are production numbers, then you don't look like you have 1%
>> HTTPS traffic -- at least not at the moment you took your thread
>> dump(s). Otherwise, your connector is getting fouled-up. There's
>> another thread this week about weirdness in the NIO connector that
>> sounds somewhat similar, but I doubt the causes are connected. You
>> might want to read that thread just the kicks.
>>
>> - -chris
>> -----BEGIN PGP SIGNATURE-----
>> Version: GnuPG/MacGPG2 v2.0.17 (Darwin)
>> Comment: GPGTools - http://gpgtools.org
>> Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/
>>
>> iEYEARECAAYFAk8CORkACgkQ9CaO5/Lv0PCAUACeJSL6ueAhjdOmiwY0qEF+oLw7
>> xTUAn2nMUUwofRRlJSAX8EYMXw51W2QX
>> =3Dv+SV
>> -----END PGP SIGNATURE-----
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>

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