Re: Tomcat JDBC Pool Cleaner Deadlock Problem

Mon, 31 Aug 2020 09:53:53 -0700 


On 8/31/20 3:21 AM, Felix Schumacher wrote:

Am 31.08.20 um 06:15 schrieb Gokhan Akgul:

Dear Phil ,
Thanks for your feedback. I forgot to mention the mysql driver version. The
Mysql driver version is 5.1.32.
My plan is to upgrade the mysql driver to 5.1.46 version and monitor for a
while.

If I read the bug report correctly, MySQL will not change its logic and
therefore using newer versions of the driver will not help.



Yeah.  There was a comment in another related bug report about changing 
the locking model in 5.1.x, so it is possible a later version will help, 
but you are right that it probably won't.




What MySQL advises is to change the pool to use the abort-Method of the
connection to close it in the case of abandoned connections.

The dbcp2 pools seems to be able to use that method, while I found no
reference to it in the jdbc-pool module (which you are using).



We are talking about making that change on commons-dev now [1], but 
currently dbcp2 uses close as jdbc-pool does.


Comments / patches welcome!

Phil



So, maybe it is a good idea to switch the used pool from the jdbc-pool
to the default tomcat pool (see
http://tomcat.apache.org/tomcat-9.0-doc/jndi-datasource-examples-howto.html).
It should work equally well (I am not sure, if it supports something
like the slowqueryreport, though). If you want to continue using the old
jdbc-pool module, you might want to file a bug on the bugtracker asking
for an enhancement to support the abort method. (I would use the dbcp2
pool.)

Felix




[1] 
https://lists.apache.org/thread.html/r598c0f654477372d112858af1c18bfc04008250156989647d883576f%40%3Cdev.commons.apache.org%3E





On Sat, Aug 29, 2020 at 6:50 PM Phil Steitz <phil.ste...@gmail.com> wrote:


On 8/27/20 2:47 AM, Gokhan Akgul wrote:

Hi ,

I have been facing the deadlock issue for the last 2 months  about
JDBCPoolCleaner Thread .

Following config set in context.xml

<Resource name="jdbc/database"
               auth="Container"
               type="javax.sql.DataSource"
               factory="org.apache.tomcat.jdbc.pool.DataSourceFactory"
               driverClassName="com.mysql.jdbc.Driver"


  
url="jdbc:mysql://adress:3306/db?useUnicode=true&amp;characterEncoding=latin5&amp;characterResultSet=latin5&amp;zeroDateTimeBehavior=convertToNull&amp;autoReconnect=true&amp;interactiveClient=true"

               username="user"
               password="pass"
               initialSize="10"
               maxActive="30"
               maxIdle="15"
               minIdle="10"
               maxWait="30000"
               timeBetweenEvictionRunsMillis="5000"
               minEvictableIdleTimeMillis="60000"
               removeAbandonedTimeout="600"
               removeAbandoned="true"
               logAbandoned="false"
               testWhileIdle="true"
               testOnBorrow="true"
               testOnReturn="false"
               validationQuery="/* ping */ SELECT 1"
               validationInterval="30000"
               jmxEnabled="true"


  
jdbcInterceptors="ConnectionState;StatementFinalizer;ResetAbandonedTimer;SlowQueryReport"

      />



Thread dump

Tomcat JDBC Pool Cleaner[63445188:1598345711425] id=16 state=BLOCKED
      - waiting to lock <0x57dcb0b7> (a

com.mysql.jdbc.JDBC4PreparedStatement)

       owned by http-nio-8080-exec-8 id=25
      at

com.mysql.jdbc.PreparedStatement.realClose(PreparedStatement.java:3078)

      at

com.mysql.jdbc.ConnectionImpl.closeAllOpenStatements(ConnectionImpl.java:1584)

      at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4364)
      at com.mysql.jdbc.ConnectionImpl.close(ConnectionImpl.java:1556)
      at

org.apache.tomcat.jdbc.pool.PooledConnection.disconnect(PooledConnection.java:388)

      at

org.apache.tomcat.jdbc.pool.PooledConnection.release(PooledConnection.java:618)

      at

org.apache.tomcat.jdbc.pool.ConnectionPool.release(ConnectionPool.java:612)

      at

org.apache.tomcat.jdbc.pool.ConnectionPool.abandon(ConnectionPool.java:569)

      at

org.apache.tomcat.jdbc.pool.ConnectionPool.checkAbandoned(ConnectionPool.java:999)

      at

org.apache.tomcat.jdbc.pool.ConnectionPool$PoolCleaner.run(ConnectionPool.java:1468)

      at java.util.TimerThread.mainLoop(Timer.java:555)
      at java.util.TimerThread.run(Timer.java:505)

      Locked synchronizers: count = 1
        -

java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync@58039868


http-nio-8080-exec-8 id=25 state=BLOCKED
      - waiting to lock <0x42de9995> (a com.mysql.jdbc.JDBC4Connection)
       owned by Tomcat JDBC Pool Cleaner[63445188:1598345711425] id=16
      at

com.mysql.jdbc.ConnectionImpl.useAnsiQuotedIdentifiers(ConnectionImpl.java:5435)

      at

com.mysql.jdbc.DatabaseMetaData.getIdentifierQuoteString(DatabaseMetaData.java:3269)

      at com.mysql.jdbc.DatabaseMetaData.<init>(DatabaseMetaData.java:675)
      at

com.mysql.jdbc.JDBC4DatabaseMetaData.<init>(JDBC4DatabaseMetaData.java:39)

      at sun.reflect.GeneratedConstructorAccessor24.newInstance(Unknown

Source)

      at

sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)

      at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
      at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
      at

com.mysql.jdbc.DatabaseMetaData.getInstance(DatabaseMetaData.java:657)

      at

com.mysql.jdbc.ConnectionImpl.getMetaData(ConnectionImpl.java:3064)

      at

com.mysql.jdbc.ConnectionImpl.getMetaData(ConnectionImpl.java:3056)

      at

com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2315)

      at sun.reflect.GeneratedMethodAccessor43.invoke(Unknown Source)
      at

sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

      at java.lang.reflect.Method.invoke(Method.java:606)
      at

org.apache.tomcat.jdbc.pool.interceptor.AbstractQueryReport$StatementProxy.invoke(AbstractQueryReport.java:210)

      at com.sun.proxy.$Proxy44.executeQuery(Unknown Source)
      at sun.reflect.GeneratedMethodAccessor43.invoke(Unknown Source)
      at

sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

      at java.lang.reflect.Method.invoke(Method.java:606)
      at

org.apache.tomcat.jdbc.pool.interceptor.AbstractQueryReport$StatementProxy.invoke(AbstractQueryReport.java:210)

      at com.sun.proxy.$Proxy44.executeQuery(Unknown Source)
      at sun.reflect.GeneratedMethodAccessor43.invoke(Unknown Source)
      at

sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

      at java.lang.reflect.Method.invoke(Method.java:606)
      at

org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:114)

      at com.sun.proxy.$Proxy44.executeQuery(Unknown Source)
      at

org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)

      at org.hibernate.loader.Loader.getResultSet(Loader.java:1953)
      at org.hibernate.loader.Loader.doQuery(Loader.java:802)
      at

org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274)

      at org.hibernate.loader.Loader.doList(Loader.java:2542)
      at

org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2276)

      at org.hibernate.loader.Loader.list(Loader.java:2271)
      at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:459)
      at

org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:365)

      at

org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196)

      at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1268)
      at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
      at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:246)

      ......

      at

com.gg.healthcheck.servlet.HealthCheckServlet.getServiceStatus(HealthCheckServlet.java:68)

      at

com.gg.healthcheck.servlet.HealthCheckServlet.doGet(HealthCheckServlet.java:45)

      at javax.servlet.http.HttpServlet.service(HttpServlet.java:626)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:733)
      at

org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)

      at

org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)

      at

org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)

      at

org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)

      at

org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)

      at

org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)

      at

org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)

      at

org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)

      at

org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)

      at

org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)

      at

org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)

      at

org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:543)

      at

org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)

      at

org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)

      at

org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:690)

      at

org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)

      at

org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)

      at

org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:615)

      at

org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)

      at

org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:818)

      at org.apache.tomcat.util.net

.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1626)

      at org.apache.tomcat.util.net

.SocketProcessorBase.run(SocketProcessorBase.java:49)

        - locked org.apache.tomcat.util.net

.NioEndpoint$NioSocketWrapper@526aa725

      at

java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

      at

java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

      at

org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)

      at java.lang.Thread.run(Thread.java:745)

      Locked synchronizers: count = 1
        - java.util.concurrent.ThreadPoolExecutor$Worker@21c6b5b9


It looks to me like the deadlock is caused by inconsistent lock
acquisition order by the JDBC driver.  The driver locks the connection
in the cleaner's close method, but when cleaning up open statements it
needs the lock on a statement.  The application thread first acquires
the statement lock but then needs the connection lock.  The result is a
deadlock.

See the discussion of this mysql driver bug:

https://bugs.mysql.com/bug.php?id=64954

There is a comment there about the locking model being changed in a
later version of the driver, so you might try upgrading to the latest
driver compatible with your jdk and tomcat version.

Phil



Tomcat version : 8.8.57
Java 7
Application is a simple spring mvc application.
Runs on Kubernetes



Do you have any idea how to solve it?


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org



---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org



---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org























					Reply via email to