We are seeing excessive CPU burn (top > 300% on multicore machine) in multiple versions of Tomcat that use APR connectors exclusively. The problem does not correlate with load. We initially saw it on 6.0.35 and subsequently on 7.0.23 as we attempted to upgrade around the problem. We have determined that the component common to both versions is tomcat-native 1.1.22. (We were not seeing this behavior on our previous component mix of 6.0.26/1.1.20.)
In addition to the circumstantial evidence of version changes, we have some JVM data that implicate tomcat-native. We've taken thread dumps and YourKit snapshots (w/CPU sampling enabled) during the problem periods and a consistent pattern appears: at least two connector threads are in org.apache.tomcat.jni.Socket.sendbb(long, int, int) throughout the period of CPU churn. The following instrumented thread dump of active threads is illustrative of this pattern: Stacks at 10:57:51 AM (uptime 5:13:38) catalina-exec-1 [WAITING] CPU time: 2:03 sun.misc.Unsafe.park(boolean, long) java.util.concurrent.locks.LockSupport.parkNanos(Object, long) java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(long) java.util.concurrent.LinkedBlockingQueue.poll(long, TimeUnit) org.apache.tomcat.util.threads.TaskQueue.poll(long, TimeUnit) org.apache.tomcat.util.threads.TaskQueue.poll(long, TimeUnit) java.util.concurrent.ThreadPoolExecutor.getTask() java.util.concurrent.ThreadPoolExecutor$Worker.run() java.lang.Thread.run() catalina-exec-10 [RUNNABLE, IN_NATIVE] CPU time: 2:28 org.apache.tomcat.jni.Socket.sendbb(long, int, int) org.apache.coyote.http11.InternalAprOutputBuffer.flushBuffer() org.apache.coyote.http11.InternalAprOutputBuffer.access$100(InternalAprOutputBuffer) org.apache.coyote.http11.InternalAprOutputBuffer$SocketOutputBuffer.doWrite(ByteChunk, Response) org.apache.coyote.http11.filters.IdentityOutputFilter.doWrite(ByteChunk, Response) org.apache.coyote.http11.AbstractOutputBuffer.doWrite(ByteChunk, Response) org.apache.coyote.Response.doWrite(ByteChunk) org.apache.catalina.connector.OutputBuffer.realWriteBytes(byte[], int, int) org.apache.tomcat.util.buf.ByteChunk.append(byte[], int, int) org.apache.catalina.connector.OutputBuffer.writeBytes(byte[], int, int) org.apache.catalina.connector.OutputBuffer.write(byte[], int, int) org.apache.catalina.connector.CoyoteOutputStream.write(byte[], int, int) org.apache.catalina.servlets.DefaultServlet.copy(CacheEntry, InputStream, ServletOutputStream) org.apache.catalina.servlets.DefaultServlet.serveResource(HttpServletRequest, HttpServletResponse, boolean) org.apache.catalina.servlets.DefaultServlet.doGet(HttpServletRequest, HttpServletResponse) javax.servlet.http.HttpServlet.service(HttpServletRequest, HttpServletResponse) javax.servlet.http.HttpServlet.service(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) edu.vt.middleware.servlet.filter.RequestDumperFilter.doFilter(ServletRequest, ServletResponse, FilterChain) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) com.github.inspektr.common.web.ClientInfoThreadLocalFilter.doFilter(ServletRequest, ServletResponse, FilterChain) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) edu.vt.middleware.servlet.filter.CharacterEncodingFilter.doFilter(ServletRequest, ServletResponse, FilterChain) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) org.apache.catalina.core.StandardWrapperValve.invoke(Request, Response) org.apache.catalina.core.StandardContextValve.invoke(Request, Response) org.apache.catalina.authenticator.AuthenticatorBase.invoke(Request, Response) org.apache.catalina.core.StandardHostValve.invoke(Request, Response) org.apache.catalina.valves.ErrorReportValve.invoke(Request, Response) org.apache.catalina.valves.AccessLogValve.invoke(Request, Response) org.apache.catalina.core.StandardEngineValve.invoke(Request, Response) org.apache.catalina.connector.CoyoteAdapter.service(Request, Response) org.apache.coyote.http11.AbstractHttp11Processor.process(SocketWrapper) org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(SocketWrapper, SocketStatus) org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run() java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Runnable) java.util.concurrent.ThreadPoolExecutor$Worker.run() java.lang.Thread.run() catalina-exec-11 [RUNNABLE, IN_NATIVE] CPU time: 10:19 org.apache.tomcat.jni.Socket.sendbb(long, int, int) org.apache.coyote.http11.InternalAprOutputBuffer.flushBuffer() org.apache.coyote.http11.InternalAprOutputBuffer.access$100(InternalAprOutputBuffer) org.apache.coyote.http11.InternalAprOutputBuffer$SocketOutputBuffer.doWrite(ByteChunk, Response) org.apache.coyote.http11.filters.IdentityOutputFilter.doWrite(ByteChunk, Response) org.apache.coyote.http11.AbstractOutputBuffer.doWrite(ByteChunk, Response) org.apache.coyote.Response.doWrite(ByteChunk) org.apache.catalina.connector.OutputBuffer.realWriteBytes(byte[], int, int) org.apache.tomcat.util.buf.ByteChunk.append(byte[], int, int) org.apache.catalina.connector.OutputBuffer.writeBytes(byte[], int, int) org.apache.catalina.connector.OutputBuffer.write(byte[], int, int) org.apache.catalina.connector.CoyoteOutputStream.write(byte[], int, int) org.apache.catalina.servlets.DefaultServlet.copy(CacheEntry, InputStream, ServletOutputStream) org.apache.catalina.servlets.DefaultServlet.serveResource(HttpServletRequest, HttpServletResponse, boolean) org.apache.catalina.servlets.DefaultServlet.doGet(HttpServletRequest, HttpServletResponse) javax.servlet.http.HttpServlet.service(HttpServletRequest, HttpServletResponse) javax.servlet.http.HttpServlet.service(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) edu.vt.middleware.servlet.filter.RequestDumperFilter.doFilter(ServletRequest, ServletResponse, FilterChain) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) com.github.inspektr.common.web.ClientInfoThreadLocalFilter.doFilter(ServletRequest, ServletResponse, FilterChain) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) edu.vt.middleware.servlet.filter.CharacterEncodingFilter.doFilter(ServletRequest, ServletResponse, FilterChain) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) org.apache.catalina.core.StandardWrapperValve.invoke(Request, Response) org.apache.catalina.core.StandardContextValve.invoke(Request, Response) org.apache.catalina.authenticator.AuthenticatorBase.invoke(Request, Response) org.apache.catalina.core.StandardHostValve.invoke(Request, Response) org.apache.catalina.valves.ErrorReportValve.invoke(Request, Response) org.apache.catalina.valves.AccessLogValve.invoke(Request, Response) org.apache.catalina.core.StandardEngineValve.invoke(Request, Response) org.apache.catalina.connector.CoyoteAdapter.service(Request, Response) org.apache.coyote.http11.AbstractHttp11Processor.process(SocketWrapper) org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(SocketWrapper, SocketStatus) org.apache.tomcat.util.net.AprEndpoint$SocketWithOptionsProcessor.run() java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Runnable) java.util.concurrent.ThreadPoolExecutor$Worker.run() java.lang.Thread.run() catalina-exec-12 [WAITING] CPU time: 1:39 sun.misc.Unsafe.park(boolean, long) java.util.concurrent.locks.LockSupport.parkNanos(Object, long) java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(long) java.util.concurrent.LinkedBlockingQueue.poll(long, TimeUnit) org.apache.tomcat.util.threads.TaskQueue.poll(long, TimeUnit) org.apache.tomcat.util.threads.TaskQueue.poll(long, TimeUnit) java.util.concurrent.ThreadPoolExecutor.getTask() java.util.concurrent.ThreadPoolExecutor$Worker.run() java.lang.Thread.run() catalina-exec-3 [WAITING] CPU time: 2:26 sun.misc.Unsafe.park(boolean, long) java.util.concurrent.locks.LockSupport.parkNanos(Object, long) java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(long) java.util.concurrent.LinkedBlockingQueue.poll(long, TimeUnit) org.apache.tomcat.util.threads.TaskQueue.poll(long, TimeUnit) org.apache.tomcat.util.threads.TaskQueue.poll(long, TimeUnit) java.util.concurrent.ThreadPoolExecutor.getTask() java.util.concurrent.ThreadPoolExecutor$Worker.run() java.lang.Thread.run() catalina-exec-5 [RUNNABLE, IN_NATIVE] CPU time: 3:00 org.apache.tomcat.jni.Socket.sendbb(long, int, int) org.apache.coyote.http11.InternalAprOutputBuffer.flushBuffer() org.apache.coyote.http11.InternalAprOutputBuffer.access$100(InternalAprOutputBuffer) org.apache.coyote.http11.InternalAprOutputBuffer$SocketOutputBuffer.doWrite(ByteChunk, Response) org.apache.coyote.http11.filters.IdentityOutputFilter.doWrite(ByteChunk, Response) org.apache.coyote.http11.AbstractOutputBuffer.doWrite(ByteChunk, Response) org.apache.coyote.Response.doWrite(ByteChunk) org.apache.catalina.connector.OutputBuffer.realWriteBytes(byte[], int, int) org.apache.tomcat.util.buf.ByteChunk.flushBuffer() org.apache.tomcat.util.buf.ByteChunk.append(byte[], int, int) org.apache.catalina.connector.OutputBuffer.writeBytes(byte[], int, int) org.apache.catalina.connector.OutputBuffer.write(byte[], int, int) org.apache.catalina.connector.CoyoteOutputStream.write(byte[], int, int) org.apache.catalina.servlets.DefaultServlet.copyRange(InputStream, ServletOutputStream, long, long) org.apache.catalina.servlets.DefaultServlet.copy(CacheEntry, ServletOutputStream, DefaultServlet$Range) org.apache.catalina.servlets.DefaultServlet.serveResource(HttpServletRequest, HttpServletResponse, boolean) org.apache.catalina.servlets.DefaultServlet.doGet(HttpServletRequest, HttpServletResponse) javax.servlet.http.HttpServlet.service(HttpServletRequest, HttpServletResponse) javax.servlet.http.HttpServlet.service(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) edu.vt.middleware.servlet.filter.RequestDumperFilter.doFilter(ServletRequest, ServletResponse, FilterChain) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) com.github.inspektr.common.web.ClientInfoThreadLocalFilter.doFilter(ServletRequest, ServletResponse, FilterChain) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) edu.vt.middleware.servlet.filter.CharacterEncodingFilter.doFilter(ServletRequest, ServletResponse, FilterChain) org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) org.apache.catalina.core.StandardWrapperValve.invoke(Request, Response) org.apache.catalina.core.StandardContextValve.invoke(Request, Response) org.apache.catalina.authenticator.AuthenticatorBase.invoke(Request, Response) org.apache.catalina.core.StandardHostValve.invoke(Request, Response) org.apache.catalina.valves.ErrorReportValve.invoke(Request, Response) org.apache.catalina.valves.AccessLogValve.invoke(Request, Response) org.apache.catalina.core.StandardEngineValve.invoke(Request, Response) org.apache.catalina.connector.CoyoteAdapter.service(Request, Response) org.apache.coyote.http11.AbstractHttp11Processor.process(SocketWrapper) org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(SocketWrapper, SocketStatus) org.apache.tomcat.util.net.AprEndpoint$SocketProcessor.run() java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Runnable) java.util.concurrent.ThreadPoolExecutor$Worker.run() java.lang.Thread.run() ContainerBackgroundProcessor[StandardEngine[Catalina]] [RUNNABLE, IN_NATIVE] CPU time: 23:33 org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery() org.apache.catalina.session.JDBCStore.load(String) org.apache.catalina.session.StoreBase.processExpires() org.apache.catalina.session.PersistentManagerBase.processExpires() org.apache.catalina.session.ManagerBase.backgroundProcess() org.apache.catalina.core.ContainerBase.backgroundProcess() org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(Container, ClassLoader) org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(Container, ClassLoader) org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(Container, ClassLoader) org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run() java.lang.Thread.run() pool-10-thread-1 [WAITING] CPU time: 4:11 sun.misc.Unsafe.park(boolean, long) java.util.concurrent.locks.LockSupport.park(Object) java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await() java.util.concurrent.LinkedBlockingQueue.take() java.util.concurrent.ThreadPoolExecutor.getTask() java.util.concurrent.ThreadPoolExecutor$Worker.run() java.lang.Thread.run() Shown threads: 8 of 164 Graphs of CPU usage over time show a sharp increase when a second thread enters sendbb; conversely there is a sharp decrease as soon as all but a single thread drop out of the method. Additionally, there may be a correlation with CPU usage and the number of threads in sendbb; for example, the CPU burn may be greater when three threads are in sendbb versus two. This feels like a concurrency bug: hard to reproduce, sporadic, and correlates with number of threads acting on the same code path. Please let me know if you'd like me to do anything further that may help determine whether this is, in fact, a bug. I'm happy to create a bug report if needed. M --------------------------------------------------------------------- To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
