Re: Logging Information when Tomcat reaches max thread limit
Hello Aquib, On Mon, Nov 2, 2020 at 10:09 AM Aquib Khan wrote: > > Hi, > > We have a usecase where we want that our application should indicate when it > reaches maximum thread limit. Our application is deployed in tomcat. Maximum > thread limit of tomcat is 200, so If 200 threads are reached, does tomcat > provide any logger information? > As far as I know, there is no logging which will tell you that the thread pool got exhausted but I am pretty sure your application will react to it by throwing connection related exception as you mentioned below. > We tried making multiple rest calls and reducing max threads to 2-3. We faced > ConnectionRefused and socketTimeout Exceptions on client side. But no > exception or logger in Catalina logs. We changed Logging level as well in > logging.properties. > > We tried Changing values of maxThreads, minspareThread, acceptCount in > server.xml. We used Jmeter for making rest calls. > > Can we get any help here? Does tomcat provides any information when it > reaches max thread limit? Do we have to change any property in server.xml or > in logging.properties > Tomcat exposes different thread pool properties via JMX which are available under JMX Object Name:"Catalina:type=ThreadPool". I think in your case "currentThreadCount" and "currentThreadsBusy" will be helpful. "currentThreadCount" will give you thread pool size. "currentThreadsBusy" will tell you how many threads are busy processing requests. Normally if the "currentThreadsBusy" count goes up then it indicates either you have thread blocking or lots of requests are coming in. Based on those numbers, you need to decide on the thread pool size. There are more properties and operations exposed via JMX. You can explore all of them by using jconsole or JMC. If you have any Application Performance Management(APM) tool like AppDynamics, Dynatrace, New Relic etc. it will make your life a bit easier. Those tools usually can throw alerts if thread pool utilization is high and based on which you can act. > Any help in this regard would be highly appreciable. > Thanks in Advance. > > Regards, > Aquib - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
RE: Weirdest Tomcat Behavior Ever?
> -Original Message- > From: Mark Thomas > Sent: Sunday, November 1, 2020 11:50 AM > To: users@tomcat.apache.org > Subject: Re: Weirdest Tomcat Behavior Ever? > > On 01/11/2020 16:25, Mark Thomas wrote: > > > > > > Keeping the previous logs for reference: > > > >>> Source Time Activity > >>> > >>> pcap15:14:25.375451 SYN proxy to Tomcat > >>> pcap15:14:25.375493 SYN, ACK Tomcat to proxy > >>> pcap15:14:25.375839 ACK proxy to Tomcat > >>> pcap15:14:25.375892 GET request proxy to Tomcat > >>> pcap15:14:25.375911 ACK Tomcat to proxy > >>> debug 15:14:25.376 o.a.c.http11.InternalOutputBuffer.init > >>> pcap15:14:25.376777 FIN Tomcat to proxy > >>> pcap15:14:25.377036 FIN, ACK proxy to Tomcat > >>> pcap15:14:25.377048 ACK Tomcat proxy > >>> debug 15:14:25.383 o.a.c.http11.InternalOutputBuffer.commit > >>> debug 15:14:25.383 o.a.c.http11.InternalOutputBuffer$1.doWrite > >>> debug 15:14:25.383 o.a.c.http11.InternalOutputBuffer$1.nextRequest > >>> debug 15:14:25.383 o.a.c.http11.InternalOutputBuffer$1.recycle > >>> > >>> Tomcat writes the request body to the buffer but when Tomcat tries > >>> to flush those bytes out to the network it finds that the socket has > >>> been closed. That normally indicates that the client has dropped the > >>> connection. This is sufficiently common that Tomcat swallows the > >>> exception. However, we know (from the pcap file) that the client did > >>> not drop the connection, Tomcat did. > > > > The next round of logging added a little more detail for the > > InternalOutputBuffer and wrapped the Socket to see when close() was > called. > > > > The results from the next round of logging are: > > > > Source Time Activity > > > > pcap13:31:26.344453 SYN proxy to Tomcat > > pcap13:31:26.344481 SYN, ACK Tomcat to proxy > > debug 13:31:26.345 DebugSocket object created > > debug 13:31:26.345 o.a.c.http11.InternalOutputBuffer.init > > pcap13:31:26.345138 ACK proxy to Tomcat > > pcap13:31:26.345174 GET request proxy to Tomcat > > pcap13:31:26.345194 ACK Tomcat to proxy > > pcap13:31:26.395281 FIN, ACK Tomcat to proxy > > pcap13:31:26.395725 ACK proxy to Tomcat > > pcap13:31:26.395741 FIN, ACK proxy to Tomcat > > pcap13:31:26.395754 ACK Tomcat to proxy > > debug 13:31:26.403 o.a.c.http11.InternalOutputBuffer.commit > > debug 13:31:26.403 o.a.c.http11.InternalOutputBuffer$1.doWrite > > debug 13:31:26.404 o.a.c.http11.InternalOutputBuffer$1.nextRequest > > debug 13:31:26.404 o.a.c.http11.InternalOutputBuffer$1.recycle > > debug 13:31:26.404 DebugSocket.close called > > > > This shows that the socket is closed long before Tomcat tries to write > > to it (that would be after the doWrite but before nextRequest) or > > Tomcat explicitly closes the socket. > > > > This also shows that neither Tomcat nor the application are directly > > calling close() on the socket to trigger the close shown by pcap. > > > > I continue to come up with theories as to what might be happening but > > they all seem unlikely. > > > > This is the BIO connector so the only time the socket should change > > state is during a method call. While it might seem a little over the > > top I think the next step is to log every single method call to > > DebugSocket along with any exception generated. We need to try and > > correlate the premature socket closure with something in the JVM. If > > there is no correlation to find then we really are into the realm of > > very strange JVM and/or OS bugs. > > > > I'll start work on v3 of the debug patch. > > http://home.apache.org/~markt/dev/v7.0.72-custom-patch-v3/ > > I opted to wrap both the InputStream and OutputStream associated with the > socket and log every method call and every exception thrown. I opted not to > log parameters with the exception of socket timeout since that might be > relevant. > > The debug logs will be noticeably more verbose that last time. Feel free to > adjust the number/size of debug log files as suits your environment. > > Mark > I applied the V3 patch and confirmed that content is being written to debug0.log, but right away I noticed an error recurring repeatedly. See below. 02-Nov-2020 06:17:12.992 FINE [http-bio-3016-exec-1] org.apache.tomcat.util.net.JIoEndpoint$DebugSocket.close bind 02-Nov-2020 06:17:15.634 FINE [http-bio-3016-Acceptor-0] org.apache.tomcat.util.net.JIoEndpoint$DebugSocket. DebugSocket [783035752], inner Socket [1397828144] for client port [52730] 02-Nov-2020 06:17:15.634 FINE [http-bio-3016-Acceptor-0] org.apache.tomcat.util.net.JIoEndpoint$DebugSocket.setSoLinger [783035752] 02-Nov-2020 06:17:15.635 FINE [http-bio-3016-Acceptor-0] org.apache.tomcat.util.net.JIoEndpoint$DebugSocket.setSoTimeout [783035752], timeout [2] 02-N
Re: Weirdest Tomcat Behavior Ever?
On 02/11/2020 11:18, Eric Robinson wrote:
>> -Original Message-
>> From: Mark Thomas
>> Sent: Sunday, November 1, 2020 11:50 AM
>> To: users@tomcat.apache.org
>> Subject: Re: Weirdest Tomcat Behavior Ever?
>>
>> On 01/11/2020 16:25, Mark Thomas wrote:
>>>
>>>
>>> Keeping the previous logs for reference:
>>>
> Source Time Activity
>
> pcap15:14:25.375451 SYN proxy to Tomcat
> pcap15:14:25.375493 SYN, ACK Tomcat to proxy
> pcap15:14:25.375839 ACK proxy to Tomcat
> pcap15:14:25.375892 GET request proxy to Tomcat
> pcap15:14:25.375911 ACK Tomcat to proxy
> debug 15:14:25.376 o.a.c.http11.InternalOutputBuffer.init
> pcap15:14:25.376777 FIN Tomcat to proxy
> pcap15:14:25.377036 FIN, ACK proxy to Tomcat
> pcap15:14:25.377048 ACK Tomcat proxy
> debug 15:14:25.383 o.a.c.http11.InternalOutputBuffer.commit
> debug 15:14:25.383 o.a.c.http11.InternalOutputBuffer$1.doWrite
> debug 15:14:25.383 o.a.c.http11.InternalOutputBuffer$1.nextRequest
> debug 15:14:25.383 o.a.c.http11.InternalOutputBuffer$1.recycle
>
> Tomcat writes the request body to the buffer but when Tomcat tries
> to flush those bytes out to the network it finds that the socket has
> been closed. That normally indicates that the client has dropped the
> connection. This is sufficiently common that Tomcat swallows the
> exception. However, we know (from the pcap file) that the client did
> not drop the connection, Tomcat did.
>>>
>>> The next round of logging added a little more detail for the
>>> InternalOutputBuffer and wrapped the Socket to see when close() was
>> called.
>>>
>>> The results from the next round of logging are:
>>>
>>> Source Time Activity
>>>
>>> pcap13:31:26.344453 SYN proxy to Tomcat
>>> pcap13:31:26.344481 SYN, ACK Tomcat to proxy
>>> debug 13:31:26.345 DebugSocket object created
>>> debug 13:31:26.345 o.a.c.http11.InternalOutputBuffer.init
>>> pcap13:31:26.345138 ACK proxy to Tomcat
>>> pcap13:31:26.345174 GET request proxy to Tomcat
>>> pcap13:31:26.345194 ACK Tomcat to proxy
>>> pcap13:31:26.395281 FIN, ACK Tomcat to proxy
>>> pcap13:31:26.395725 ACK proxy to Tomcat
>>> pcap13:31:26.395741 FIN, ACK proxy to Tomcat
>>> pcap13:31:26.395754 ACK Tomcat to proxy
>>> debug 13:31:26.403 o.a.c.http11.InternalOutputBuffer.commit
>>> debug 13:31:26.403 o.a.c.http11.InternalOutputBuffer$1.doWrite
>>> debug 13:31:26.404 o.a.c.http11.InternalOutputBuffer$1.nextRequest
>>> debug 13:31:26.404 o.a.c.http11.InternalOutputBuffer$1.recycle
>>> debug 13:31:26.404 DebugSocket.close called
>>>
>>> This shows that the socket is closed long before Tomcat tries to write
>>> to it (that would be after the doWrite but before nextRequest) or
>>> Tomcat explicitly closes the socket.
>>>
>>> This also shows that neither Tomcat nor the application are directly
>>> calling close() on the socket to trigger the close shown by pcap.
>>>
>>> I continue to come up with theories as to what might be happening but
>>> they all seem unlikely.
>>>
>>> This is the BIO connector so the only time the socket should change
>>> state is during a method call. While it might seem a little over the
>>> top I think the next step is to log every single method call to
>>> DebugSocket along with any exception generated. We need to try and
>>> correlate the premature socket closure with something in the JVM. If
>>> there is no correlation to find then we really are into the realm of
>>> very strange JVM and/or OS bugs.
>>>
>>> I'll start work on v3 of the debug patch.
>>
>> http://home.apache.org/~markt/dev/v7.0.72-custom-patch-v3/
>>
>> I opted to wrap both the InputStream and OutputStream associated with the
>> socket and log every method call and every exception thrown. I opted not to
>> log parameters with the exception of socket timeout since that might be
>> relevant.
>>
>> The debug logs will be noticeably more verbose that last time. Feel free to
>> adjust the number/size of debug log files as suits your environment.
>>
>> Mark
>>
>
> I applied the V3 patch and confirmed that content is being written to
> debug0.log, but right away I noticed an error recurring repeatedly. See below.
Thanks for getting that done over a weekend. Much appreciated.
Don't worry, the exception isn't an error. It is an exception created
(but not thrown) by the debug code so we can see the call stack when the
socket was closed. It is the result of something like:
log.debug("Message goes here", new Exception());
I was hoping to see some unexpected code calling close() - no luck. All
the calls to close were exactly what I would expect from normal
operations. v3 will provide more insight on the I/O operations. Fingers
cro
RE: Weirdest Tomcat Behavior Ever?
> From: Mark Thomas > Sent: Monday, November 2, 2020 5:38 AM > To: users@tomcat.apache.org > Subject: Re: Weirdest Tomcat Behavior Ever? > > On 02/11/2020 11:18, Eric Robinson wrote: > >> -Original Message- > >> From: Mark Thomas > >> Sent: Sunday, November 1, 2020 11:50 AM > >> To: users@tomcat.apache.org > >> Subject: Re: Weirdest Tomcat Behavior Ever? > >> > >> On 01/11/2020 16:25, Mark Thomas wrote: > >>> > >>> > >>> Keeping the previous logs for reference: > >>> > > Source Time Activity > > > > pcap15:14:25.375451 SYN proxy to Tomcat > > pcap15:14:25.375493 SYN, ACK Tomcat to proxy > > pcap15:14:25.375839 ACK proxy to Tomcat > > pcap15:14:25.375892 GET request proxy to Tomcat > > pcap15:14:25.375911 ACK Tomcat to proxy > > debug 15:14:25.376 o.a.c.http11.InternalOutputBuffer.init > > pcap15:14:25.376777 FIN Tomcat to proxy > > pcap15:14:25.377036 FIN, ACK proxy to Tomcat > > pcap15:14:25.377048 ACK Tomcat proxy > > debug 15:14:25.383 o.a.c.http11.InternalOutputBuffer.commit > > debug 15:14:25.383 o.a.c.http11.InternalOutputBuffer$1.doWrite > > debug 15:14:25.383 > o.a.c.http11.InternalOutputBuffer$1.nextRequest > > debug 15:14:25.383 o.a.c.http11.InternalOutputBuffer$1.recycle > > > > Tomcat writes the request body to the buffer but when Tomcat tries > > to flush those bytes out to the network it finds that the socket > > has been closed. That normally indicates that the client has > > dropped the connection. This is sufficiently common that Tomcat > > swallows the exception. However, we know (from the pcap file) that > > the client did not drop the connection, Tomcat did. > >>> > >>> The next round of logging added a little more detail for the > >>> InternalOutputBuffer and wrapped the Socket to see when close() was > >> called. > >>> > >>> The results from the next round of logging are: > >>> > >>> Source Time Activity > >>> > >>> pcap13:31:26.344453 SYN proxy to Tomcat > >>> pcap13:31:26.344481 SYN, ACK Tomcat to proxy > >>> debug 13:31:26.345 DebugSocket object created > >>> debug 13:31:26.345 o.a.c.http11.InternalOutputBuffer.init > >>> pcap13:31:26.345138 ACK proxy to Tomcat > >>> pcap13:31:26.345174 GET request proxy to Tomcat > >>> pcap13:31:26.345194 ACK Tomcat to proxy > >>> pcap13:31:26.395281 FIN, ACK Tomcat to proxy > >>> pcap13:31:26.395725 ACK proxy to Tomcat > >>> pcap13:31:26.395741 FIN, ACK proxy to Tomcat > >>> pcap13:31:26.395754 ACK Tomcat to proxy > >>> debug 13:31:26.403 o.a.c.http11.InternalOutputBuffer.commit > >>> debug 13:31:26.403 o.a.c.http11.InternalOutputBuffer$1.doWrite > >>> debug 13:31:26.404 o.a.c.http11.InternalOutputBuffer$1.nextRequest > >>> debug 13:31:26.404 o.a.c.http11.InternalOutputBuffer$1.recycle > >>> debug 13:31:26.404 DebugSocket.close called > >>> > >>> This shows that the socket is closed long before Tomcat tries to > >>> write to it (that would be after the doWrite but before nextRequest) > >>> or Tomcat explicitly closes the socket. > >>> > >>> This also shows that neither Tomcat nor the application are directly > >>> calling close() on the socket to trigger the close shown by pcap. > >>> > >>> I continue to come up with theories as to what might be happening > >>> but they all seem unlikely. > >>> > >>> This is the BIO connector so the only time the socket should change > >>> state is during a method call. While it might seem a little over the > >>> top I think the next step is to log every single method call to > >>> DebugSocket along with any exception generated. We need to try and > >>> correlate the premature socket closure with something in the JVM. If > >>> there is no correlation to find then we really are into the realm of > >>> very strange JVM and/or OS bugs. > >>> > >>> I'll start work on v3 of the debug patch. > >> > >> http://home.apache.org/~markt/dev/v7.0.72-custom-patch-v3/ > >> > >> I opted to wrap both the InputStream and OutputStream associated with > >> the socket and log every method call and every exception thrown. I > >> opted not to log parameters with the exception of socket timeout > >> since that might be relevant. > >> > >> The debug logs will be noticeably more verbose that last time. Feel > >> free to adjust the number/size of debug log files as suits your > environment. > >> > >> Mark > >> > > > > I applied the V3 patch and confirmed that content is being written to > debug0.log, but right away I noticed an error recurring repeatedly. See > below. > > Thanks for getting that done over a weekend. Much appreciated. > > Don't worry, the exception isn't an error. It is an exception created (but not > thrown) by the debug code so we can see the c
