Missing connections in tomcat jdbc connection pool

yael alfasi picture yael alfasi · Jul 12, 2012 · Viewed 20.4k times · Source

We just migrated from dbcp to tomcat jdbc connection pooling. We tried the system in load and received the following exception:

java.sql.SQLException: [IA1856] Timeout: Pool empty. Unable to fetch a connection in 1 seconds, none available[size:125; busy:90; idle:0; lastwait:1000].
        at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:632)
        at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:174)
        at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:124)
        at com.inneractive.model.mappings.BasicPersistenceEntityMapping.getConnection(BasicPersistenceEntityMapping.java:233)
        at com.inneractive.model.mappings.BasicPersistenceEntityMapping.callWithConnection(BasicPersistenceEntityMapping.java:243)
        at com.inneractive.model.mappings.PersistenceEntityMapping.get(PersistenceEntityMapping.java:194)
        at com.inneractive.model.data.client.ClientUtils.GetClientByExamples(ClientUtils.java:353)
        at com.inneractive.client.ExternalAdRingsClientStart.getClientInfoByRequestParametersOrInsert(ExternalAdRingsClientStart.java:1329)
        at com.inneractive.client.ExternalAdRingsClientStart.newClientSession(ExternalAdRingsClientStart.java:245)
        at com.inneractive.simpleM2M.web.SimpleM2MProtocolBean.generateCampaign(SimpleM2MProtocolBean.java:235)
        at com.inneractive.simpleM2M.web.SimpleM2MProtocolBean.generateCampaign(SimpleM2MProtocolBean.java:219)
        at com.inneractive.simpleM2M.web.AdsServlet.doGet(AdsServlet.java:175)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:617)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:555)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:859)
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588)
        at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:396)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)

Notice this:

[size:125; busy:90; idle:0; lastwait:1000]

Where are the connections that are not busy? The busy number kept going down after this, but we still didnt manage to get any connections.

Any ideas?

Configuration:

<Resource auth="Container" driverClassName="com.mysql.jdbc.Driver"
                factory="org.apache.tomcat.jdbc.pool.DataSourceFactory" loginTimeout="10000"
                maxActive="35" maxIdle="35" maxWait="1000" name="jdbc/mysql"
                password="-----" testOnBorrow="true" testOnReturn="false" type="javax.sql.DataSource"
                url="jdbc:mysql://localhost:3306/my_db?elideSetAutoCommits=true&amp;useDynamicCharsetInfo=false&amp;rewriteBatchedStatements=true&amp;useLocalSessionState=true&amp;useLocalTransactionState=true&amp;alwaysSendSetIsolation=false&amp;cacheServerConfiguration=true&amp;noAccessToProcedureBodies=true&amp;useUnicode=true&amp;characterEncoding=UTF-8"
                username="root" validationQuery="SELECT 1"/>

env: ubuntu and tomcat 6. db - mysql

Answer

hovanessyan picture hovanessyan · Jul 26, 2012

Taking a look at the source of ConnectionPool.java you seem to hit this code snippet in the borrowConnection() method:

        //we didn't get a connection, lets see if we timed out
        if (con == null) {
            if ((System.currentTimeMillis() - now) >= maxWait) {
                throw new SQLException("[" + Thread.currentThread().getName()+"] " +
                    "Timeout: Pool empty. Unable to fetch a connection in " + (maxWait / 1000) +
                    " seconds, none available["+busy.size()+" in use].");
            } else {
                //no timeout, lets try again
                continue;
            }
        }

So according to this, your connection is Null.

The value of con is retrieved on the line:

PooledConnection con = idle.poll();

if you track the code, you will see idle is (depending on your configuration, but by default) FairBlockingQueue. You may checkout the implementation for hints.

In general you always have to close ResultSets, Statements, and Connections and used connections should be correctly released back to the pool. Not doing so correctly may result in connections never been closed => never being available again for reuse (connection pool "leaks").

I suggest you construct some detailed logging over the state of the pool and monitor it to isolate the problem.

Some guidelines from Apache for preventing database connection pool leaks:

removeAbandoned="true"

abandoned database connections are removed and recycled

removeAbandonedTimeout="60"

set the number of seconds a database connection has been idle before it is considered abandoned

logAbandoned="true"

log a stack trace of the code which abandoned the database connection resources. Keep in mind that "logging of abandoned Connections adds overhead for every Connection borrow because a stack trace has to be generated."

I still think slightly increasing the maxWait value (1200, 1500, 1700 - just experiment, there will be no difference in the response times from user perspective) will clear those rare cases, in which you still have problems.