c3p0 deadlock on RefurbishCheckinResourceTask, get

2019-09-07 07:34发布

问题:

I've a webApp deployed on tomcat6, there's an import message function, which will import a large amount of messages persisting them into an Oracle 11g database.

I'm getting the deadlock occasionally/unpredictably, after running import for a while.

The trace:

7 août 2014 13:04:38 com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector run
ATTENTION: com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@637d7dd6 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!
7 août 2014 13:04:38 com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector run
ATTENTION: com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@637d7dd6 -- APPARENT DEADLOCK!!! Complete Status: 
    Managed Threads: 8
    Active Threads: 8
    Active Tasks: 
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@55e4ef4e (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@45460ed4 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#3)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@49da1926 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#7)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@14bc659d (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@78597c06 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#4)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@6667f88e (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#5)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@2a5d8dbb (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#6)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@441364ad (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2)
    Pending Tasks: 
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@7ca35537
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@1370b3e5
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@9d7dc72
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@14bfd04d
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@3d0479df
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@27310c3a
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@519c7f0
Pool thread stack traces:
    Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0,5,main]
        com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:562)
    Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#3,5,main]
        com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:562)
    Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#7,5,main]
        com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:562)
    Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1,5,main]
        com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:562)
    Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#4,5,main]
        com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:562)
    Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#5,5,main]
        com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:562)
    Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#6,5,main]
        com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:562)
    Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2,5,main]
        com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:562)


7 août 2014 13:05:13 com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector run
ATTENTION: com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@637d7dd6 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!
7 août 2014 13:05:13 com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector run
ATTENTION: com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@637d7dd6 -- APPARENT DEADLOCK!!! Complete Status: 
    Managed Threads: 8
    Active Threads: 8
    Active Tasks: 
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@62ac4df7 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@e8fdc6f (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@4140546 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#3)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@70a25e6b (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#7)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@33e4fc92 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@4a6064a4 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#4)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@466c6e60 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#6)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@27e87047 (com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#5)
    Pending Tasks: 
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@bdba1dc
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@7be684ff
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@b9b2923
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@292c79d8
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@26f36906
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@114d8aa
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@7bf6e678
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@5c447da5
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@14950af6
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@3124219d
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask@7a92974e
Pool thread stack traces:
    Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1,5,main]
        org.netbeans.lib.profiler.server.ProfilerRuntimeMemory.getAndSendCurrentStackTrace(ProfilerRuntimeMemory.java:221)
        org.netbeans.lib.profiler.server.ProfilerRuntimeObjLiveness.traceObjAlloc(ProfilerRuntimeObjLiveness.java:281)
        com.mchange.v2.c3p0.impl.NewProxyConnection.<init>(NewProxyConnection.java:32)
        com.mchange.v2.c3p0.impl.NewProxyConnection.<init>(NewProxyConnection.java:1376)
        com.mchange.v2.c3p0.impl.NewPooledConnection.getConnection(NewPooledConnection.java:151)
        com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.refurbishResourceOnCheckin(C3P0PooledConnectionPool.java:285)
        com.mchange.v2.resourcepool.BasicResourcePool.attemptRefurbishResourceOnCheckin(BasicResourcePool.java:1615)
        com.mchange.v2.resourcepool.BasicResourcePool.access$200(BasicResourcePool.java:32)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask.run(BasicResourcePool.java:1228)
        com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:557)
    Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0,5,main]
        org.netbeans.lib.profiler.server.ProfilerRuntimeMemory.getAndSendCurrentStackTrace(ProfilerRuntimeMemory.java:221)
        org.netbeans.lib.profiler.server.ProfilerRuntimeObjLiveness.traceObjAlloc(ProfilerRuntimeObjLiveness.java:281)
        com.mchange.v2.c3p0.impl.NewProxyConnection.<init>(NewProxyConnection.java:32)
        com.mchange.v2.c3p0.impl.NewProxyConnection.<init>(NewProxyConnection.java:1376)
        com.mchange.v2.c3p0.impl.NewPooledConnection.getConnection(NewPooledConnection.java:151)
        com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.refurbishResourceOnCheckin(C3P0PooledConnectionPool.java:285)
        com.mchange.v2.resourcepool.BasicResourcePool.attemptRefurbishResourceOnCheckin(BasicResourcePool.java:1615)
        com.mchange.v2.resourcepool.BasicResourcePool.access$200(BasicResourcePool.java:32)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask.run(BasicResourcePool.java:1228)
        com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:557)
    Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#3,5,main]
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask.run(BasicResourcePool.java:1229)
        com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:557)
    Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#7,5,main]
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask.run(BasicResourcePool.java:1229)
        com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:557)
    Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2,5,main]
        org.netbeans.lib.profiler.server.ProfilerRuntimeMemory.getAndSendCurrentStackTrace(ProfilerRuntimeMemory.java:221)
        org.netbeans.lib.profiler.server.ProfilerRuntimeObjLiveness.traceObjAlloc(ProfilerRuntimeObjLiveness.java:281)
        java.util.HashMap.addEntry(Unknown Source)
        java.util.HashMap.put(Unknown Source)
        java.util.HashSet.add(Unknown Source)
        com.mchange.v2.c3p0.util.ConnectionEventSupport.addConnectionEventListener(ConnectionEventSupport.java:39)
        com.mchange.v2.c3p0.impl.NewPooledConnection.addConnectionEventListener(NewPooledConnection.java:194)
        com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.refurbishResourceOnCheckin(C3P0PooledConnectionPool.java:290)
        com.mchange.v2.resourcepool.BasicResourcePool.attemptRefurbishResourceOnCheckin(BasicResourcePool.java:1615)
        com.mchange.v2.resourcepool.BasicResourcePool.access$200(BasicResourcePool.java:32)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask.run(BasicResourcePool.java:1228)
        com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:557)
    Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#4,5,main]
        org.netbeans.lib.profiler.server.ProfilerRuntimeMemory.getAndSendCurrentStackTrace(ProfilerRuntimeMemory.java:221)
        org.netbeans.lib.profiler.server.ProfilerRuntimeObjLiveness.traceObjAlloc(ProfilerRuntimeObjLiveness.java:281)
        java.util.HashMap.clone(Unknown Source)
        java.util.HashSet.clone(Unknown Source)
        com.mchange.v2.c3p0.util.ConnectionEventSupport.fireConnectionClosed(ConnectionEventSupport.java:49)
        com.mchange.v2.c3p0.impl.NewPooledConnection.fireConnectionClosed(NewPooledConnection.java:439)
        com.mchange.v2.c3p0.impl.NewPooledConnection.markClosedProxyConnection(NewPooledConnection.java:318)
        com.mchange.v2.c3p0.impl.NewProxyConnection.close(NewProxyConnection.java:1246)
        com.mchange.v1.db.sql.ConnectionUtils.attemptClose(ConnectionUtils.java:41)
        com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.refurbishResourceOnCheckin(C3P0PooledConnectionPool.java:292)
        com.mchange.v2.resourcepool.BasicResourcePool.attemptRefurbishResourceOnCheckin(BasicResourcePool.java:1615)
        com.mchange.v2.resourcepool.BasicResourcePool.access$200(BasicResourcePool.java:32)
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask.run(BasicResourcePool.java:1228)
        com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:557)
    Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#6,5,main]
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask.run(BasicResourcePool.java:1229)
        com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:557)
    Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#5,5,main]
        com.mchange.v2.resourcepool.BasicResourcePool$1RefurbishCheckinResourceTask.run(BasicResourcePool.java:1229)
        com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:557)

It seems that there are plenty of RefurbishCheckinResourceTask, and according to the trace, c3p0 fails to getConnection. I'm using Spring, hibernate, c3p0.

My c3p0 configuration:

<bean id="pmiDataSource" class="com.mchange.v2.c3p0.ComboPooledDataSource"
    destroy-method="close">
    <property name="driverClass" value="oracle.jdbc.driver.OracleDriver" />
    <property name="jdbcUrl" value="jdbc:oracle:thin:********" />
    <property name="user" value="****" />
    <property name="password" value="****" />
    <property name="acquireIncrement" value="5" />
    <property name="numHelperThreads" value="6" />
    <property name="minPoolSize" value="10" />
    <property name="initialPoolSize" value="15" />
    <property name="maxPoolSize" value="25" />
</bean>

My hibernate properties:

<property name="hibernateProperties">
    <value>
        hibernate.dialect=org.hibernate.dialect.Oracle10gDialect
        hibernate.auto_close_session=true
        hibernate.validator.autoregister_listeners=false
        hibernate.validator.apply_to_ddl=false
        hibernate.cache.use_second_level_cache=true
        hibernate.cache.region.factory_class=net.sf.ehcache.hibernate.EhCacheRegionFactory
        hibernate.cache.use_query_cache=false
        javax.persistence.validation.mode=none
        hibernate.generate_statistics=true
    </value>
</property>

I've checked a lot of forum about this, one of the most similar case was this. c3p0 apparent deadlock / creating emergency threads. APPARENT DEADLOCK 0.9.1.2

Could some help please?

回答1:

It's not a c3p0 problem, in fact its my own fault.

I used a TaskExecutor to run a multi-treaded inner runnalbe task. Since this procedure makes call from inner instance to outer class method, it has to deal with the synchronization problem, which I ignored in the first place.

When the inner instances run into some error due to synchronization, it will block some c3p0 connection from returning back to the connection-pool.

So this turned out to be an outer-inner-class instance method call problem. Just need to be careful with synchronization issues.

Sometimes the error won't show on a development machine, but once it's published on a more powerful production machine with many cores, the error can easily happen.