You are viewing a plain text version of this content. The canonical link for it is here.

Posted to users@tomcat.apache.org by dimple ranka <di...@gmail.com> on 2015/11/03 07:17:06 UTC

Performance degrades on tomcat7 for the same runs of a sample performance 60 user test

Hi all,

I am doing some performance data collection on tomcat7 on a 8 processor
high end machine with CentOS release 6.7 (Final) operating system and i am
observing slowness with subsequent runs of the same jmeter test. Here are
the version and specfication details followed by the endpoint source and
the problem statement finally.

##############################################
Tomcat7 Version  ==>
##############################################
Server version: Apache Tomcat/7.0.64
Server built:   Aug 19 2015 17:18:06 UTC
Server number:*  7.0.64.0*
OS Name:        Linux
OS Version:     2.6.32-573.3.1.el6.x86_64
Architecture:   amd64
JVM Version:    1.7.0_79-b15
JVM Vendor:     Oracle Corporation
##############################################


##############################################
Connector configurations
##############################################
<Connector port="8443" protocol="org.apache.coyote.http11.
*Http11NioProtocol*" SSLEnabled="true"
maxThreads="150" scheme="https" secure="true"
keystoreType="PKCS12"
keystoreFile="XXXXXX"
keystorePass="password" clientAuth="false"
sslEnabledProtocols="TLSv1,TLSv1.1,TLSv1.2" />
##############################################


##############################################
Machine Specifications
##############################################
Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                8
On-line CPU(s) list:   0-7
Thread(s) per core:    2
Core(s) per socket:    4
Socket(s):             1
NUMA node(s):          1
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 58
Stepping:              9
CPU MHz:               1600.000
BogoMIPS:              7000.55
Virtualization:        VT-x
L1d cache:             32K
L1i cache:             32K
L2 cache:              256K
L3 cache:              8192K
NUMA node0 CPU(s):     0-7
##############################################


##############################################
Source code of the endpoint being performance tested
##############################################
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;


@Path("/null")
public class NullEndPoint {
public static final String UTF_8 = "UTF-8";
public static final String JSON_CONTENT_TYPE = MediaType.APPLICATION_JSON +
"; charset=" + UTF_8;
@POST
@Consumes(JSON_CONTENT_TYPE)
@Produces(JSON_CONTENT_TYPE)
public Response verify(String params) {
return Response.ok("{ \"status\":\"success\"}").build();
}

}
##############################################


##############################################
Jmeter Test Plan - 60 users test for 1200 seconds duration
##############################################
<?xml version="1.0" encoding="UTF-8"?>
<jmeterTestPlan version="1.2" properties="2.4" jmeter="2.9 r1437961">
  <hashTree>
    <TestPlan guiclass="TestPlanGui" testclass="TestPlan"
testname="SampleTest" enabled="true">
      <stringProp name="TestPlan.comments"></stringProp>
      <boolProp name="TestPlan.functional_mode">false</boolProp>
      <boolProp name="TestPlan.serialize_threadgroups">false</boolProp>
      <elementProp name="TestPlan.user_defined_variables"
elementType="Arguments" guiclass="ArgumentsPanel" testclass="Arguments"
testname="User Defined Variables" enabled="true">
        <collectionProp name="Arguments.arguments"/>
      </elementProp>
      <stringProp name="TestPlan.user_define_classpath"></stringProp>
    </TestPlan>
    <hashTree>
      <kg.apc.jmeter.threads.SteppingThreadGroup
guiclass="kg.apc.jmeter.threads.SteppingThreadGroupGui"
testclass="kg.apc.jmeter.threads.SteppingThreadGroup" testname="MU - Reg"
enabled="true">
        <stringProp name="ThreadGroup.on_sample_error">continue</stringProp>
        <stringProp
name="ThreadGroup.num_threads">${__P(users,60)}</stringProp>
        <stringProp name="Threads initial delay">0</stringProp>
        <stringProp name="Start users count">10</stringProp>
        <stringProp name="Start users count burst">0</stringProp>
        <stringProp name="Start users period">30</stringProp>
        <stringProp name="Stop users count">10</stringProp>
        <stringProp name="Stop users period">1</stringProp>
        <stringProp name="flighttime">${__P(duration,1200)}</stringProp>
        <stringProp name="rampUp">5</stringProp>
        <elementProp name="ThreadGroup.main_controller"
elementType="LoopController" guiclass="LoopControlPanel"
testclass="LoopController" testname="Loop Controller" enabled="true">
          <boolProp name="LoopController.continue_forever">false</boolProp>
          <intProp name="LoopController.loops">-1</intProp>
        </elementProp>
      </kg.apc.jmeter.threads.SteppingThreadGroup>
      <hashTree>
        <HeaderManager guiclass="HeaderPanel" testclass="HeaderManager"
testname="HTTP Header Manager" enabled="true">
          <collectionProp name="HeaderManager.headers">
            <elementProp name="" elementType="Header">
              <stringProp name="Header.name">Content-Type</stringProp>
              <stringProp name="Header.value">application/json</stringProp>
            </elementProp>
          </collectionProp>
        </HeaderManager>
        <hashTree/>
        <Arguments guiclass="ArgumentsPanel" testclass="Arguments"
testname="User Defined Variables" enabled="true">
          <collectionProp name="Arguments.arguments">
            <elementProp name="userNameUUID" elementType="Argument">
              <stringProp name="Argument.name">userNameUUID</stringProp>
              <stringProp name="Argument.value">user_${__UUID</stringProp>
              <stringProp name="Argument.metadata">=</stringProp>
            </elementProp>
            <elementProp name="host" elementType="Argument">
              <stringProp name="Argument.name">host</stringProp>
              <stringProp
name="Argument.value">${__P(myhost,XXX.XX.XX.XX)}</stringProp>
              <stringProp name="Argument.metadata">=</stringProp>
            </elementProp>
            <elementProp name="port" elementType="Argument">
              <stringProp name="Argument.name">port</stringProp>
              <stringProp name="Argument.value">8443</stringProp>
              <stringProp name="Argument.metadata">=</stringProp>
            </elementProp>
            <elementProp name="protocol" elementType="Argument">
              <stringProp name="Argument.name">protocol</stringProp>
              <stringProp name="Argument.value">https</stringProp>
              <stringProp name="Argument.metadata">=</stringProp>
            </elementProp>
            <elementProp name="pathPrefix" elementType="Argument">
              <stringProp name="Argument.name">pathPrefix</stringProp>
              <stringProp name="Argument.value">/null</stringProp>
              <stringProp name="Argument.metadata">=</stringProp>
            </elementProp>
          </collectionProp>
        </Arguments>
        <hashTree/>
        <HTTPSamplerProxy guiclass="HttpTestSampleGui"
testclass="HTTPSamplerProxy" testname="Null Request" enabled="true">
          <boolProp name="HTTPSampler.postBodyRaw">true</boolProp>
          <elementProp name="HTTPsampler.Arguments" elementType="Arguments">
            <collectionProp name="Arguments.arguments">
              <elementProp name="" elementType="HTTPArgument">
                <boolProp name="HTTPArgument.always_encode">false</boolProp>
                <stringProp name="Argument.value">{&#xd;
}</stringProp>
                <stringProp name="Argument.metadata">=</stringProp>
              </elementProp>
            </collectionProp>
          </elementProp>
          <stringProp name="HTTPSampler.domain">${host}</stringProp>
          <stringProp name="HTTPSampler.port">${port}</stringProp>
          <stringProp name="HTTPSampler.connect_timeout"></stringProp>
          <stringProp name="HTTPSampler.response_timeout"></stringProp>
          <stringProp name="HTTPSampler.protocol">${protocol}</stringProp>
          <stringProp name="HTTPSampler.contentEncoding"></stringProp>
          <stringProp name="HTTPSampler.path">${pathPrefix}</stringProp>
          <stringProp name="HTTPSampler.method">POST</stringProp>
          <boolProp name="HTTPSampler.follow_redirects">true</boolProp>
          <boolProp name="HTTPSampler.auto_redirects">false</boolProp>
          <boolProp name="HTTPSampler.use_keepalive">true</boolProp>
          <boolProp name="HTTPSampler.DO_MULTIPART_POST">false</boolProp>
          <boolProp name="HTTPSampler.monitor">false</boolProp>
          <stringProp name="HTTPSampler.embedded_url_re"></stringProp>
        </HTTPSamplerProxy>
        <hashTree/>
        <ResultCollector guiclass="ViewResultsFullVisualizer"
testclass="ResultCollector" testname="View Results Tree" enabled="true">
          <boolProp name="ResultCollector.error_logging">false</boolProp>
          <objProp>
            <name>saveConfig</name>
            <value class="SampleSaveConfiguration">
              <time>true</time>
              <latency>true</latency>
              <timestamp>true</timestamp>
              <success>true</success>
              <label>true</label>
              <code>true</code>
              <message>true</message>
              <threadName>true</threadName>
              <dataType>true</dataType>
              <encoding>false</encoding>
              <assertions>true</assertions>
              <subresults>true</subresults>
              <responseData>false</responseData>
              <samplerData>false</samplerData>
              <xml>false</xml>
              <fieldNames>false</fieldNames>
              <responseHeaders>false</responseHeaders>
              <requestHeaders>false</requestHeaders>
              <responseDataOnError>false</responseDataOnError>

<saveAssertionResultsFailureMessage>false</saveAssertionResultsFailureMessage>
              <assertionsResultsToSave>0</assertionsResultsToSave>
              <bytes>true</bytes>
            </value>
          </objProp>
          <stringProp name="filename"></stringProp>
        </ResultCollector>
        <hashTree/>
      </hashTree>
    </hashTree>
  </hashTree>
</jmeterTestPlan>
##############################################


##############################################
On tomcat7 number of requests fullfilled per second
##############################################
* RUN1 ** ==> **  38128.97704918033 runs/sec*
 *RUN2 ==> **  19040.35947712418 runs/sec*
 *RUN3 ==> ** 19043.7908496732**  runs/sec*
* RUN4 ==> ** 19001.71568627451 runs/sec*
##############################################

##############################################
*PROBLEM*
##############################################
It can be clearly seen that the performance degrades with multiple runs of
the same jmeter test by almost 50% and then on the 3rd or 4th run it seems
to stabliize. This issue is not reproducible on tomcat6 on the same
machine. It shows up only on tomcat7 onwards. Also tomcat8 is showing
similar symptoms. The slowness shows up only in the next subsequent run
against the server without tomcat restart.

Also the slowness issue is more obvious when the endpoint is doing
cryptographic validations(more processing).

Please let us know what change in tomcat7 is showing this change. Can some
configuration help in fixing this. We are suspecting that the threading
model in tomcat7 onwards is the cause of this.
##############################################

Regards,
Dimple

Re: Performance degrades on tomcat7 for the same runs of a sample performance 60 user test

Posted by Dimple Ranka <dr...@noknok.com>.

On Mon, Nov 9, 2015 at 8:34 PM, Christopher Schultz <
chris@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-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>