Running out of DB connections!

Question

I'm running a Spring/Hibernate connecting to MySQL setup using c3p0 as my connection pool. For some bizarre reason it runs out of connections when the system is under load (of course).

The site was pretty stable until we started hitting a new level of traffic (over a hundred concurrent users). At that point the DB would melt down (peg the CPU). My first action was in the application to improve performance through extensive caching and optimization of queries etc.

Now it will just run out of connections intermittently. It doesn't even seem that dependent on load. More on time which makes me think it's a leak but for the life of me I can't figure out where it would be coming from.

    WARN [2011-03-07 17:19:42,409] [TP-Processor38] (JDBCExceptionReporter.java:100) - SQL Error: 0, SQLState: null
ERROR [2011-03-07 17:19:42,409] [TP-Processor38] (JDBCExceptionReporter.java:101) - An attempt by a client to checkout a Connection has timed out.
ERROR [2011-03-07 17:19:42,410] [TP-Processor38] (HttpHeadFilter.java:46) - There was a problem passing thru filter:/is-this-guy-crazy-or-just-a-huge-dancing-with-the-stars-fan
org.springframework.web.util.NestedServletException: Request processing failed; nested exception is org.hibernate.exception.GenericJDBCException: could not execute query
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:659)
        at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:552)
        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.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:343)
        at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:109)

Caused by: java.sql.SQLException: An attempt by a client to checkout a Connection has timed out.
    at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:106)
    at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:65)
    at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:527)
    at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)

Here's my configuration:

 <bean id="dataSource" class="org.springframework.jdbc.datasource.LazyConnectionDataSourceProxy">
        <property name="targetDataSource" ref="rootDataSource" />
    </bean>
    <bean id="sessionFactory" class="org.springframework.orm.hibernate3.LocalSessionFactoryBean">
        <property name="mappingLocations" value="classpath:hibernate-mapping.xml" />
        <property name="hibernateProperties">
            <props>
                <prop key="hibernate.connection.provider_class">net.sf.hibernate.connection.C3P0ConnectionProvider</prop>
                <prop key="hibernate.dialect">${hibernate.dialect}</prop>
                <prop key="hibernate.show_sql">${hibernate.show_sql}</prop>
                <prop key="hibernate.cache.use_second_level_cache">true</prop>
                <prop key="hibernate.cache.use_query_cache">true</prop>
                <prop key="hibernate.cache.generate_statistics">true</prop>
                <prop key="hibernate.cache.provider_class">net.sf.ehcache.hibernate.EhCacheProvider</prop>
                <prop key="hibernate.generate_statistics">${hibernate.generate_statistics}</prop>
                <prop key="hibernate.connection.zeroDateTimeBehavior">convertToNull</prop>
                <prop key="hibernate.bytecode.use_reflection_optimizer">${hibernate.bytecode.use_reflection_optimizer}</prop>
                <!--<prop key="hibernate.hbm2ddl.auto">${hibernate.hbm2ddl.auto}</prop>-->
                <prop key="hibernate.jdbc.batch_size">${hibernate.jdbc.batch_size}</prop>

                <!--Actually, it seems the following property affects batch size (or explicit per relationship in the mapping)-->
                <!--<prop key="hibernate.default_batch_fetch_size">${hibernate.jdbc.batch_size}</prop>-->
            </props>
        </property>
        <property name="dataSource" ref="dataSource" />
    </bean>

    <bean id="rootDataSource" class="com.mchange.v2.c3p0.ComboPooledDataSource">
        <property name="driverClass" value="${jdbc.driver}" />
        <property name="jdbcUrl" value="${jdbc.url}" />
        <property name="user" value="${jdbc.username}" />
        <property name="password" value="${jdbc.password}" />
        <property name="initialPoolSize" value="20" />
        <property name="maxPoolSize" value="200" />
        <property name="checkoutTimeout" value="30000" />
        <property name="maxStatements" value="180" />

        <property name="minPoolSize">
            <value>${hibernate.c3p0.minPoolSize}</value>
        </property>
        <property name="acquireRetryAttempts">
            <value>${hibernate.c3p0.acquireRetryAttempts}</value>
        </property>
        <property name="acquireIncrement">
            <value>${hibernate.c3p0.acquireIncrement}</value>
        </property>
        <property name="idleConnectionTestPeriod">
            <value>${hibernate.c3p0.idleConnectionTestPeriod}</value>
        </property>
        <property name="maxIdleTime">
            <value>${hibernate.c3p0.maxIdleTime}</value>
        </property>
        <property name="maxIdleTimeExcessConnections">
            <value>${hibernate.c3p0.maxIdleTimeExcessConnections}</value>
        </property>
        <property name="maxConnectionAge">
            <value>${hibernate.c3p0.maxConnectionAge}</value>
        </property>
        <property name="preferredTestQuery">
            <value>${hibernate.c3p0.preferredTestQuery}</value>
        </property>
        <property name="testConnectionOnCheckin">
            <value>${hibernate.c3p0.testConnectionOnCheckin}</value>
        </property>
        <property name="numHelperThreads">
            <value>${hibernate.c3p0.numHelperThreads}</value>
        </property>
        <property name="unreturnedConnectionTimeout">
            <value>${hibernate.c3p0.unreturnedConnectionTimeout}</value>
        </property>
        <property name="debugUnreturnedConnectionStackTraces">
            <value>${hibernate.c3p0.debugUnreturnedConnectionStackTraces}</value>
        </property>
        <property name="automaticTestTable">
            <value>${hibernate.c3p0.automaticTestTable}</value>
        </property>
    </bean>
    hibernate.c3p0.acquireIncrement=5
hibernate.c3p0.minPoolSize=20
hibernate.c3p0.acquireRetryAttempts=30
hibernate.c3p0.idleConnectionTestPeriod=3600
hibernate.c3p0.maxIdleTime=7200
hibernate.c3p0.maxIdleTimeExcessConnections=1800    
hibernate.c3p0.maxConnectionAge=14400
hibernate.c3p0.preferredTestQuery=select 1;
hibernate.c3p0.testConnectionOnCheckin=false
hibernate.c3p0.numHelperThreads=6
hibernate.c3p0.unreturnedConnectionTimeout=0
hibernate.c3p0.debugUnreturnedConnectionStackTraces=true
hibernate.c3p0.automaticTestTable=test_connection;

I am running OpenSessionInViewInterceptor which should be closing the connections:

 <bean id="openSessionInViewInterceptor" class="org.springframework.orm.hibernate3.support.OpenSessionInViewInterceptor">
    <property name="sessionFactory">
        <ref bean="sessionFactory" />
    </property>
    <property name="flushModeName">
        <value>FLUSH_AUTO</value>
    </property>

</bean>

I am also using the spring annotations for @Transactional since I reuse my services in non web fronted code.

There are really only two options here, it's not releasing connections when done. Or it's hanging out chatting up the db like it's trying to get in her pants. If anyone has any ideas I would be grateful thx

FOLLOW UP: In the end it turns out I was leaking connections due to using OpenSessionInViewInterceptor. I had spring security running as a filter so it would connect to the DB and never close them. The fix was to move the OpenSessionInViewInterceptor to OpenSessionInViewFilter.

Answer 1

Try enabling logging and setting the c3p0.debugUnreturnedConnectionStackTraces property to true. Also set c3p0.unreturnedConnectionTimeout to something smaller than your average query time (1 sec?). Then any thing that takes longer than the timeout will log a stack trace. This should allow you to narrow down things pretty quickly.

If there's no pattern to the stack traces, it could just be that your pool is too small. You said 100 concurrent users, but any idea how many queries per second this is? If it's 100 queries per second and you have 20 connections, then each sql execution needs to take less than 200 ms (20 connections => 20 total seconds of work per sec of wall clock time to do 100 queries).

Answer 2

It's pretty unlikely that @Transactional leaks connections - otherwise, your site would stop working after the first 100 requests.

But there is another reason why this happens:

Maybe you have set a timeout for "dead" connections and some queries take longer than that. That means that your pool removed a busy connection as "dead" from the pool and requests another from the DB - until the DB pulls the plug.

To debug this, enable logging for your connection pool, so you can see when it requests new connections.