On Tue, Jan 13, 2015 at 11:49 AM, Darren Davis <dar...@virtualvoodoo.net> wrote:
First thing, please don't top post. The convention followed on this list is to either reply inline, like this, or reply at the bottom. 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. > I would agree. If things are working properly the validation request should return very quickly. As to what's happening here I can't say exactly, but do you by chance have a firewall in between Tomcat and the database? What can sometimes happen when there's a firewall between Tomcat and the database that causes similar behavior is that the firewall will disconnect persistent idle connections (your db connections) after a certain period of time (often 30 or 60 minutes). Depending on how the firewall is configured it may just passively drop packets for that connection. In this case, there's no way to know what's happened and it can take a considerable amount of time for the connection to timeout. If this is what's happening, you have a couple possibilities for working around it. - configure an idle validation test (i.e. testWhileIdle and friends). This should periodically send traffic, in the form of a validation query, to each connection sitting idle in the pool. - set maxAge to something less than the limit set by the firewall. If using Tomcat's jdbc-pool (not sure if this is supported by other pools), it will throw out connections older than this value (in ms). - reconfigure your idle limits so you don't have as many idle connections. You've likely got connections sitting idle in the pool for a very long time, which means you probably don't need that many idle connections. If you lower this, the connections might get used more and not be closed by the firewall. There's probably other possible fixes as well, those are in no particular order and just the first ones that came to mind. > 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 > I don't think this will help here, but it's a good idea. It's an optimization for the MySQL jdbc driver that should make your validation queries faster. Dan > > > "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? > > > > > >
