Hi Mark, Sorry for the late reply, it has been a couple of busy days.
We are running our application on two nodes and we have seen the issue on both nodes. These machines are running quad core cpus. What we have usually seen is that the application jvm process is consuming 100% (basically one core) on one machine and 200% (2 cores) on the other machine. The cpu usage/core usage seems to correlate quite well with the number of looping threads that we can observe via jmx. The load does not move between threads, it is pinned to the looping thread. We have only observed this behavior on one application and only in production. "Unfortunately" we did a deployment this week so both nodes have been restarted which means that at the moment the cpu usage is down to almost 0. We are planning to update to Tomcat 8.5.x in the coming week (planned update, not a forced update related to this issue). Are you aware of any major code changes between the 8.0.x and 8.5.x branches related to this functionality ? Best regards, Andreas -----Original Message----- From: Mark Thomas [mailto:ma...@apache.org] Sent: den 17 januari 2018 22:20 To: Tomcat Users List <users@tomcat.apache.org> Subject: Re: Ajp Nio-thread stuck in loop and consuming a lot of cpu On 16/01/18 23:21, Mark Thomas wrote: > On 16/01/18 09:21, Toom Andreas wrote: >> Hi Mark, >> >> We pulled out a CPU Call Tree using JVisualVM instead of YourKit and >> I have uploaded a screenshot of it here: https://imgur.com/a/mqYxn >> >> There is not much extra information compared to the java thread dump in my >> initial post but it highlights in which code branch/method call most of the >> cpu time is spent. Perhaps it will give some additional clues ? Let me know >> if you think that it is worthwhile to use YourKit instead of JVisualVM and I >> will try to get that for you instead. > > Thanks. This has given me a couple of ideas. I need to do some more > testing. I hope to be able to get this done in the next day or so. Unfortunately my ideas didn't pan out. What levels of CPU usage are you observing? Is it always the same threads generating the load or does it move between threads? Can you reproduce this on a system you can attach a remote debugger to? What we really need to do is understand the code path that is being taken and why. I can see the likely code path in the data we have so far but nothing that looks abnormal. Mark > > Mark > > >> >> Best regards, >> Andreas >> >> -----Original Message----- >> From: Mark Thomas [mailto:ma...@apache.org] >> Sent: den 12 januari 2018 11:27 >> To: Tomcat Users List <users@tomcat.apache.org> >> Subject: Re: Ajp Nio-thread stuck in loop and consuming a lot of cpu >> >> On 12/01/18 06:58, Toom Andreas wrote: >>> Hi, >>> >>> We are having an issue with an application running Apache Tomcat 8.0.47 >>> using Oracle Jvm 1.8.0.151 on Linux (RHEL 7). The Tomcat process is >>> consuming cpu at a constant high level even though there is a low amount >>> of incoming traffic. When inspecting the process health using JMX >>> /JVisualVM CPU Sampler we see that there are 4 ajp-nio-exec threads >>> together with a NioBlockingSelector.BlockPoller thread that consume most of >>> the cpu. >> >> Are you able to determine the code path of the loop? A single stack trace >> can point us in the right direction but often the root cause can still be >> tricky to track down. >> >> A profiler such as YourKit in CPU tracing mode should be able to provide >> enough info to figure this out (and won't require any code changes to your >> system). >> >> Remote debugging is the other option but that is less ideal in production. >> >> Mark >> >> >>> >>> A stack trace of one of the ajp-io-exec threads looks like this: >>> >>> "ajp-nio-48317-exec-14233" - Thread t@201195 >>> java.lang.Thread.State: TIMED_WAITING >>> at sun.misc.Unsafe.park(Native Method) >>> - parking to wait for <342fab60> (a >>> java.util.concurrent.CountDownLatch$Sync) >>> at >>> java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) >>> at >>> java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037) >>> at >>> java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328) >>> at >>> java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277) >>> at >>> org.apache.tomcat.util.net.NioEndpoint$KeyAttachment.awaitLatch(NioEndpoint.java:1400) >>> at >>> org.apache.tomcat.util.net.NioEndpoint$KeyAttachment.awaitReadLatch(NioEndpoint.java:1402) >>> at >>> org.apache.tomcat.util.net.NioBlockingSelector.read(NioBlockingSelector.java:185) >>> at >>> org.apache.tomcat.util.net.NioSelectorPool.read(NioSelectorPool.java:250) >>> at >>> org.apache.tomcat.util.net.NioSelectorPool.read(NioSelectorPool.java:231) >>> at >>> org.apache.coyote.ajp.AjpNioProcessor.readSocket(AjpNioProcessor.java:194) >>> at >>> org.apache.coyote.ajp.AjpNioProcessor.read(AjpNioProcessor.java:160) >>> at >>> org.apache.coyote.ajp.AbstractAjpProcessor.readMessage(AbstractAjpProcessor.java:1091) >>> at >>> org.apache.coyote.ajp.AbstractAjpProcessor.process(AbstractAjpProcessor.java:804) >>> at >>> org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:684) >>> at >>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1539) >>> at >>> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1495) >>> - locked <279cc7f7> (a >>> org.apache.tomcat.util.net.NioChannel) >>> 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: >>> - locked <10e1f474> (a >>> java.util.concurrent.ThreadPoolExecutor$Worker) >>> >>> A stack trace of the NioBlockingSelector.BlockPoller thread looks like this: >>> >>> "NioBlockingSelector.BlockPoller-2" - Thread t@17 >>> java.lang.Thread.State: RUNNABLE >>> at >>> sun.nio.ch.EPollArrayWrapper.epollWait(Native Method) >>> at >>> sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269) >>> at >>> sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93) >>> at >>> sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86) >>> - locked <648895e4> (a sun.nio.ch.Util$3) >>> - locked <17921532> (a >>> java.util.Collections$UnmodifiableSet) >>> - locked <67762111> (a >>> sun.nio.ch.EPollSelectorImpl) >>> at >>> sun.nio.ch.SelectorImpl.selectNow(SelectorImpl.java:105) >>> at >>> org.apache.tomcat.util.net.NioBlockingSelector$BlockPoller.run(NioBl >>> oc >>> kingSelector.java:339) >>> >>> Locked ownable synchronizers: >>> - None >>> >>> It seems like the worker thread is trying to read from the underlying >>> socket. When we inspect the OS tcp/ip statistics using the ss-command (ss >>> -i src :<ajp-port>) the following connections are suspicious: >>> >>> State Recv-Q Send-Q Local Address:Port Peer >>> Address:Port >>> CLOSE-WAIT 2 0 10.x.x.x:48317 10.x.x.11:53724 >>> cubic wscale:7,7 rto:202 rtt:1.724/2.424 >>> ato:40 mss:1448 cwnd:10 ssthresh:31 bytes_acked:343869507 >>> bytes_received:22259372 segs_out:302687 segs_in:141943 send 67.2Mbps >>> lastsnd:1290791171 lastrcv:1290786778 lastack:1290786767 pacing_rate >>> 134.4Mbps retrans:0/433 rcv_rtt:1.875 rcv_space:28960 >>> CLOSE-WAIT 1 0 10.x.x.x:48317 10.x.x.12:41990 >>> cubic wscale:7,7 rto:202 rtt:1.132/0.899 >>> ato:40 mss:1448 cwnd:10 ssthresh:22 bytes_acked:37347221 >>> bytes_received:3346200 segs_out:35273 segs_in:20608 send 102.3Mbps >>> lastsnd:289840681 lastrcv:289730802 lastack:289720796 pacing_rate 204.5Mbps >>> retrans:0/13 reordering:24 rcv_rtt:1.875 rcv_space:28960 >>> CLOSE-WAIT 1 0 10.x.x.x:48317 10.x.x.12:60068 >>> cubic wscale:7,7 rto:209 rtt:8.757/14.317 >>> ato:40 mss:1448 cwnd:10 ssthresh:36 bytes_acked:180903401 >>> bytes_received:16401965 segs_out:170017 segs_in:100392 send 13.2Mbps >>> lastsnd:395602314 lastrcv:395602267 lastack:395602257 pacing_rate 26.5Mbps >>> retrans:0/106 rcv_rtt:1.875 rcv_space:28960 >>> CLOSE-WAIT 2 0 10.x.x.x:48317 10.x.x.11:50628 >>> cubic wscale:7,7 rto:203 >>> rtt:2.992/4.252 >>> ato:40 mss:1448 cwnd:13 ssthresh:25 bytes_acked:4185335 >>> bytes_received:471220 segs_out:4193 segs_in:2181 send 50.3Mbps >>> lastsnd:1036916135 lastrcv:1036871377 lastack:1036871367 pacing_rate >>> 100.6Mbps retrans:0/1 reordering:26 rcv_rtt:6.375 rcv_space:28960 >>> >>> We are running our Tomcat node behind and Apache server and use Tomcat >>> Connector (mod_jk) as a load balancer. When looking at the hosts running >>> the Apache node the corresponding sockets are closed. To us it seems that >>> Tomcat has not properly closed the underlying socket when Apache/mod_jk >>> initiated a FIN and is instead continuously trying to read from the socket >>> even though it has been closed on the Apache side ? >>> >>> I know that we are one version behind the latest release of Tomcat 8.0.x >>> but I checked the changelog and I could not see any fixed issues matching >>> this problem. Unfortunately we are only seeing this in production and we >>> have not been able to reproduce in test. Has anyone experienced a similar >>> issue like this before ? >>> >>> For reference our connector configuration in server.xml looks like this: >>> >>> <Connector port="48317" >>> protocol="AJP/1.3" >>> maxThreads="200" >>> connectionTimeout="600000" >>> xpoweredBy="false" >>> allowTrace="false" >>> URIEncoding="UTF-8" >>> requiredSecret="xxx" >>> secure="true" >>> scheme="https" >>> proxyPort="443" /> >>> >>> And our Tomcat Connector configuration for Apache in workers.properties >>> looks like this: >>> >>> worker.list = status,app >>> >>> # Create workers for app >>> worker.app-1.type=ajp13 >>> worker.app-1.host=host8128.corpdomain.internal >>> worker.app-1.port=48317 >>> worker.app-1.ping_mode=A >>> worker.app-1.connection_pool_timeout=600 >>> worker.app-1.secret=xxx >>> worker.app-2.type=ajp13 >>> worker.app-2.host=host8129.corpdomain.internal >>> worker.app-2.port=48317 >>> worker.app-2.ping_mode=A >>> worker.app-2.connection_pool_timeout=600 >>> worker.app-2.secret=xxx >>> >>> # Create a loadbalancer for app >>> worker.app.type=lb >>> worker.app.sticky_session=1 >>> worker.app.balance_workers=app-1, app-2 >>> >>> Best regards, >>> Andreas >>> >>> >>> Andreas Toom >>> Systemutvecklare/IT >>> TEL: +46 702 03 04 98 >>> [Volvofinans Bank AB]<http://www.volvofinans.se/> >>> >>> >>> >>> >> >> >> --------------------------------------------------------------------- >> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org >> For additional commands, e-mail: users-h...@tomcat.apache.org >> >> >> --------------------------------------------------------------------- >> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org >> For additional commands, e-mail: users-h...@tomcat.apache.org >> > > > --------------------------------------------------------------------- > To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org > For additional commands, e-mail: users-h...@tomcat.apache.org > --------------------------------------------------------------------- To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
