1

Problem first:

My service reponse time increases while the concurrency increases. I found 1000+ threads blocks on the step that tomcat response to client. But I don't know how to solve it.

Background:

My service is a Spring boot project which embedded a tomcat. (tomcat-embed-core-8.5.23)

My experiment is to use JMeter as client, create 2000 threads to send request to my service for 10 round (totally 20000 requests). And after my service there is a stub services to response in 2 seconds delay for each request. (i.e. JMeter (2000 thread) => My Service => Stub Server )

experiment data

  • In My service, I set the “server.tomcat.max-threads=2000”. So there are 2000+ threads named "http-nio-8080*”

  • The result is, the max response time are >30 s. This is copied from CLI,

    summary = 20000 in 00:01:23 = 241.7/s Avg: 6890 Min: 2288 Max: 31158 Err: 0 (0.00%)

The Min response time (2288ms) is as expected (as there are 2000ms cost in stub server). But the Max response time (31158 ms) is too long. I analyzed the jstack log. There were 1121 threads blocked on the same lock. (I attached one of the stack content. And I think it’s the time point of My service response to JMeter. But unfortunately there is a SynchronizedStack blocking the 1000+ threads)

I have evidence that the lock is the real killer of the response time. In another jstack log 9 seconds later, there were still 1058 threads lock on the same lock. 

"http-nio-8080-exec-3988" #4038 daemon prio=5 os_prio=0 tid=0x00007fdec045c800 nid=0x1050 waiting for monitor entry [0x00007fdb6c94e000] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.tomcat.util.collections.SynchronizedStack.pop(SynchronizedStack.java:75) - waiting to lock <0x00000000dac7afd0> (a org.apache.tomcat.util.collections.SynchronizedStack) at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:89) at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:157) at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1267) at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:670) at org.apache.tomcat.util.net.SocketWrapperBase.flushBlocking(SocketWrapperBase.java:607) at org.apache.tomcat.util.net.SocketWrapperBase.flush(SocketWrapperBase.java:597) at org.apache.coyote.http11.Http11OutputBuffer.flushBuffer(Http11OutputBuffer.java:581) at org.apache.coyote.http11.Http11OutputBuffer.flush(Http11OutputBuffer.java:272) at org.apache.coyote.http11.Http11Processor.flush(Http11Processor.java:1560) at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:283) at org.apache.coyote.Response.action(Response.java:173) at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:317) at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:284) at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:118) at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:297) at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141) - locked <0x00000000fe000000> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229) at org.springframework.util.StreamUtils.copy(StreamUtils.java:119) at org.springframework.http.converter.StringHttpMessageConverter.writeInternal(StringHttpMessageConverter.java:106) at org.springframework.http.converter.StringHttpMessageConverter.writeInternal(StringHttpMessageConverter.java:41) at org.springframework.http.converter.AbstractHttpMessageConverter.write(AbstractHttpMessageConverter.java:227) at org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodProcessor.writeWithMessageConverters(AbstractMessageConverterMethodProcessor.java:247) at org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.handleReturnValue(RequestResponseBodyMethodProcessor.java:174) at org.springframework.web.method.support.HandlerMethodReturnValueHandlerComposite.handleReturnValue(HandlerMethodReturnValueHandlerComposite.java:81) at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:113) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738) at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872) at javax.servlet.http.HttpServlet.service(HttpServlet.java:661) at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) at javax.servlet.http.HttpServlet.service(HttpServlet.java:742) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.boot.web.filter.ApplicationContextHeaderFilter.doFilterInternal(ApplicationContextHeaderFilter.java:55) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:110) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:108) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.boot.actuate.autoconfigure.MetricsFilter.doFilterInternal(MetricsFilter.java:106) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459) at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) - locked <0x00000000e1a59188> (a org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:748) Locked ownable synchronizers: - <0x00000000df55e210> (a java.util.concurrent.ThreadPoolExecutor$Worker)
Improve this question

1 Answer 1

Reset to default
4

You mistakenly allow tomcat to overcommit.

First thing first, limit the tomcat executor threads to about 100 or 200 max. Practically you should never have more than 200 threads in any jvm, unless you really know what you are doing and have 99% of them waiting (not blocked monitor entry).

Then, limit the tcp SYN queue length (the serversocket accept queue) to make sure that you don't accept all jmeter connections when too many are made.

Start with severely limited threads and increase the number of thread only as long as you have idle on both network bandwidth and CPU, and even then, as long as the responsetime doesn't increase.

Improve this answer
Sign up to request clarification or add additional context in comments.

4 Comments

Thanks for your experience shaing. I agree to limit the concurrency could shorten the response time. But before that I still want to pay a little more time on the 2000 threads solution. I guess If there is no such tomcat SynchronizedStack lock, my service would response more quickly. Any suggestion?
This will sound odd, but if you can try with jetty, you might see a difference on the contending exec threads. This issue here appears to be deep in the implementation of the server. I don't think you have much control over this lock thing. Another suggestion: try the good old http11 connector, not the NIO one. You could be surprised of how well the OS can deal with 1 threads per socket; having a different connector impl could avoid this huge contention problem of 2000 threads on a single nio funnel.
Sorry for late. I have tried 3 solutions. 1. use "BIO" in tomcat. I didn't see threads blocking in "jstack log". But there were a lot of connect refused error found in JMeter (I set the connect timeout being 10 seconds). So the "BIO" is not my choice. 2. use jetty to replace tomcat. Jetty is really faster 10% than tomcat. 3. increase CPU resource for my service from 2 cores to 3 cores. It's really improved the performance remarkable. (from 30s to 8s for JMeter 2000 threads; and from 13s to 3s for JMeter 1000 threads)
Always put the backpressure at the entry of the system, otherwise you overcommit. Having rejection at your client side (jmeter) is a normal graceful degradation that a load balancer would use to dispatch to another server. You certainly can choose to queue and slow down service time, but you need to put a limit to that, both in time and in memory required to buffer the huge pile of thousands of delayed requests. In my book, either I can begin serving within 1s (not including the service time) or reject. This means a queue no longer than your max rate.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.