tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Marvin Addison <marvin.addi...@gmail.com>
Subject Excessive CPU w/APR Connectors on tomcat-native 1.1.22
Date Wed, 11 Jan 2012 22:42:12 GMT
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-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org


Mime
View raw message