1

I have a java servlet application that runs on tomcat with c3p0 configured in tomcat. I have an application that is used internally by just a few people at my organization. Typically there are 3 or less people using it and sometimes up to 5. So, not a lot of people. Often, and unpredictably, the application fails with the below error. Usually it occurs after a long period of idle time (overnight) and fails on the first request the next day. I have other production applications with a similar stack that don't have this issue but they are rarely idle. Here's the error (and yes, I've searched stackoverflow and seen others with similar issues but none of the solutions seem to work for me):

WARNING: com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@2a3252ed -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!
Mar 19, 2014 6:42:11 AM com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector run
WARNING: com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@2a3252ed -- APPARENT DEADLOCK!!! Complete Status:
        Managed Threads: 3
        Active Threads: 3
        Active Tasks:
                com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@b7eed31
                        on thread: C3P0PooledConnectionPoolManager[identityToken->2ykl7d901mnvek411mheiv|3a7f5639]-HelperThread-#2
                com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@3a0631dc
                        on thread: C3P0PooledConnectionPoolManager[identityToken->2ykl7d901mnvek411mheiv|3a7f5639]-HelperThread-#1
                com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@6cb38046
                        on thread: C3P0PooledConnectionPoolManager[identityToken->2ykl7d901mnvek411mheiv|3a7f5639]-HelperThread-#0
        Pending Tasks:
                com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@7caaab6a
                com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@28dbfc17
                com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask@2835ef6
                com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask@7ecf69c3
                com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask@6328c23f
                com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask@8e8e8f5
                com.mchange.v2.resourcepool.BasicResourcePool$AsyncTestIdleResourceTask@73163164
                com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@3604d743
                com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@77d08b69
                com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@1c70d7f3
                com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@3471a11b
Pool thread stack traces:
        Thread[C3P0PooledConnectionPoolManager[identityToken->2ykl7d901mnvek411mheiv|3a7f5639]-HelperThread-#2,5,main]
                java.net.SocketInputStream.socketRead0(Native Method)
                java.net.SocketInputStream.read(SocketInputStream.java:146)
                com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
                com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
                com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
                com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3116)
                com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3573)
                com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3562)
                com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4113)
                com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2570)
                com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2731)
                com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2812)
                com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2761)
                com.mysql.jdbc.StatementImpl.executeQuery(StatementImpl.java:1612)
                com.mysql.jdbc.ConnectionImpl.getTransactionIsolation(ConnectionImpl.java:3352)
                com.mchange.v2.c3p0.impl.NewPooledConnection.<init>(NewPooledConnection.java:125)
                com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:211)
                com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:184)
                com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:200)
                com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:1086)
                com.mchange.v2.resourcepool.BasicResourcePool.doAcquireAndDecrementPendingAcquiresWithinLockOnSuccess(BasicResourcePool.java:1073)
                com.mchange.v2.resourcepool.BasicResourcePool.access$800(BasicResourcePool.java:44)
                com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask.run(BasicResourcePool.java:1810)
                com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:648)
        Thread[C3P0PooledConnectionPoolManager[identityToken->2ykl7d901mnvek411mheiv|3a7f5639]-HelperThread-#1,5,main]
                com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:672)
        Thread[C3P0PooledConnectionPoolManager[identityToken->2ykl7d901mnvek411mheiv|3a7f5639]-HelperThread-#0,5,main]
                com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:672)

Here's my config in tomcat. Items in "capslock" are changed to protect the innocent:

<Resource name="jdbc/NAME_HERE" auth="Container"
              description="DESCRIPTION"
              jdbcUrl="jdbc:mysql://PATH_TO_RDS?autoReconnect=true"
              user="USER"
              password="PASS"
              type="com.mchange.v2.c3p0.ComboPooledDataSource"
              factory="org.apache.naming.factory.BeanFactory"
              driverClass="com.mysql.jdbc.Driver"
              maxPoolSize="50"
              minPoolSize="10"
              acquireIncrement="5"
              acquireRetryAttempts="0"
              acquireRetryDelay="3000"
              breakAfterAcquireFailure="false"
              maxConnectionAge="60"
              maxIdleTime="30"
              maxIdleTimeExcessConnections="10"
              idleConnectionTestPeriod="15"
              testConnectionOnCheckout="true"
              preferredTestQuery="SELECT 1"
              debugUnreturnedConnectionStackTraces="true"
              autoCommitOnClose="true"
    />

I am using C3P0 0.9.2.1, mchange 0.2.3.4, and mysql connector 5.1.26 at the server. I'm also using hibernate 3.2.5.ga in the application.

I don't know if it matters but we use RDS from Amazon, so it's not on localhost.

Any help would be appreciated. This has been going on for a while and I've tried everything I can find on various forums with no luck.

garagebrewer
  • 61
  • 6
  • At that point I would try a different connection pool. A Tomcat connection pool is a nice modern alternative https://people.apache.org/~fhanik/jdbc-pool/jdbc-pool.html – anttix Mar 19 '14 at 17:11
  • Debugging issues like these is very involved so I doubt you get an answer from stackoverflow. But you never know ;) – anttix Mar 19 '14 at 17:17
  • EDIT: This is a better link for Tomcat pool docs https://tomcat.apache.org/tomcat-7.0-doc/jdbc-pool.html – anttix Mar 19 '14 at 17:19
  • Hmm. So there's something unusual in this one. By the active tasks section alone, all ScatteredAcquireTasks, I'd normally say that "c3p0's Thread-pool Threads are hung in Connection acquisition. Attempts to acquire Connections from the DBMS are hanging, neither succeeding nor failing with an Exception. That is the problem you need to debug." However, looking at the active Thread stack traces, that's not the whole story. One Thread is hung at Connection acquisition, another is hung trying to acquire the Thread pool's monitor, a third for reasons that remain mysterious. – Steve Waldman Mar 19 '14 at 20:50
  • A question: What happens after you see this error? c3p0 tries to recover from this sort of deadlock. It interrupt()s the frozen Threads and discards them, runs backlogged tasks in one-off Threads, and sets up a new Thread pool. Does your app recover? Does the error repeat over and over? Or what? If you cycle (bring down then up) the DBMS, does the running application heal? – Steve Waldman Mar 19 '14 at 20:54
  • (if it it's possible to get a full Thread dump of your application (while it is in a broken state, showing monitor acquisition and custody, that might be helpful. if one Thread really is locked trying to acquire the Thread pool's monitor, it'd be good to see who's got it and isn't giving it up.) – Steve Waldman Mar 19 '14 at 20:58
  • 1
    autoReconnect=true looks supicious to me. In a connection pooled environment reconnects are better handled by the pool and not by the driver. What happens if you remove that flag? See the following post for a relevant quote from MySQL documentation http://stackoverflow.com/questions/667289/why-does-autoreconnect-true-not-seem-to-work – anttix Mar 19 '14 at 21:00
  • Steve, after I see the error, it immediately shows an OutOfMemoryError and then there are repeated attempts to recover but it loops through memory and deadlock errors. I suppose it's possible the system is out of memory first but that's not what shows in the logs. And, again, the strange thing is that the application logs memory and shows plenty free (on the last request from yesterday). Then it sits overnight and the 1st request the next day starts this sequence of errors (sometimes but more often recently). – garagebrewer Mar 20 '14 at 04:23
  • Anttix, I'm seriously considering an alternate connection pool. Although I've had different problems with tomcat's in the past. It's been a while and a few versions since I've tried that though. – garagebrewer Mar 20 '14 at 04:25

1 Answers1

2

Just to provide an answer, this all turned out to be a JVM memory issue. The JVM would run out of memory overnight. I don't know why but this server had some special garbage collector options turned on for tomcat and when I remove those, not only did the problem go away but the memory footprint on that machine is much smaller. The default garbage collector must be more aggressive then the one that was being used. The problem hasn't occurred in several weeks and was never related to c3p0, I don't think. C3P0 was just the one catching and reporting problems.

garagebrewer
  • 61
  • 6
  • mind sharing the GC flags you used? I'm experiencing this exact issue right now would love to try out your settings. Thanks – phatduckk May 07 '14 at 06:10
  • Well, I removed the bad flags, so I'm not 100% sure but I think I was using -XX:+UseConcMarkSweepGC. My current settings are to use: JAVA_OPTS="-Djava.awt.headless=true -Xmx1536m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/usr/share/tomcat7/dumps". Note, those last 2 were put in to catch heap dumps when it crashed again but since removing the aforementioned option fixed it, I've never had to deal with those. – garagebrewer May 07 '14 at 20:12