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. > > > > <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? > I am sorry but i added crypto signature verification to the sample, here is the source of the end point => package signature; import java.security.InvalidKeyException; import java.security.KeyFactory; import java.security.NoSuchAlgorithmException; import java.security.PublicKey; import java.security.Signature; import java.security.SignatureException; import java.security.spec.InvalidKeySpecException; import java.security.spec.X509EncodedKeySpec; import javax.ws.rs.Consumes; import javax.ws.rs.POST; import javax.ws.rs.Path; import javax.ws.rs.Produces; import javax.ws.rs.core.MediaType; import javax.ws.rs.core.Response; import javax.ws.rs.core.Response.Status; @Path("/authenticate") public class SignatureEndPoint { public static final String UTF_8 = "UTF-8"; public static final String JSON_CONTENT_TYPE = MediaType.APPLICATION_JSON + "; charset=" + UTF_8; private static byte[] pubKey = { 48, 89, 48, 19, 6, 7, 42, -122, 72, -50, 61, 2, 1, 6, 8, 42, -122, 72, -50, 61, 3, 1, 7, 3, 66, 0, 4, -118, 97, 58, -75, 1, 66, 68, 102, 71, -94, 34, -8, 8, -120, -43, -29, 12, -85, 98, -118, 32, -90, -48, 4, 42, -113, 105, -68, -84, 100, 105, 80, -23, 47, 97, 63, -68, -25, 31, -65, 126, -116, -102, -25, 102, 120, 122, -119, -38, 111, 91, 112, 29, 82, -3, -81, 56, 82, -89, 28, 37, -45, -111, 99 }; private static byte[] signedData = { 4, 62, -78, 0, 15, 46, 32, 0, -41, -117, -97, -12, 114, 91, -121, -68, 80, -100, -107, -27, 11, -63, -10, 2, -127, 85, -65, -116, 2, 114, -37, 14, 91, -61, -58, -63, 4, 121, 45, -7, 11, 46, 9, 0, 65, 66, 67, 68, 35, 65, 66, 67, 68, 16, 46, 0, 0, 14, 46, 5, 0, 1, 0, 1, 2, 0, 10, 46, 32, 0, -106, 122, -79, 27, 114, -30, -22, -59, -74, 108, 12, 119, 45, 78, 123, -94, 31, 24, 56, -90, 107, -25, -76, 77, -25, 48, -109, 74, -85, -23, -123, -26, 9, 46, 32, 0, -81, 7, 27, 16, 86, -106, 32, -126, -5, 79, -50, 106, 94, 65, -120, -85, 71, -22, 33, 46, 102, -112, -122, -32, -121, -107, 74, 14, 92, 64, -40, 16, 13, 46, 4, 0, 0, 0, 0, 0, 4, 1, 32, 0, 36, -36, 66, -85, -14, -44, 40, -35, -74, -57, -30, 68, 78, -82, 105, -26, 47, 1, -66, 94, -85, 44, 37, 67, -54, -67, 101, 74, 127, -5, 19, 104 }; private static byte[] signature = { 48, 69, 2, 32, 126, -95, -8, -124, -8, 81, -84, 29, 125, -60, -94, -71, -96, 6, 82, -117, -50, -85, 55, 112, -31, 79, -17, 18, 109, -102, -124, -122, 106, -45, -21, -35, 2, 33, 0, -46, 40, -87, 85, 5, 18, 109, -65, -34, -83, -87, 56, 12, -28, -106, -8, -32, 109, -114, 92, 62, 39, -14, 29, -23, 118, -99, -90, -86, -109, -98, -68 }; @POST @Consumes(JSON_CONTENT_TYPE) @Produces(JSON_CONTENT_TYPE) public Response verifySignature(String authParams) { if(verifyECDSASignature(authParams)) { return Response.ok("{ \"status\":\"success\"}").build(); } else { return Response.status(Status.INTERNAL_SERVER_ERROR).build(); } } public boolean verifyECDSASignature(String authParams) { try { KeyFactory factory = KeyFactory.getInstance("EC"); PublicKey publicKey = factory.generatePublic(new X509EncodedKeySpec(pubKey)); Signature sig = Signature.getInstance("SHA256WITHECDSA"); sig.initVerify(publicKey); sig.update(signedData); boolean verified = sig.verify(signature); return verified; } catch (NoSuchAlgorithmException e) { // TODO Auto-generated catch block e.printStackTrace(); } catch (InvalidKeyException e) { // TODO Auto-generated catch block e.printStackTrace(); } catch (SignatureException e) { // TODO Auto-generated catch block e.printStackTrace(); } catch (InvalidKeySpecException e) { // TODO Auto-generated catch block e.printStackTrace(); } return false; } } > > > 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. > ==> Most of the stack traces are like the above i.e. sun.security.ec. ECDSASignature.verifySignedDigest(Native Method), but only few show like the below. verifySignedDigest is the hotspot. > > > 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. > ==> Reasonable explanation but wondering if there is a way to know if it is a memory fragmentation issue. > > > 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. > ==> Appreciate you patience in spending time on looking at these stack traces. > > 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. > ==> We had used profiler before and can re-collect some information with it as suggested. My only concern is that in the same environment with the same JRE we end up with this slowness when we switch to tomcat7 and performance drop is by 50% which is significant. I will provide more information but i have shared the source of the signature end point which i will be continuing to investigate with further. Also will look into the TLS as suggested. > > -chris > > --------------------------------------------------------------------- > To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org > For additional commands, e-mail: users-h...@tomcat.apache.org > >
