Bug #77238 DBCP fails to function when using com.mysql.jdbc.FailoverConnectionProxy
Submitted: 4 Jun 2015 1:24 Modified: 25 Jul 2015 16:15
Reporter: Joe Blow Email Updates:
Status: No Feedback Impact on me:
None 
Category:Connector / J Severity:S2 (Serious)
Version:5.1.30 OS:Any
Assigned to: CPU Architecture:Any

[4 Jun 2015 1:24] Joe Blow 
Description:
This bug is similar to #63284, specifically when MySQL is configured for a failover implementation DBCP ends up getting into a state where objects cannot be returned or borrowed.

Threads that are attempting to access the trace (ArrayList) object in AbandonedObjectPool end up encountering the same behaviour in #63284, and the following stack trace is present:

"http-bio-8080-exec-3286" #19649 daemon prio=5 tid=0x00002aacc721f800 nid=0x57d1 waiting for monitor entry [0x000000004f44f000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at com.mysql.jdbc.FailoverConnectionProxy.invoke(FailoverConnectionProxy.java:106)
	- waiting to lock <0x0000000445b0bd98> (a com.mysql.jdbc.FailoverConnectionProxy)
	at com.sun.proxy.$Proxy9.equals(Unknown Source)
	at org.apache.commons.dbcp.DelegatingConnection.innermostDelegateEquals(DelegatingConnection.java:169)
	at org.apache.commons.dbcp.DelegatingConnection.equals(DelegatingConnection.java:190)
	at java.util.ArrayList.remove(ArrayList.java:528)
	at org.apache.commons.dbcp.AbandonedObjectPool.returnObject(AbandonedObjectPool.java:101)
	- locked <0x0000000417233428> (a java.util.ArrayList)
	at org.apache.commons.dbcp.PoolableConnection.close(PoolableConnection.java:90)
	- locked <0x0000000787f4ba50> (a org.apache.commons.dbcp.PoolableConnection)
	at org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.close(PoolingDataSource.java:191)

The currently running thread is:

"http-bio-8080-exec-3328" #19683 daemon prio=5 tid=0x0000000021933800 nid=0x5b9b runnable [0x0000000050662000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.String.toCharArray(String.java:2886)
	at com.mysql.jdbc.PreparedStatement$ParseInfo. (PreparedStatement.java:356)
	at com.mysql.jdbc.PreparedStatement$ParseInfo. (PreparedStatement.java:205)
	at com.mysql.jdbc.PreparedStatement. (PreparedStatement.java:920)
	at com.mysql.jdbc.JDBC4PreparedStatement. (JDBC4PreparedStatement.java:47)
	at sun.reflect.GeneratedConstructorAccessor18.newInstance(Unknown Source)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:408)
	at com.mysql.jdbc.Util.handleNewInstance(Util.java:409)
	at com.mysql.jdbc.PreparedStatement.getInstance(PreparedStatement.java:839)
	at com.mysql.jdbc.ConnectionImpl.clientPrepareStatement(ConnectionImpl.java:1583)
	at com.mysql.jdbc.ConnectionImpl.prepareStatement(ConnectionImpl.java:4599)
	- locked <0x0000000445b0bd98> (a com.mysql.jdbc.FailoverConnectionProxy)
	at com.mysql.jdbc.LoadBalancedMySQLConnection.prepareStatement(LoadBalancedMySQLConnection.java:2173)
	at sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:483)
	at com.mysql.jdbc.LoadBalancingConnectionProxy.invoke(LoadBalancingConnectionProxy.java:644)
	- locked <0x0000000445b0bd98> (a com.mysql.jdbc.FailoverConnectionProxy)
	at com.mysql.jdbc.FailoverConnectionProxy.invoke(FailoverConnectionProxy.java:135)
	- locked <0x0000000445b0bd98> (a com.mysql.jdbc.FailoverConnectionProxy)
	at com.sun.proxy.$Proxy9.prepareStatement(Unknown Source)
	at org.apache.commons.dbcp.DelegatingConnection.prepareStatement(DelegatingConnection.java:295)
	at org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.prepareStatement(PoolingDataSource.java:318)

And there is a huge backlog of congested threads waiting to lock java.util.ArrayList, for example:

"http-bio-8080-exec-3313" #19676 daemon prio=5 tid=0x00002aacc4b8c800 nid=0x5b94 waiting for monitor entry [0x000000004f14e000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:84)
	- waiting to lock <0x0000000417233428> (a java.util.ArrayList)
	at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
	at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)

And

"http-bio-8080-exec-3308" #19671 daemon prio=5 tid=0x0000000020943800 nid=0x57e7 waiting for monitor entry [0x000000004e641000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.apache.commons.dbcp.AbandonedObjectPool.returnObject(AbandonedObjectPool.java:100)
	- waiting to lock <0x0000000417233428> (a java.util.ArrayList)
	at org.apache.commons.dbcp.PoolableConnection.close(PoolableConnection.java:90)
	- locked <0x000000045db9b4d0> (a org.apache.commons.dbcp.PoolableConnection)
	at org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.close(PoolingDataSource.java:191)

How to repeat:
It is not entirely clear how to replicate this behaviour in a simplistic manner similar to #63284.

Suggested fix:
The DBCP correctly functions and allows connections to be returned and borrowed from the pool.
[4 Jun 2015 1:28] Joe Blow 
Contains a sample list of thread dumps taken whilst the problem was present.

Attachment: sample_thread_dumps.zip (application/zip, text), 2.13 MiB.
[4 Jun 2015 1:29] Joe Blow 
This was replicated using the MySQL Connector / J 5.1.30, DBCP 1.4 & JIRA 6.3.4.
[25 Jun 2015 16:15] Filipe Silva 
Hi Joe,

Thank you for this bug report.

I recommend you to upgrade to Connector/J version 5.1.35 as the fail-over feature was completely reviewed in this release.

Please let us know if this fixes your problem.
[26 Jul 2015 1:00] Bugs System 
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".