The problem occurred again this morning. I was able to generate a thread
dump and narrow down the source of our problem to tomcat thread 23.
>From 8:45:51,397 to 09:01:19,083, it was stuck in the validate check for a
newly instantiated connection:
I ran the thread dump several times during this interval, and the stack
trace for thread 23 did not change at all.
I did check our database log file and determined that during the 8 hours
that led up to our first error on the server yesterday, we had just a total
of 12 unique connections. The problem occurred the the creation of
connection # 13, which was then used several other times later.
The incident this morning also coincided with creating a new connection in
the pool. It does not make any sense that the simple validation query of
"SELECT 1" would require a wait of 15 minutes to succeed.
It's also strange that this only happens sporadically, and not every time a
new connection is being "birthed" by the system.
We've tried two different pooling technologies: DBCP and the new Apache
JDBC pooling on this server and both exhibit the same 15 minute occasional
wait.
we've come across documentation that suggests we could modify our
validation statement by prefixing it with /* ping */, which we're thinking
about trying
"http-nio-8443-exec-23" #156 daemon prio=5 os_prio=0 tid=0x00007f0658387000
nid=0x7a60 runnable [0x00007f05e7466000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.$$YJP$$socketRead0(Native Method)
at java.net.SocketInputStream.socketRead0(SocketInputStream.java)
at java.net.SocketInputStream.read(SocketInputStream.java:150)
at java.net.SocketInputStream.read(SocketInputStream.java:121)
at
com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
at
com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
at
com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
- locked <0x00000000bdf09420> (a
com.mysql.jdbc.util.ReadAheadInputStream)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2549)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3002)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2991)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3532)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2002)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2618)
- locked <0x00000000bdf04df0> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568)
at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:842)
- locked <0x00000000bdf04df0> (a com.mysql.jdbc.JDBC4Connection)
- locked <0x00000000ff107cd8> (a com.mysql.jdbc.StatementImpl)
at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:681)
at
org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:503)
at
org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:437)
at
org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:763)
at
org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:617)
at
org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:186)
at
org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:127)
at
org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:83)
at
org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446)
at
org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167)
at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160)
at
org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)
at
org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473)
at
org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:556)
at
org.springframework.transaction.support.AbstractPlatformTransactionManager.handleExistingTransaction(AbstractPlatformTransactionManager.java:424)
at
org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:348)
at
org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:417)
at
org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:255)
at
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy77.findOrCreateSystemTask(Unknown Source)
at
com.tracom.max.service.impl.SynchronizationServiceImpl.findOrCreateSystemTask(SynchronizationServiceImpl.java:115)
- locked <0x00000000a45652b8> (a
com.tracom.max.service.impl.SynchronizationServiceImpl)
at
com.tracom.max.service.impl.SessionServiceImpl.processRaterInvitation(SessionServiceImpl.java:1767)
at
com.tracom.max.service.impl.SessionServiceImpl.addRaterToSession(SessionServiceImpl.java:1697)
at sun.reflect.GeneratedMethodAccessor566.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at
org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)
at
org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)
at
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy64.addRaterToSession(Unknown Source)
at
com.tracom.tracomlearning.controller.InviteRaterController.processInviteRater(InviteRaterController.java:461)
at sun.reflect.GeneratedMethodAccessor565.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at
org.springframework.web.method.support.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:215)
at
org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:132)
at
org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:104)
at
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:745)
at
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:685)
at
org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:80)
at
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:919)
at
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:851)
at
org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:953)
at
org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:855)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:644)
at
org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:829)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:725)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:291)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at
com.tracom.tracomlearning.utils.XSSFilter.doFilterInternal(XSSFilter.java:33)
at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:106)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)
at
org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:118)
at
org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:84)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at
org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:113)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at
org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:103)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at
org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:113)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at
org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:54)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at
org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:45)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at
org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:150)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at
org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:183)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at
org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:105)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at
org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)
at
org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)
at
org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192)
at
org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)
at
org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:343)
at
org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:260)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at
org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:106)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:239)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:506)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:142)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
at
org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:610)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:537)
at
org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1081)
at
org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:658)
at
org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:222)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1566)
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1523)
- locked <0x00000000fecbac90> (a
org.apache.tomcat.util.net.SecureNioChannel)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
On Tue, Jan 13, 2015 at 8:21 AM, Daniel Mikusa <dmik...@pivotal.io> wrote:
> On Tue, Jan 13, 2015 at 9:51 AM, Darren Davis <dar...@virtualvoodoo.net>
> wrote:
>
> > Recently we deployed our production application on a Tomcat 8.0.14 web
> > server. We are using the Tomcat JDBC Connection pool against MySQL 5.
> Our
> > web application uses Spring (3.2.11.RELEASE) /Hibernate (3.6.10.Final)
> for
> > transaction management. We are using a Cent OS 6 linux server in the
> cloud
> > running the 2.6.32-504 kernel. We're using the 1.8.0_25 jdk.
> >
> >
> >
> > Ever since deployment, we've noticed that a couple of times per day, when
> > Spring is attempting to prepare/open a new JDBC Connection, the thread in
> > question times out for about 15 minutes, and then resumes as if
> everything
> > is fine.
> >
>
> What's the CPU usage like at this time? Seems unlikely, but maybe your in
> the middle of a massive full GC.
>
>
> >
> > The line that appears to be hanging from the hibernate side is
> > factory.getConnectionProvider().getConnection(), which I think simply
> asks
> > for a connection from the pool.
> >
>
> Out of curiosity how did you determine this? Did you take a thread dump?
> If not, that would be a good place to start. Grab three or four thread
> dumps during that 15 minute window. The thread dump will tell you exactly
> what's happening in the thread at the time. Looking at multiple dumps will
> also show you if the thread has progressed from one dump to the next.
>
> Instructions for taking at thread dump can be found here:
>
>
>
> http://wiki.apache.org/tomcat/HowTo#How_do_I_obtain_a_thread_dump_of_my_running_webapp_.3F
>
> Dan
>
>
> >
> > The following options are defined in the Resource definition:
> > auth="Container"
> > factory="org.apache.tomcat.jdbc.pool.DataSourceFactory"
> > type="javax.sql.DataSource"
> > driverClassName="com.mysql.jdbc.Driver"
> > maxActive=500
> > maxIdle=55
> > maxWait=15000
> > validationQuery="Select 1"
> > testOnBorrow="true"
> > defaultAutoCommit="false"
> >
> > At this time of year, our user load peaks around 150, so we shouldn't be
> > coming close to the maxActive defined. MySql is configured to allow for
> > 1010 maximum connections (we have two Tomcat instances that point to it,
> > configured similarly)
>
>
> > This application has ran for years without a problem against a Tomcat 6
> > instance, but after moving to Jdk 8 and Tomcat 8, we're seeing this 15
> > minute wait.
> >
> > Any ideas on what could cause this sort of thing, and as there additional
> > logging we could turn on to try and figure out what is happening inside
> the
> > pool to make it wait so long?
> >
>
