Apache pauses unexpectedly to make a request

Question

After running the web application for a day, the login load properly but don't work. The log show a tomcat pause in the moment of request.

I'm using:

• Spring 3
• c3p0
• MySql
• and Tomcat 7

The log is as follows:

Jan 06, 2014 9:56:18 PM org.apache.coyote.AbstractProtocol pause
INFO: Pausing ProtocolHandler ["http-bio-8080"]
Jan 06, 2014 9:56:18 PM org.apache.coyote.AbstractProtocol pause
INFO: Pausing ProtocolHandler ["ajp-bio-8009"]
Jan 06, 2014 9:56:18 PM org.apache.catalina.core.StandardService stopInternal
INFO: Stopping service Catalina
Jan 06, 2014 9:56:18 PM org.apache.catalina.core.StandardWrapper unload
INFO: Waiting for 19 instance(s) to be deallocated for Servlet [Faces Servlet]
Jan 06, 2014 9:56:19 PM org.apache.catalina.core.StandardWrapper unload
INFO: Waiting for 19 instance(s) to be deallocated for Servlet [Faces Servlet]
Jan 06, 2014 9:56:20 PM org.apache.catalina.core.StandardWrapper unload
INFO: Waiting for 19 instance(s) to be deallocated for Servlet [Faces Servlet]
Jan 06, 2014 9:56:20 PM org.apache.catalina.core.StandardWrapper unload
INFO: Waiting for 18 instance(s) to be deallocated for Servlet [default]
Jan 06, 2014 9:56:21 PM org.apache.catalina.core.StandardWrapper unload
INFO: Waiting for 18 instance(s) to be deallocated for Servlet [default]
Jan 06, 2014 9:56:22 PM org.apache.catalina.core.StandardWrapper unload
INFO: Waiting for 18 instance(s) to be deallocated for Servlet [default]
java.sql.SQLException: An SQLException was provoked by the following failure:        java.lang.InterruptedException
       at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:106)
       at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:65)
       at com.mchange.v2.sql.SqlUtils.toSQLException(SqlUtils.java:62)
       at   com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:531)
       at com.mchange.v2.c3p0.impl.AbstractPoolBackedDataSource.getConnection(AbstractPoolBackedDataSource.java:128)
       at com.tda.financiero.common.JasperReportProvider.llenarReporte(JasperReportProvider.java:116)
       at com.tda.financiero.common.JasperReportProvider.ejecutarReportePDF(JasperReportProvider.java:53)
       at com.tda.financiero.common.ReporteServiceImpl.generarFacturaPDF(ReporteServiceImpl.java:26)
       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
       at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
       at java.lang.reflect.Method.invoke(Method.java:606)
       at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:318)
       at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
           ...
Caused by: java.lang.InterruptedException
       at java.lang.Object.wait(Native Method)
       at com.mchange.v2.resourcepool.BasicResourcePool.awaitAvailable(BasicResourcePool.java:1315)
       at com.mchange.v2.resourcepool.BasicResourcePool.prelimCheckoutResource(BasicResourcePool.java:557)
       at com.mchange.v2.resourcepool.BasicResourcePool.checkoutResource(BasicResourcePool.java:477)
       at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.checkoutPooledConnection(C3P0PooledConnectionPool.java:525)
... 79 more
Jan 06, 2014 9:56:22 PM javax.faces.event.MethodExpressionActionListener processAction
SEVERE: Received 'java.lang.NullPointerException' when invoking action listener '#{userManagedBean.login()}' for component 'login'
Jan 06, 2014 9:56:23 PM javax.faces.event.MethodExpressionActionListener processAction
SEVERE: java.lang.NullPointerException
at org.apache.catalina.session.ManagerBase.generateSessionId(ManagerBase.java:807)
at org.apache.catalina.session.ManagerBase.createSession(ManagerBase.java:653)

The log also show a NullPointerException but is after of the another exception. Any ideas? It would be good if you can give me hints where to look or how to go about anaysing this problem. Thanks!

EDIT

I used Spring's applicationContext file for configure c3p0 pool connections, all DAOs use sessionFactory, the services is annotated with @Transactional. In brief, Spring controls the connections. Only 2 users using the application, I think with c3p0 defaults is enough so I had that configuration.

<bean id="dataSource" class="com.mchange.v2.c3p0.ComboPooledDataSource" destroy-method="close">
    <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="testConnectionOnCheckin" value="true"/>
    <property name="idleConnectionTestPeriod" value="3600"/>  
    <property name="preferredTestQuery" value="SELECT 1" />             
</bean>

<!-- Session Factory Declaration -->
<bean id="sessionFactory" class="org.springframework.orm.hibernate4.LocalSessionFactoryBean">
    <property name="dataSource" ref="dataSource" />
    <property name="packagesToScan" value="com.tda.financiero.domain.model"/>       
    <property name="hibernateProperties">
        <props>
            <prop key="hibernate.dialect">org.hibernate.dialect.MySQLDialect</prop>
            <!-- <prop key="hibernate.show_sql">true</prop> -->  
        </props>
    </property>
</bean>

<!-- Enable the configuration of transactional behavior based on annotations -->
<tx:annotation-driven transaction-manager="txManager"/>

<!-- Transaction Manager is defined -->
<bean id="txManager" class="org.springframework.orm.hibernate4.HibernateTransactionManager">
   <property name="sessionFactory" ref="sessionFactory"/>
</bean>

Answer 1

So, you had some clients trying to checkout Connections from a c3p0 DataSource, but wait()ing because no Connections were available. At some point, those Threads were interrupt()ed. It is impossible to say form what you have listed above by what they were interrupt()ed. It does not look like these Threads explicitly timed-out [c3p0 has a config param called checkoutTimeout], because then you would have seen a TimeoutException rather than the InterruptedException.

So, one thing to wonder is, what interrupted these Threads? They are client Threads, probably spawned by Tomcat, not c3p0-internal Threads. c3p0 didn't interrupt() them.

Another, perhaps more productive, thing to wonder is, why were these Threads wait()ing for Connections that ought to have been available for them in the Connection pool? Was your Connection pool too small for the load it experiences, in which case the best response is to increase the c3p0 parameter maxPoolSize? Does the Connection pool have so much load that, despite a sufficiently large maxPoolSize, Connection maintenance tasks are becoming backlogged? In this case, the c3p0 config property numHelperThreads might help.

Or, perhaps the most common problem, does your application leak Connections? That is, does it occasionally checkout Connections from the DataSource that it ultimately fails to close()? Does your application ensure that all Connections it checks out are close()ed in a finally block, even if an Exception occurs while cleaning up other resources in the finally blocks? If running Java 7, do you acquire Connections using the wonderful new try-with-resources syntax?

You've offered no information about the scale, load, or configuration of your application, but Connection leaks are by far the most common cause of Threads hanging too long trying to acquire database Connections. c3p0 has two configuration parameters unreturnedConnectionTimeout and debugUnreturnedConnectionStackTraces to help you work around and (please!) debug and fix Connection leaks. See the discussion here.

Using these params to check whether you have a parameter leak is the first thing I'd try, given the information you've given.

If you know that your app has a high concurrent load, though, you might play with maxPoolSize. And via JMX, you can monitor whether c3p0's Thread pool is keeping up, or whether you might want to increase numHelperThreads.