Re: Performance degrades on tomcat7 for the same runs of a sample performance 60 user test
Dimple, On 11/9/15 3:46 AM, dimple ranka wrote: > Some help is really appreciated, atleast it will be good to hear if some > one else is also facing slowness with the tomcat7 server. > > I did some more investigation here and as mentioned earlier saw the > slowness with tomcat7 is more reproducible when there are some > cryptographic signature verifications. I was going to ask about the crypto. One of the only threads actually doing anything in the thread dump you showed was showing a TLS handshake. Java's crypto is not very fast compared to native crypto. IF you are handling TLS from Tomcat, you might want to consider a faster solution if you do a lot of transactions. If you have a shortage of entropy on the server, generating new crypto keys can really slow things down. That could certainly explain the "first run is fast, later runs are slower" observation. But this has absolutely nothing to do with Tomcat -- it's all within the JVM so you shouldn't have noticed a change with a Tomcat upgrade. > Turning on the StuckThreadDetectionValve with 1 second threshold as > shown below revealed that there are warning logs with threads stuck > showing up in the next run of the test. This clearly shows that the > slowness is due to the threads getting into the blocked state. More > are in the signature verification but few are in other areas too. > > className="org.apache.catalina.valves.StuckThreadDetectionValve" > threshold="1" /> > > NOTE - the above test was performed on a low end windows machine. Since the > granularity of the valve threshold is in seconds was finding it hard to > reproduce the valve to spit out some logs on the high end server. But the > test shows that in the second run of the performance test which was run on > another machine, only then i see the warning logs on the tomcat server. > > [snip] > > WARNING: Thread "http-nio-8443-exec-55" (id=83) has been active for 1,397 > milliseconds (since 11/7/15 11:06 AM) to serve the same request for > https://10.55.198.52:8443/Signature/authenticate and may be stuck > (configured threshold for this StuckThreadDetectionValve is 1 seconds). > There is/are 1 thread(s) in total that are monitored by this Valve and may > be stuck. > java.lang.Throwable > at sun.security.ec.ECDSASignature.verifySignedDigest(Native Method) > at sun.security.ec.ECDSASignature.engineVerify(ECDSASignature.java:309) > at java.security.Signature$Delegate.engineVerify(Signature.java:1192) > at java.security.Signature.verify(Signature.java:626) > at signature.SignatureEndPoint.verifyECDSASignature(Unknown Source) > at signature.SignatureEndPoint.verifySignature(Unknown Source) > at sun.reflect.GeneratedMethodAccessor51.invoke(Unknown Source) > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > at java.lang.reflect.Method.invoke(Method.java:606) > at > com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60) > at > com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$ResponseOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:205) > at > com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75) > at > com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302) > at > com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108) > at > com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147) > at > com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84) > at > com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1511) > at > com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1442) > at > com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1391) > at > com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1381) > at > com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416) > at > com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:538) > at > com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:716) > at javax.servlet.http.HttpServlet.service(HttpServlet.java:731) > at > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) > at > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) > at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) > at > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) > at > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) > at >
Re: Performance degrades on tomcat7 for the same runs of a sample performance 60 user test
On Mon, Nov 9, 2015 at 8:34 PM, Christopher Schultz < ch...@christopherschultz.net> wrote: > Dimple, > > On 11/9/15 3:46 AM, dimple ranka wrote: > > Some help is really appreciated, atleast it will be good to hear if some > > one else is also facing slowness with the tomcat7 server. > > > > I did some more investigation here and as mentioned earlier saw the > > slowness with tomcat7 is more reproducible when there are some > > cryptographic signature verifications. > > I was going to ask about the crypto. One of the only threads actually > doing anything in the thread dump you showed was showing a TLS > handshake. Java's crypto is not very fast compared to native crypto. IF > you are handling TLS from Tomcat, you might want to consider a faster > solution if you do a lot of transactions. > > If you have a shortage of entropy on the server, generating new crypto > keys can really slow things down. That could certainly explain the > "first run is fast, later runs are slower" observation. But this has > absolutely nothing to do with Tomcat -- it's all within the JVM so you > shouldn't have noticed a change with a Tomcat upgrade. > > ==> We have configured the secure random source as below to avoid the entropy issue - securerandom.source=file:/dev/./urandom > Turning on the StuckThreadDetectionValve with 1 second threshold as > > shown below revealed that there are warning logs with threads stuck > > showing up in the next run of the test. This clearly shows that the > > slowness is due to the threads getting into the blocked state. More > > are in the signature verification but few are in other areas too. > > > > > className="org.apache.catalina.valves.StuckThreadDetectionValve" > > threshold="1" /> > > > > NOTE - the above test was performed on a low end windows machine. Since > the > > granularity of the valve threshold is in seconds was finding it hard to > > reproduce the valve to spit out some logs on the high end server. But the > > test shows that in the second run of the performance test which was run > on > > another machine, only then i see the warning logs on the tomcat server. > > > > [snip] > > > > > WARNING: Thread "http-nio-8443-exec-55" (id=83) has been active for 1,397 > > milliseconds (since 11/7/15 11:06 AM) to serve the same request for > > https://10.55.198.52:8443/Signature/authenticate and may be stuck > > (configured threshold for this StuckThreadDetectionValve is 1 seconds). > > There is/are 1 thread(s) in total that are monitored by this Valve and > may > > be stuck. > > java.lang.Throwable > > at sun.security.ec.ECDSASignature.verifySignedDigest(Native Method) > > at sun.security.ec.ECDSASignature.engineVerify(ECDSASignature.java:309) > > at java.security.Signature$Delegate.engineVerify(Signature.java:1192) > > at java.security.Signature.verify(Signature.java:626) > > at signature.SignatureEndPoint.verifyECDSASignature(Unknown Source) > > at signature.SignatureEndPoint.verifySignature(Unknown Source) > > at sun.reflect.GeneratedMethodAccessor51.invoke(Unknown Source) > > at > > > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > > at java.lang.reflect.Method.invoke(Method.java:606) > > at > > > com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60) > > at > > > com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$ResponseOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:205) > > at > > > com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75) > > at > > > com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302) > > at > > > com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108) > > at > > > com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147) > > at > > > com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84) > > at > > > com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1511) > > at > > > com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1442) > > at > > > com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1391) > > at > > > com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1381) > > at > > > com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416) > > at > > > com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:538) > > at > > > com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:716) > > at javax.servlet.http.HttpServlet.service(HttpServlet.java:731) > > at > > > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) >
Re: Performance degrades on tomcat7 for the same runs of a sample performance 60 user test
Hi all, Some help is really appreciated, atleast it will be good to hear if some one else is also facing slowness with the tomcat7 server. I did some more investigation here and as mentioned earlier saw the slowness with tomcat7 is more reproducible when there are some cryptographic signature verifications. Turning on the StuckThreadDetectionValve with 1 second threshold as shown below revealed that there are warning logs with threads stuck showing up in the next run of the test. This clearly shows that the slowness is due to the threads getting into the blocked state. More are in the signature verification but few are in other areas too. NOTE - the above test was performed on a low end windows machine. Since the granularity of the valve threshold is in seconds was finding it hard to reproduce the valve to spit out some logs on the high end server. But the test shows that in the second run of the performance test which was run on another machine, only then i see the warning logs on the tomcat server. CATALINA.out contents showing the stuck threads ===> Nov 07, 2015 11:01:13 AM org.apache.catalina.startup.HostConfig undeploy INFO: Undeploying context [/host-manager] Nov 07, 2015 11:01:13 AM org.apache.catalina.startup.HostConfig undeploy INFO: Undeploying context [/docs] Nov 07, 2015 11:01:13 AM org.apache.catalina.startup.HostConfig undeploy INFO: Undeploying context [] Nov 07, 2015 11:01:13 AM org.apache.catalina.startup.HostConfig undeploy INFO: Undeploying context [/Signature] Nov 07, 2015 11:01:13 AM org.apache.catalina.startup.HostConfig undeploy INFO: Undeploying context [/examples] Nov 07, 2015 11:01:13 AM org.apache.catalina.startup.HostConfig undeploy INFO: Undeploying context [/manager] Nov 07, 2015 11:01:13 AM org.apache.catalina.startup.HostConfig deployWAR INFO: Deploying web application archive D:\apache-tomcat-7.0.64\webapps\Signature.war Nov 07, 2015 11:01:16 AM org.apache.catalina.startup.TldConfig execute INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time. Nov 07, 2015 11:01:17 AM com.sun.jersey.api.core.servlet.WebAppResourceConfig init INFO: Scanning for root resource and provider classes in the Web app resource paths: /WEB-INF/lib /WEB-INF/classes Nov 07, 2015 11:01:18 AM com.sun.jersey.api.core.ScanningResourceConfig logClasses INFO: Root resource classes found: class signature.NullEndPoint class signature.SignatureEndPoint Nov 07, 2015 11:01:18 AM com.sun.jersey.api.core.ScanningResourceConfig logClasses INFO: Provider classes found: class org.codehaus.jackson.jaxrs.JsonMappingExceptionMapper class org.codehaus.jackson.jaxrs.JacksonJaxbJsonProvider class org.codehaus.jackson.jaxrs.JacksonJsonProvider class org.codehaus.jackson.jaxrs.JsonParseExceptionMapper Nov 07, 2015 11:01:18 AM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate INFO: Initiating Jersey application, version 'Jersey: 1.17 01/17/2013 03:31 PM' Nov 07, 2015 11:01:19 AM org.apache.catalina.startup.HostConfig deployWAR INFO: Deployment of web application archive D:\apache-tomcat-7.0.64\webapps\Signature.war has finished in 5,871 ms Nov 07, 2015 11:01:19 AM org.apache.catalina.startup.HostConfig deployDirectory INFO: Deploying web application directory D:\apache-tomcat-7.0.64\webapps\docs Nov 07, 2015 11:01:19 AM org.apache.catalina.startup.TldConfig execute INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time. Nov 07, 2015 11:01:19 AM org.apache.catalina.startup.HostConfig deployDirectory INFO: Deployment of web application directory D:\apache-tomcat-7.0.64\webapps\docs has finished in 140 ms Nov 07, 2015 11:01:19 AM org.apache.catalina.startup.HostConfig deployDirectory INFO: Deploying web application directory D:\apache-tomcat-7.0.64\webapps\examples Nov 07, 2015 11:01:19 AM org.apache.catalina.startup.TldConfig execute INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time. Nov 07, 2015 11:01:19 AM org.apache.catalina.startup.HostConfig deployDirectory INFO: Deployment of web application directory D:\apache-tomcat-7.0.64\webapps\examples has finished in 445 ms Nov 07, 2015 11:01:19 AM org.apache.catalina.startup.HostConfig deployDirectory INFO: Deploying web application directory D:\apache-tomcat-7.0.64\webapps\host-manager Nov 07, 2015 11:01:19 AM org.apache.catalina.startup.TldConfig execute INFO: At least one JAR was scanned for
