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(NioBlockingSelector.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
