-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA256 Darren,
On 1/13/15 1:04 PM, Christopher Schultz wrote: > On 1/13/15 11:49 AM, Darren Davis wrote: >> 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. > > Agreed. > >> 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. > > The problem is with the driver and/or database, not with the > connection pool. It's not surprising that you are experiencing > problems regardless of the pool being used. > >> we've come across documentation that suggests we could modify our >> validation statement by prefixing it with /* ping */, which >> we're thinking about trying > > Using "/* ping */" is usually a good idea for MySQL, but it may > mask the problem. What you may find is that the next "real" query > you use hangs for 15 minutes. If you are going to use /* ping */ > and you are going to use the tomcat-jdbc pool, then you may as well > not configure a validation query at all because Tomcat's pool will > use Connection.isValid which amounts to the same thing (and will > work for any compliant JDBC driver, not just with MySQL). > >> "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) > > Is it possible to rule-out any network problems? Is there any > pattern at all to the pauses? Another thought: what do you get if you run SHOW PROCESSLIST on the server during these long pauses? I remember a guy who once did a START TRANSACTION and then locked up some tables before going to lunch without either a ROLLBACK or COMMIT, and he help up loads of transactions that were waiting to get locks (presumably for PK sequences or whatever). Could there be some other process that is starting a conflicting transaction here? "SELECT 1" should require no no locks whatsoever, but it might be something silly like contention with the query cache. I've seen MySQL do some colossally stupid things before... maybe something odd like that is happening, here. - -chris -----BEGIN PGP SIGNATURE----- Version: GnuPG v1 Comment: GPGTools - http://gpgtools.org iQIcBAEBCAAGBQJUtY8jAAoJEBzwKT+lPKRYsvUP/28Mpo5cV1Xeogqc4JWspJbi zWwyHM1J9sLps8nYib2+DUtxBfUYaEIXtCzoZ62e4/Z1c9h/oJaECFocnvz8fSbS Af5cPJexPSMkx6ggOLl61ymBYiZmItJwtfhwoyh+DDQmPZalFU6znJ/txHKUO5+7 MmxccIo9N/S7mmktUYaeG63MIq8v/gmH9+VsDEChYqbucK6n11EL+Y+whfntfcWS pS18vkYlF1albiB7Epd7fl6wuoZH1hoTJsnr23lIEP42hH8Kb7yE49nIaAM/IB1D vXMRQSWhLNZCpEWpa3wJGJk19DeTJaTcs+yuJIDtPyZxtuCPlA7zDqdTGQmLdKgf aWq08ei6Vq5POWrIdBHJ6OHZUgsgBmMS7c53INNm7sC+XXY4hIUW5SWoZQUHERoG 3ms+LMJtaP5zhteFYc8BvptFuIHreZCL19kcaRA0W1BPnhxXKL9C1e/BJG1LCS8d b5UH4xC4LPcmz0FF6/e9DH81SBmRTR4EWcLekFxjihtBtDxxl52GnjFFB/ynsFvd PweCCo9R+itj5hUhFj3VQqli8DF+3/puwikHlaQjQEvi3smVP0faTSL6b89zk3uM T/DzEIyyvvLA45qQoxFbUsDBNWvJYDbr3NZu7pty+XNupsD1Ys4mxTxce0rjHhk4 EJjblPF13mtCisFA2z/p =9u7v -----END PGP SIGNATURE----- --------------------------------------------------------------------- To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
