Hi All,

I am having some issues with FBWrappingDataSource (version 2.1.4 of the JayBird
Driver) where once the maximum number of connections in the pool are created, my
application can no longer obtain connectiond from the pool.

This occurs even though the debug log for JayBird indicates that my connections
are being returned to the connection pool.

I am not sure if this is a Driver issue or a Spring issue.

The Definition of the datasource in the spring container is as follows:

<bean id="dataSource"
class="org.firebirdsql.pool..FBWrappingDataSource"
destroy-method="shutdown">
<property name="database"
value="${dbhost}/${dbport}:${dbpath}" />
<property name="blockingTimeout" value="${cpblockingtimeout}" />
<property name="defaultIsolation" >
<util:constant
static-field="org.firebirdsql.jdbc.FBConnectionHelper.TRANSACTION_SERIALIZABLE"
/>
</property>
<property name="description" value="My Database" />
<property name="maxIdleTime" value="${cpmaxidletime}" />
<property name="maxPoolSize" value="${cpmaxpoolsize}" />
<property name="maxStatements" value="${cpmaxstatements}" />
<property name="minPoolSize" value="${cpminpoolsize}" />
<property name="loginTimeout" value="${cplogintimeout}" />
<property name="pingInterval" value="${cppinginterval}" />
<property name="pingStatement"
value="SELECT cast(1 AS INTEGER) FROM RDB$DATABASE" />
<property name="retryInterval" value="${cpretryinterval}" />
<property name="socketBufferSize" value="${cpsocketbufszie}" />
<property name="type" value="PURE_JAVA" />
<property name="pooling" value="true" />
</bean>

The values for the various variables above are as follows in the properties file:

dbhost=localhost
dbport=3050
dbpath=/blah/blah/mydb.gdb
cpblockingtimeout=5000
cpmaxidletime=2147483
cpmaxstatements=1000
cpmaxpoolsize=10
cpminpoolsize=0
cpsocketbufszie=8192
cppinginterval=5000
cpretryinterval=1000
cplogintimeout=5

My test code simply spawns a bunch of threads that use SimpleJdbcTemplate (via a DAO object) to obtain a single record from the database (Firebird 1.5/SI-V1.5.3.4870).

I have log4j set up to capture all messages in debug mode from the JayBird driver.

What I am seeing is that the driver provides/creates a connection for each request up until the pool is full (max 10 connections) and then further connection requests are rejected even though the application threads (via SimpleJdbcTemplate) are releasing the connections back to the pool. At this point, I cannot seem to determine why the connections released back to the pool can't be reused by other threads.

A Sample from the JayBird Driver Log follows:

This section shows where Spring starts up, instantiates the FBWrappingDataSource and then attempts to get the database name so it can use the sql-error-codes.xml file if found...

[DEBUG] 13 Apr 2009 10:54:31,714: Thread main wants to take connection.
[DEBUG] 13 Apr 2009 10:54:31,715: Trying to create connection, total connections 0, max allowed 10
[DEBUG] 13 Apr 2009 10:54:31,780: Got socket
[DEBUG] 13 Apr 2009 10:54:31,785: user.name: root
[DEBUG] 13 Apr 2009 10:54:31,786: op_connect
[DEBUG] 13 Apr 2009 10:54:31,786: sent
[DEBUG] 13 Apr 2009 10:54:31,786: op_accept
[DEBUG] 13 Apr 2009 10:54:31,786: received
[DEBUG] 13 Apr 2009 10:54:31,786: op_attach
[DEBUG] 13 Apr 2009 10:54:31,787: sent
[DEBUG] 13 Apr 2009 10:54:31,788: op_response
[DEBUG] 13 Apr 2009 10:54:31,788: readStatusVector arg:isc_arg_gds int: 0
[DEBUG] 13 Apr 2009 10:54:31,788: received
[DEBUG] 13 Apr 2009 10:54:31,788: op_info_database
[DEBUG] 13 Apr 2009 10:54:31,788: sent
[DEBUG] 13 Apr 2009 10:54:31,788: op_response
[DEBUG] 13 Apr 2009 10:54:31,788: readStatusVector arg:isc_arg_gds int: 0
[DEBUG] 13 Apr 2009 10:54:31,788: received
[DEBUG] 13 Apr 2009 10:54:31,789: parseDatabaseInfo: first 2 bytes are 318 or: 62, 1
[DEBUG] 13 Apr 2009 10:54:31,789: isc_info_db_sql_dialect:3
[DEBUG] 13 Apr 2009 10:54:31,791: isc_info_firebird_version:SI-V1.5.3.4870 Firebird 1.5/SI-V1.5.3.4870 Firebird 1.5/tcp (outermate)/P10
[DEBUG] 13 Apr 2009 10:54:31,792: isc_info_ods_version:10
[DEBUG] 13 Apr 2009 10:54:31,792: isc_info_ods_minor_version:1
[INFO ] 13 Apr 2009 10:54:31,839: Pool supports open statements across commit : true
[INFO ] 13 Apr 2009 10:54:31,839: Pool supports open statements across rollback : true
[DEBUG] 13 Apr 2009 10:54:31,840: Thread main created connection.
[DEBUG] 13 Apr 2009 10:54:31,841: Thread main got connection.
[DEBUG] 13 Apr 2009 10:54:31,865: Thread main released connection.

Here are some excerpts from where the application is actually running:
[DEBUG] 13 Apr 2009 10:58:09,423: Thread pool-2-thread-15 wants to take connection.
[DEBUG] 13 Apr 2009 10:58:09,423: Trying to create connection, total connections 1, max allowed 10
[DEBUG] 13 Apr 2009 10:58:09,424: Got socket

This repeats over and over with the total connections count incrementing by 1 each time a new thread wants a connection by calling SimpleJdbcTemplate.query...

Scattered throughout the log are these indications that threads are releasing the connections back to the pool:

[WARN ] 13 Apr 2009 10:58:09,623: Pool localhost/3050:/blah/blah/mydb.gdb will be unblocked
[DEBUG] 13 Apr 2009 10:58:09,623: Thread pool-2-thread-9 released connection.
[DEBUG] 13 Apr 2009 10:58:09,624: Thread pool-2-thread-15 released connection.

etc...

Once the total number of max connections have been created (10 in this case) the following messages start showing up in the log, even though by that time, all 10 previous connections have been released back to the pool. This is just the excerpt for a single thread trying to get a connection after all 10 have been created and released back to the pool:

[WARN ] 13 Apr 2009 10:58:10,860: No connection in pool. Thread pool-2-thread-7
[DEBUG] 13 Apr 2009 10:58:10,860: Trying to create connection, total connections 10, max allowed 10
[DEBUG] 13 Apr 2009 10:58:10,860: Was not able to add more connections.
[WARN ] 13 Apr 2009 10:58:10,860: Pool localhost/3050:/blah/blah/mydb.gdb is empty and will block here. Thread pool-2-thread-7
[WARN ] 13 Apr 2009 10:58:11,870: No connection in pool. Thread pool-2-thread-7
[DEBUG] 13 Apr 2009 10:58:11,870: Trying to create connection, total connections 10, max allowed 10
[DEBUG] 13 Apr 2009 10:58:11,870: Was not able to add more connections.
[WARN ] 13 Apr 2009 10:58:11,870: Pool localhost/3050:/blah/blah/mydb.gdb is empty and will block here. Thread pool-2-thread-7
[WARN ] 13 Apr 2009 10:58:12,880: No connection in pool. Thread pool-2-thread-7
[DEBUG] 13 Apr 2009 10:58:12,880: Trying to create connection, total connections 10, max allowed 10
[DEBUG] 13 Apr 2009 10:58:12,880: Was not able to add more connections.
[WARN ] 13 Apr 2009 10:58:12,880: Pool localhost/3050:/blah/blah/mydb.gdb is empty and will block here. Thread pool-2-thread-7
[WARN ] 13 Apr 2009 10:58:13,890: No connection in pool. Thread pool-2-thread-7
[DEBUG] 13 Apr 2009 10:58:13,890: Trying to create connection, total connections 10, max allowed 10
[DEBUG] 13 Apr 2009 10:58:13,890: Was not able to add more connections.
[WARN ] 13 Apr 2009 10:58:13,890: Pool localhost/3050:/blah/blah/mydb.gdb is empty and will block here. Thread pool-2-thread-7
[WARN ] 13 Apr 2009 10:58:14,900: No connection in pool. Thread pool-2-thread-7
[DEBUG] 13 Apr 2009 10:58:14,900: Thread pool-2-thread-5 wants to take connection.
[DEBUG] 13 Apr 2009 10:58:14,900: Trying to create connection, total connections 10, max allowed 10
[DEBUG] 13 Apr 2009 10:58:14,900: Was not able to add more connections.

This repeats for all the other threads that are trying to obtain a connection.

I am at a loss as to understand what is happening or why the pool refuses to give out connections that have been released back to it.

I am not using any sort of Spring transactions or anything fancy other than the typical CRUD model with Domain Objects and DAO objects in spring. The first 10 threads that do obtain connections actually return valid sql results as expected.

My expectation is that each of the threads will sleep for the blocking timeout period and then retry according to the retryinterval value and eventually will return with an error to the application if there really are no connections in the pool.

Any help in sorting this out would be greatly appreciated.

Thanks in advance for the help.
Jim