On Tue, Jan 13, 2015 at 2:33 PM, Christopher Schultz < ch...@christopherschultz.net> wrote:
> -----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 > > HI Christopher. Yes, we've tried a show process list and can find no evidence of the validation query running on mysql. We also just tried an experiment outside of Tomcat completely, but connecting to a downed web server host and manually opening up a mysql client connection to the data server and executing a single command. We left that client window idle for an hour and 5 minutes, and attempted to execute a simple select count(*) command against a tiny table. The client attempted to execute the query, and a NetStat on that box showed an open connection between the two servers using port 3306. We also checked the process list during this time and could not find any queries at all from the sever in question. At about the 15 minute wait mark, the client finally came back with this message: "ERROR 2013 (HY000): Lost connection to MySQL server during query. Attempting the execute the command a 2nd time (using the up arrow), re-established the connection and it ran perfectly in a few milliseconds. I checked the mysql configuration and it is set to the default values for keeping connections/interactive connections open (for 8 hours), so it seems that maybe the Cisco firewall between the two servers is terminating connections out from under us, but in a way what the O/S cannot detect it. I've also fired up the yourKit profiler on this box and am seeing other threads which have had to wait in the same SocketInputStream.read code, all three started a few seconds apart, it just wasn't detected as a deadlock, because it took place outside of any synchronized methods. It seems that sometime around the hour mark, connections get dropped, so we're thinking that either adding idle checking or dropping old connections may help us avoid this. Although we are a little concerned by the various Connector / J alleged socket read issues which may as a possible problem. We're running an older 5.1.18 version of the Connector/J driver, but aren't sure of moving to the latest .34 release would change anything.
