You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by "Vanga Palli, Ravindra Kumar" <ra...@hp.com> on 2013/05/22 21:46:14 UTC

Enable logging for JIoEndpoint

Hi,

Short question:

I have a simple question, how to ensure JIoEndpoint logs to catalina.log fine when threads are maxed out?
I have read the tomcat logging documentation for tomcat 6.0.28/RHEL6.3.

Long question:

We are using tomcat 6.0.28,  our goal is to figure out are we maxing out on number of threads and I am looking at JIoEndpiont.java source code and found the following code. So, looks like JIoEndpoint logs whenever all the worker threads are busy, if i receive conncurrent connections more than maxThreads in server.xml , i should see this logging message in catalina.out. So, how do i enable the logs for this class org.apache.tomcat.util.net.JIoEndpoint.

if (curThreadsBusy == maxThreads) {
                    log.info(sm.getString("endpoint.info.maxThreads",
                            Integer.toString(maxThreads), address,
                            Integer.toString(port)));
                }

I modified  the following logging file: tomcat/conf/logging.properties, added this entry to this file and bounced the server.

cat /usr/Interwoven/tomcat/conf/logging.properties | grep -A 4 -B 3 JIo
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/host-manager].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/host-manager].handlers = 5host-manager.org.apache.juli.FileHandler

org.apache.tomcat.util.net.JIoEndpoint.level = FINE

# For example, set the com.xyz.foo logger to only log SEVERE
# messages:
#org.apache.catalina.startup.ContextConfig.level = FINE


I also configured the server.xml as follows:

<Connector
                   port="1776"
                   maxThreads="8"
                   threadPriority="MAX_PRIORITY"
                   minSpareThreads="3"
                   maxSpareThreads="5"
                   enableLookups="false"
                   acceptCount="512"
                   debug="0"
                   connectionTimeout="20000"
                   useURIValidationHack="false"
                   disableUploadTimeout="true"
                   URIEncoding="UTF-8"/>

Then, i ran the test as follows which generates 500 concurrent request, as there are only 8 max threads, i should get log message that all threads are busy.

ab -n 1000 -c 500 http://localhost:1776/test.

 In theory i should see the log message if i configured everything correctly. So do you have any idea on what am i missing here. How do i see the logging for JIoEndpoint class ?

Any insights would be helpful.
Thanks,
Ravi

Re: Enable logging for JIoEndpoint

Posted by Christopher Schultz <ch...@christopherschultz.net>.
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

Ravi,

On 5/24/13 4:59 PM, Vanga Palli, Ravindra Kumar wrote:
> I don't think we are using Executor's in our tomcat 6.0.28 server
> configuration. Both of the following stack traces clearly indicate
> that i am not using executors instead I am using JioEndpoint
> 
> I can give two examples from my logs:
> 
> Here is the output of kill -3 <pid> which gives output of thread
> stack traces, this is what i got.
> 
> 
> "http-1776-115" daemon prio=10 tid=0x00007fe0b00dd000 nid=0x6987 in
> Object.wait() [0x00007fe119edd000] java.lang.Thread.State: WAITING
> (on object monitor) at java.lang.Object.wait(Native Method) -
> waiting on <0x00000000e1539d50> (a
> org.apache.tomcat.util.net.JIoEndpoint$Worker) at
> java.lang.Object.wait(Object.java:502) at
> org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416)
>
> 
- - locked <0x00000000e1539d50> (a
org.apache.tomcat.util.net.JIoEndpoint$Worker)
> at
> org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442)
>
> 
at java.lang.Thread.run(Thread.java:679)

Hmm. Yes, it seems that you are not using an executor. I'm not sure
how that's possible as Tomcat 6 is supposed to always use an executor.

Whoops, I was reading the Tomcat 7 documentation. Sorry about that.

I don't have a Tomcat 6.0.x deployment handy to abuse, so it may take
me some time to reproduce this.

- -chris
-----BEGIN PGP SIGNATURE-----
Version: GnuPG/MacGPG2 v2.0.17 (Darwin)
Comment: GPGTools - http://gpgtools.org
Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/

iQIcBAEBCAAGBQJRn9z8AAoJEBzwKT+lPKRYOOoP/1y2lUpboDx+6GvDN8X0GlwU
hzkQKk4oFMqSSSyZktwQWYQB/V3uuWVXUklBUSlHxMBXtjL4+sLraspV1WjaRhuY
BeLxY3kLdrKYqjr7xb1rm4klc49gIB9tUlLPit5dcuXofOFrJOhOoT6hZc2OPY4W
D4X3PGsjXGbS1k0/SqQIG50RBzb3yaqZhMxAAbhf6odlzK/hh6iRVwP/3M9GjVxV
8L2Zl3N9Cd64JlwhfuWreVzTd9LSdJdf/sXU+6+dIRBnphv4HKnrH10Iwqc6CRak
QYBxbvqq+Im7zgLDgLdTX7M2+38ThsE3eHk4IMoP0ABZpCga1gBjHsfJcHo/sHUc
tNySBsz/zsYlEC/Z2arKZPwxKPfhlBUa+nEJBop8LkgHbpkNs9GcnaImKJkcCe57
63hv1+3vnyGnSMotTozbUaqCzcinFgDdP6Xtce0P4YnT0+Gp5nTFyhchCAWvyfQk
dBgMxyPzWVqkbSMc6oLfSSwHkyPa0HhF1rqT//RnJkk4JGG9Hr+FTZeB0BG7tfjM
40AlyVnsrP7VX7wZlpbUBskMG1M/AnAFz7IIkQAc57ZEVtBi5m2Wl+Fspr3YsVDy
HD3KNMGbI2AZQB2CXpCpUSiq/AOsBku0bQQy56ZTZ/SrvH4qQUzSq/CRmOPU3sZl
wx9X8ke6W5pDs5EPEsZa
=U8th
-----END PGP SIGNATURE-----

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


RE: Enable logging for JIoEndpoint

Posted by "Vanga Palli, Ravindra Kumar" <ra...@hp.com>.
Chris,

I don't think we are using Executor's in our tomcat 6.0.28 server configuration. Both of the following stack traces clearly indicate that i am not using executors instead I am using JioEndpoint 

I can give two examples from my logs:

 Here is the output of kill -3 <pid> which gives output of thread stack traces, this is what i got. 


"http-1776-115" daemon prio=10 tid=0x00007fe0b00dd000 nid=0x6987 in Object.wait() [0x00007fe119edd000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x00000000e1539d50> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
        at java.lang.Object.wait(Object.java:502)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416)
        - locked <0x00000000e1539d50> (a org.apache.tomcat.util.net.JIoEndpoint$Worker)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442)
        at java.lang.Thread.run(Thread.java:679)

A runtime exception stack trace..

*********CHOPPED OFFFF APPLICATION STACK RACE************************
 at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        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:191)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:568)
        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:845)
        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:679)


Thanks,
Ravi
________________________________________
From: Christopher Schultz [chris@christopherschultz.net]
Sent: Thursday, May 23, 2013 8:28 AM
To: Tomcat Users List
Subject: Re: Enable logging for JIoEndpoint

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

Ravi,

On 5/22/13 3:46 PM, Vanga Palli, Ravindra Kumar wrote:
> I have a simple question, how to ensure JIoEndpoint logs to
> catalina.log fine when threads are maxed out?
>
> I have read the tomcat logging documentation for tomcat
> 6.0.28/RHEL6.3.
>
> Long question:
>
> We are using tomcat 6.0.28, our goal is to figure out are we
> maxing out on number of threads and I am looking at
> JIoEndpiont.java source code and found the following code. So,
> looks like JIoEndpoint logs whenever all the worker threads are
> busy, if i receive conncurrent connections more than maxThreads in
> server.xml , i should see this logging message in catalina.out. So,
> how do i enable the logs for this class
> org.apache.tomcat.util.net.JIoEndpoint.
>
> if (curThreadsBusy == maxThreads) {
> log.info(sm.getString("endpoint.info.maxThreads",
> Integer.toString(maxThreads), address, Integer.toString(port))); }
>
> I modified  the following logging file:
> tomcat/conf/logging.properties, added this entry to this file and
> bounced the server.
>
> cat /usr/Interwoven/tomcat/conf/logging.properties | grep -A 4 -B 3
> JIo
> org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/host-manager].level
> = INFO
> org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/host-manager].handlers
> = 5host-manager.org.apache.juli.FileHandler
>
> org.apache.tomcat.util.net.JIoEndpoint.level = FINE
>
> # For example, set the com.xyz.foo logger to only log SEVERE #
> messages: #org.apache.catalina.startup.ContextConfig.level = FINE
>
>
> I also configured the server.xml as follows:
>
> <Connector port="1776" maxThreads="8"
> threadPriority="MAX_PRIORITY" minSpareThreads="3"
> maxSpareThreads="5" enableLookups="false" acceptCount="512"
> debug="0" connectionTimeout="20000" useURIValidationHack="false"
> disableUploadTimeout="true" URIEncoding="UTF-8"/>
>
> Then, i ran the test as follows which generates 500 concurrent
> request, as there are only 8 max threads, i should get log message
> that all threads are busy.
>
> ab -n 1000 -c 500 http://localhost:1776/test.
>
> In theory i should see the log message if i configured everything
> correctly. So do you have any idea on what am i missing here. How
> do i see the logging for JIoEndpoint class ?
>
> Any insights would be helpful.

Thank you for asking a question with complete details!

I can confirm when setting:

org.apache.tomcat.util.net.JIoEndpoint.level=FINE

I get no output in catalina.out when I clearly should have reached
maxThreads.

I also tried:

org.apache.tomcat.level=FINE

...which gives me an incredible amount of output, but searching for
"threads " finds nothing. I was using Tomcat 7.0.39 which is quite
different but I suspect that the problem might be the same between
both versions.

I'll bet that you are using an "executor", whether you know it or not.
I checked, and the StandardThreadExecutor class (in 6.0.x) has no
logging whatsoever. Sure enough, the ThreadPoolExecutor in 7.0.x also
has (virtually) no logging.

So, I suspect you will not be able to get this kind of information
sent to the log file. Instead, you'll have to obtain it through other
means (e.g. JMX).

I'm not sure why JIoEndpoint contains all of the code it does, as
IIRC, Tomcat 6 switched-over to using Executors for all thread
management, even if you don't define one yourself using <Executor>.
Tomcat 7's JIoEndpoint has none of the thread-management code that
still exists in Tomcat 6, so I suspect it has simply been deprecated
in 6.0 and removed entirely in 7.0.

- -chris
-----BEGIN PGP SIGNATURE-----
Version: GnuPG/MacGPG2 v2.0.17 (Darwin)
Comment: GPGTools - http://gpgtools.org
Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/

iQIcBAEBCAAGBQJRnjW6AAoJEBzwKT+lPKRYntwP/R89LI8anb5rXjRA9Eb005I4
1LXoclPKY4XjAIqpW+Y8Egjat1WDCBNXEqJE0fo2IVwA8rEiOmFZiuK/YGNywcWm
O8jDrbs8AbURMP1lHFTnuepLzKObIcr4mGvu3FMhthOimv8CHJtfAtVsc6e/1Di9
J/LfyDMdptOl9JEbit+qNiUVDbRDCst8Xj4hi9bnWNtB5KSCFXcA3DxKIsHueCeH
/GRHrBXBemsjXUu+HvW5UGTNdF5fgnt9a/cKT5iuwTd7wgQJYiOIeHXNKvFTrkZQ
tjMaKvlvCWT+9ZqHOUU5irvntHgnGOQTP6nu5RiVq482kwVHyysyBpy3aE7rI+48
qLRzc7831a9hbh2v5nREQ7jkj5J1Q7pDtJs4F2UKIxVPfK0OyegaqjOM6IxDp12p
QON9S9TeedC9c+r0HIoBwhR19qhwdEM40Xx7DLQW1Hmr0KAyOfSFBV1ZRIfWwc7m
cetoEdkFuor/CxYdtvYYvaEYG1x48LY9hAoJkZBYFp7m8vjc02AJgassqlxVijHF
qp4fHX2CaemOHOg6x+q5mDwZJpvyRNe5h2zkyU4k0HAo4wnEi1+QZ06yBQzju3QW
aIR7+/w2ZeGieddpZuJjkcCIxoZueTPgT4upTQKR3mdtVq7uMox+QMMj4ZKtHcLq
RgogWtxUA9BBy9cASzdF
=gDxl
-----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


Re: Enable logging for JIoEndpoint

Posted by Christopher Schultz <ch...@christopherschultz.net>.
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

Ravi,

On 5/22/13 3:46 PM, Vanga Palli, Ravindra Kumar wrote:
> I have a simple question, how to ensure JIoEndpoint logs to 
> catalina.log fine when threads are maxed out?
> 
> I have read the tomcat logging documentation for tomcat 
> 6.0.28/RHEL6.3.
> 
> Long question:
> 
> We are using tomcat 6.0.28, our goal is to figure out are we
> maxing out on number of threads and I am looking at
> JIoEndpiont.java source code and found the following code. So,
> looks like JIoEndpoint logs whenever all the worker threads are
> busy, if i receive conncurrent connections more than maxThreads in
> server.xml , i should see this logging message in catalina.out. So,
> how do i enable the logs for this class
> org.apache.tomcat.util.net.JIoEndpoint.
> 
> if (curThreadsBusy == maxThreads) { 
> log.info(sm.getString("endpoint.info.maxThreads", 
> Integer.toString(maxThreads), address, Integer.toString(port))); }
> 
> I modified  the following logging file: 
> tomcat/conf/logging.properties, added this entry to this file and 
> bounced the server.
> 
> cat /usr/Interwoven/tomcat/conf/logging.properties | grep -A 4 -B 3
> JIo 
> org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/host-manager].level
> = INFO 
> org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/host-manager].handlers
> = 5host-manager.org.apache.juli.FileHandler
> 
> org.apache.tomcat.util.net.JIoEndpoint.level = FINE
> 
> # For example, set the com.xyz.foo logger to only log SEVERE #
> messages: #org.apache.catalina.startup.ContextConfig.level = FINE
> 
> 
> I also configured the server.xml as follows:
> 
> <Connector port="1776" maxThreads="8" 
> threadPriority="MAX_PRIORITY" minSpareThreads="3" 
> maxSpareThreads="5" enableLookups="false" acceptCount="512" 
> debug="0" connectionTimeout="20000" useURIValidationHack="false" 
> disableUploadTimeout="true" URIEncoding="UTF-8"/>
> 
> Then, i ran the test as follows which generates 500 concurrent 
> request, as there are only 8 max threads, i should get log message
> that all threads are busy.
> 
> ab -n 1000 -c 500 http://localhost:1776/test.
> 
> In theory i should see the log message if i configured everything 
> correctly. So do you have any idea on what am i missing here. How
> do i see the logging for JIoEndpoint class ?
> 
> Any insights would be helpful.

Thank you for asking a question with complete details!

I can confirm when setting:

org.apache.tomcat.util.net.JIoEndpoint.level=FINE

I get no output in catalina.out when I clearly should have reached
maxThreads.

I also tried:

org.apache.tomcat.level=FINE

...which gives me an incredible amount of output, but searching for
"threads " finds nothing. I was using Tomcat 7.0.39 which is quite
different but I suspect that the problem might be the same between
both versions.

I'll bet that you are using an "executor", whether you know it or not.
I checked, and the StandardThreadExecutor class (in 6.0.x) has no
logging whatsoever. Sure enough, the ThreadPoolExecutor in 7.0.x also
has (virtually) no logging.

So, I suspect you will not be able to get this kind of information
sent to the log file. Instead, you'll have to obtain it through other
means (e.g. JMX).

I'm not sure why JIoEndpoint contains all of the code it does, as
IIRC, Tomcat 6 switched-over to using Executors for all thread
management, even if you don't define one yourself using <Executor>.
Tomcat 7's JIoEndpoint has none of the thread-management code that
still exists in Tomcat 6, so I suspect it has simply been deprecated
in 6.0 and removed entirely in 7.0.

- -chris
-----BEGIN PGP SIGNATURE-----
Version: GnuPG/MacGPG2 v2.0.17 (Darwin)
Comment: GPGTools - http://gpgtools.org
Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/

iQIcBAEBCAAGBQJRnjW6AAoJEBzwKT+lPKRYntwP/R89LI8anb5rXjRA9Eb005I4
1LXoclPKY4XjAIqpW+Y8Egjat1WDCBNXEqJE0fo2IVwA8rEiOmFZiuK/YGNywcWm
O8jDrbs8AbURMP1lHFTnuepLzKObIcr4mGvu3FMhthOimv8CHJtfAtVsc6e/1Di9
J/LfyDMdptOl9JEbit+qNiUVDbRDCst8Xj4hi9bnWNtB5KSCFXcA3DxKIsHueCeH
/GRHrBXBemsjXUu+HvW5UGTNdF5fgnt9a/cKT5iuwTd7wgQJYiOIeHXNKvFTrkZQ
tjMaKvlvCWT+9ZqHOUU5irvntHgnGOQTP6nu5RiVq482kwVHyysyBpy3aE7rI+48
qLRzc7831a9hbh2v5nREQ7jkj5J1Q7pDtJs4F2UKIxVPfK0OyegaqjOM6IxDp12p
QON9S9TeedC9c+r0HIoBwhR19qhwdEM40Xx7DLQW1Hmr0KAyOfSFBV1ZRIfWwc7m
cetoEdkFuor/CxYdtvYYvaEYG1x48LY9hAoJkZBYFp7m8vjc02AJgassqlxVijHF
qp4fHX2CaemOHOg6x+q5mDwZJpvyRNe5h2zkyU4k0HAo4wnEi1+QZ06yBQzju3QW
aIR7+/w2ZeGieddpZuJjkcCIxoZueTPgT4upTQKR3mdtVq7uMox+QMMj4ZKtHcLq
RgogWtxUA9BBy9cASzdF
=gDxl
-----END PGP SIGNATURE-----

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