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. > > <Valve > 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 > org.apache.logging.log4j.core.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:66) > at > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) > at > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) > at > org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) > at > org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) > at > org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:614) > at > org.apache.catalina.valves.StuckThreadDetectionValve.invoke(StuckThreadDetectionValve.java:221) > at > org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170) > at > org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) > at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:956) > at > org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) > at > org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:423) > at > org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1079) > at > org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625) > at > org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1760) > at > org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1719) > at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at > org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) > at java.lang.Thread.run(Thread.java:745) This wasn't one of the threads in your original thread dump. The other one was a TLS handshake. This one is ... something else -- I'm not sure. What kind of crypto signature verification is Jersey doing? > WARNING: Thread "http-nio-8443-exec-55" (id=83) was previously reported to > be stuck but has completed. It was active for approximately 1,468 > milliseconds. > Nov 07, 2015 11:08:41 AM > org.apache.catalina.valves.StuckThreadDetectionValve > notifyStuckThreadDetected > WARNING: Thread "http-nio-8443-exec-20" (id=48) has been active for 1,221 > milliseconds (since 11/7/15 11:08 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 > org.apache.logging.log4j.core.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:66) > at > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) > at > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) > at > org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) > at > org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) > at > org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:614) > at > org.apache.catalina.valves.StuckThreadDetectionValve.invoke(StuckThreadDetectionValve.java:221) > at > org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170) > at > org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) > at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:956) > at > org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) > at > org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:423) > at > org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1079) > at > org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625) > at > org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1760) > at > org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1719) > at > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at > org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) > at java.lang.Thread.run(Thread.java:745) Okay, do the rest look like this? Reading stack traces isn't exactly fun for us. > WARNING: Thread "http-nio-8443-exec-42" (id=70) has been active for 1,942 > milliseconds (since 11/7/15 11:09 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 2 thread(s) in total that are monitored by this Valve and may > be stuck. > java.lang.Throwable > at java.io.BufferedWriter.<init>(BufferedWriter.java:105) > at java.io.BufferedWriter.<init>(BufferedWriter.java:88) > at > com.sun.jersey.core.util.ReaderWriter.writeToAsString(ReaderWriter.java:188) This thread is writing, but it may have been "stuck" earlier in a crypto operation and only now being reported. > Nov 07, 2015 11:09:16 AM > org.apache.catalina.valves.StuckThreadDetectionValve > notifyStuckThreadDetected > WARNING: Thread "http-nio-8443-exec-71" (id=99) has been active for 1,024 > milliseconds (since 11/7/15 11:09 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 3 thread(s) in total that are monitored by this Valve and may > be stuck. > java.lang.Throwable > at java.util.Arrays.copyOfRange(Arrays.java:2694) > at java.lang.String.<init>(String.java:203) > at java.lang.String.substring(String.java:1913) > at java.net.URI$Parser.substring(URI.java:2850) > at java.net.URI$Parser.parseServer(URI.java:3228) > at java.net.URI$Parser.parseAuthority(URI.java:3136) > at java.net.URI$Parser.parseHierarchical(URI.java:3078) > at java.net.URI$Parser.parse(URI.java:3034) > at java.net.URI.<init>(URI.java:595) > at com.sun.jersey.api.uri.UriBuilderImpl.createURI(UriBuilderImpl.java:721) > at com.sun.jersey.api.uri.UriBuilderImpl._build(UriBuilderImpl.java:651) > at com.sun.jersey.api.uri.UriBuilderImpl.build(UriBuilderImpl.java:641) Same here: building a URI probably isn't taking a great deal of time (unless the source String is enormous). > Nov 07, 2015 11:09:16 AM > org.apache.catalina.valves.StuckThreadDetectionValve > notifyStuckThreadDetected > WARNING: Thread "http-nio-8443-exec-17" (id=45) has been active for 1,666 > milliseconds (since 11/7/15 11:09 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 4 thread(s) in total that are monitored by this Valve and may > be stuck. > java.lang.Throwable > at java.io.BufferedWriter.<init>(BufferedWriter.java:105) > at java.io.BufferedWriter.<init>(BufferedWriter.java:88) Etc. > Nov 07, 2015 11:09:17 AM > org.apache.catalina.valves.StuckThreadDetectionValve > notifyStuckThreadDetected > WARNING: Thread "http-nio-8443-exec-30" (id=58) has been active for 1,647 > milliseconds (since 11/7/15 11:09 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 5 thread(s) in total that are monitored by this Valve and may > be stuck. > java.lang.Throwable > at java.io.BufferedWriter.<init>(BufferedWriter.java:105) > at java.io.BufferedWriter.<init>(BufferedWriter.java:88) Another one. > WARNING: Thread "http-nio-8443-exec-36" (id=64) has been active for 1,674 > milliseconds (since 11/7/15 11:09 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 6 thread(s) in total that are monitored by this Valve and may > be stuck. > java.lang.Throwable > at java.nio.HeapByteBuffer.<init>(HeapByteBuffer.java:57) > at java.nio.ByteBuffer.allocate(ByteBuffer.java:331) > at sun.nio.cs.StreamEncoder.<init>(StreamEncoder.java:195) > at sun.nio.cs.StreamEncoder.<init>(StreamEncoder.java:175) > at sun.nio.cs.StreamEncoder.forOutputStreamWriter(StreamEncoder.java:68) Okay, I'm not reading any more of these. I think what you need to do is instrument with a profiler and find out what methods are actually taking the most time. Looking at stack traces is only useful if they are telling a consistent story, and these are only getting you *some* information. A profile will give you the hot spots and let you decide what to do about them. If it turns out Tomcat is the problem (which is unlikely), we'd be happy to investigate any performance problems that might exist. -chris --------------------------------------------------------------------- To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
