Timed out waiting for a free available connection.

[chris]

Hi,

In some stress tests of my application I'm guessing the following exception (BoneCP 0.7.0):

Caused by: java.sql.SQLException: Timed out waiting for a free available connection.
at com.jolbox.bonecp.BoneCP.getConnection(BoneCP.java:432)
at com.jolbox.bonecp.BoneCPDataSource.getConnection(BoneCPDataSource.java:91)

I don't have a timeout set for BoneCP, so I'm thinking it should default to Long.MAX_VALUE, so I'm not sure why I'm getting this exception.

Our application has 128 threads that are doing reasonably quick database operations, but they may occasionally take a while, here's the BoneCP config:

<property name="idleMaxAge" value="30"/>
<property name="idleConnectionTestPeriod" value="30"/>
<property name="partitionCount" value="${bonecp.partitionCount}"/>
<property name="acquireIncrement" value="10"/>
<property name="maxConnectionsPerPartition" value="20"/>
<property name="minConnectionsPerPartition" value="60"/>
<property name="statementsCacheSize" value="0"/>
<property name="releaseHelperThreads" value="3"/>
<property name="connectionTestStatement" value="select 1"/>

It starts to happen an hour or so after starting our stress test, and our stress test does around 100 operations per second. We were seeing the exception several times an hour. Using the profiler YourKit, I saw there was quite a bit of contention on the monitor for Connections from the threads making the call, and the statement release helper threads, so I disabled them by adding the following to the config:

<property name="statementReleaseHelperThreads" value="0"/>

This brought down the number of exceptions drastically, down to around one every few hours.

Any thoughts or help would be appreciate.

Thanks,
Chris

[wwadge]

Hi,

First of all can you try repeating this test using v0.7.1-rc4 please (it's available in maven central repo).

There were quite some fixes put in place post v0.7.0 branch.

Wallace

[fennec]

Hi,

I am able to reproduce the same error with a performance UT when I set more clients than connections. I set 10 connections and 100 clients. The DB is HSQL in "in memory" mode. I can't reproduce the issue with MSSQL Server, DB2 or Oracle but I think it might hide a "fairness" issue the is triggered more easily with HSQL.

Here are my parameters :
idleConnectionTestPeriodInMinutes=1
idleMaxAgeInMinutes=5
maxConnectionsPerPartition=10
minConnectionsPerPartition=1
partitionCount=1
acquireIncrement=1
statementsCacheSize=100
releaseHelperThreads=1

I tried with 3 releaseHelperThreads but it was the same. It is intentional to have mode clients than connections.

Version is
X-Compile-Target-JDK: 1.6
Implementation-Version: 0.7.1.RELEASE

Here is a stack :
java.sql.SQLException: Timed out waiting for a free available connection.
at com.jolbox.bonecp.BoneCP.getConnection(BoneCP.java:503)
at com.jolbox.bonecp.BoneCPDataSource.getConnection(BoneCPDataSource.java:114)

[wwadge]

This is really odd. Here's the code that triggers it:

Code: Select all

result = connectionPartition.getFreeConnections().poll(this.connectionTimeoutInMs, TimeUnit.MILLISECONDS);
            if (result == null){
               if (this.nullOnConnectionTimeout){
                  return null;
               }
               // 08001 = The application requester is unable to establish the connection.
               throw new SQLException("Timed out waiting for a free available connection.", "08001");
            }


with this.connectionTimeoutInMs set to Long.Max_Value

Have you got a working snippet of code that reproduces this problem? For the record I've never hit this issue even though I hammer it quite a number of times.

[fennec]

If I explicitly set connectionTimeoutInMs to 300000 then I don't run into the problem. What is your implementation queue for retrieving free connections ? Maybe you're using a magic value or something ?

Unfortunately I can't give you a standalone snipet, it is a very large application and I can't separate it without spending week doing it.

Is the queue you're using guaranties that the oldest "clients" will be served first ?

[wwadge]

If I explicitly set connectionTimeoutInMs to 300000 then I don't run into the problem. What is your implementation queue for retrieving free connections ? Maybe you're using a magic value or something ?

Nope, no magic values or anything of that sort. In fact the queue (blockingqueue) doesn't even accept nulls so I'm definitely not injecting it here. The connectionTimeoutInMs thing is pretty odd for if it's set to zero (the default) it gets replaced by Long.MAX_VALUE. I tried testing it out to see what happens to see if it was overflowing or something but everything looks fine

Are you using Sun's JDK?

[fennec]

Yes I use Sun jdk1.6.0_20, I could upgrade for tests but our product must ship with jdk1.6.0_20. BTW I'm on windows for this test.

BlockingQueue is an interface, what implementation are you using ? ArrayBlockingQueue ?

Also I think I'm hitting concurrency issues or something with statement cache, I have to set statementsCacheSize=0 or I get random SQLException when under heavy load:
Caused by: java.sql.BatchUpdateException: Invalid column name 'ServiceId'.
at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeBatch(SQLServerStatement.java:1723)
at com.jolbox.bonecp.StatementHandle.executeBatch(StatementHandle.java:469)

This is very strange because other similar queries of the same batch (delete from test_1026051201 where ServiceId = 883072) are executing correctly. I can reproduce the error with SQL Server and HSQL.

[wwadge]

Yes I use Sun jdk1.6.0_20, I could upgrade for tests but our product must ship with jdk1.6.0_20. BTW I'm on windows for this test.

BlockingQueue is an interface, what implementation are you using ? ArrayBlockingQueue ?

I use LinkedTransferQueue (http://gee.cs.oswego.edu/dl/concurrent/dist/docs/java/util/concurrent/TransferQueue.html) in the default case. I also use Sun's JDK too btw. There do seem to be some related JVM bugs on the internal locks though: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6822370.

I've hammered it a bit but the only way I can see it making sense is that the poll routine is not obeying Long.MAX_VALUE as a delay value for some odd reason.

Also I think I'm hitting concurrency issues or something with statement cache, I have to set statementsCacheSize=0 or I get random SQLException when under heavy load:
Caused by: java.sql.BatchUpdateException: Invalid column name 'ServiceId'.
at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeBatch(SQLServerStatement.java:1723)
at com.jolbox.bonecp.StatementHandle.executeBatch(StatementHandle.java:469)

This is very strange because other similar queries of the same batch (delete from test_1026051201 where ServiceId = 883072) are executing correctly. I can reproduce the error with SQL Server and HSQL.

[/quote]

Let's deal with this separately when we're done with the first one for now.

[fennec]

Is there a way to use another queue ? BTW I'm using a dual core machine, the JDK bug seems to occur on 4/8 core machines on specific non-windows platform.

Do you have a fail safe configuration to recommend ?
Here is my current configuration :
pool.class=com.jolbox.bonecp.BoneCPDataSource
pool.driverClass=org.hsqldb.jdbc.JDBCDataSource
pool.jdbcUrl=geturl()
pool.username=$USER
pool.password=$PASSWORD
pool.idleConnectionTestPeriodInMinutes=1
pool.idleMaxAgeInMinutes=5
pool.maxConnectionsPerPartition=$MAX_CONNECTIONS:40
pool.minConnectionsPerPartition=1
pool.partitionCount=1
pool.acquireIncrement=1
pool.statementsCacheSize=100
pool.releaseHelperThreads=1
pool.ConnectionTimeoutInMs=$LOGIN_TIMEOUT:30000
pool.poolName=$ROLE

[wwadge]

You can try using serviceMode set to LIFO that uses a different queue implementation though it isn't as heavily tested (but should work).

As to failsafe config:
1. Disable release helper threads (= set to zero)
2. Disable statement cache (= set to zero)

The rest of your config is fine. For extra paranoia you can set minconnections = max connections to disable pool resizing but this shouldn't affect you at all.

For what it's worth I'm testing on Windows on an i7 machine (8 core), java version "1.6.0_18".

I wish I could reproduce your issue at least once