I'm running into an issue where I deploy a JBI unit onto SMX, it analyzes my
hibernate-annotated POJOs and starts (or wants) to create tables in the
database, and then runs into an "APPARENT DEADLOCK" issue with c3p0. The
funny thing is that when I unit test this, I get no such issues. Table
creation is just fine and I'm able to persist data. Its when I package it
into a JBI unit and deploy it on SMX is when I get the deadlock issue. Due
to the deadlocks, no tables were created. Is SMX doing something in
particular that hogs up all of the connections in the c3p0 pool upon
initialization? Below is a stacktrace:
#########################
......
10:00:01,684 | INFO | Thread-7 | PoolBackedDataSource |
e.v2.c3p0.PoolBackedDataSource 269 | Initializing c3p0 pool...
[EMAIL PROTECTED] [ connectionPoolDataSource
-> [EMAIL PROTECTED] [
acquireIncrement -> 1, acquireRetryAttempts -> 30, acquireRetryDelay ->
1000, autoCommitOnClose -> false, automaticTestTable -> null,
breakAfterAcquireFailure -> false, checkoutTimeout -> 0,
connectionTesterClassName ->
com.mchange.v2.c3p0.impl.DefaultConnectionTester, factoryClassLocation ->
null, forceIgnoreUnresolvedTransactions -> false, identityToken -> 1636731,
idleConnectionTestPeriod -> 3000, initialPoolSize -> 5, maxIdleTime -> 300,
maxPoolSize -> 20, maxStatements -> 0, maxStatementsPerConnection -> 0,
minPoolSize -> 5, nestedDataSource ->
[EMAIL PROTECTED] [ description -> null,
driverClass -> null, factoryClassLocation -> null, identityToken -> 1128ee5,
jdbcUrl -> jdbc:mysql://localhost:3306/test, properties -> {user=******,
password=******, release_mode=on_close} ], preferredTestQuery -> null,
propertyCycle -> 300, testConnectionOnCheckin -> false,
testConnectionOnCheckout -> false, usesTraditionalReflectiveProxies ->
false; userOverrides: {} ], dataSourceName -> 1516490, factoryClassLocation
-> null, identityToken -> 1516490, numHelperThreads -> 3 ]
10:00:01,700 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 81 | RDBMS: MySQL, version:
5.0.27-community-nt
10:00:01,700 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 82 | JDBC driver: MySQL-AB JDBC Driver,
version: mysql-connector-java-5.0.4 ( $Date: 2006-10-19 17:47:48 +0200 (Thu,
19 Oct 2006) $, $Revision: 5908 $ )
10:00:01,715 | INFO | Thread-7 | Dialect |
org.hibernate.dialect.Dialect 151 | Using dialect:
org.hibernate.dialect.MySQLDialect
10:00:01,715 | INFO | Thread-7 | ransactionFactoryFactory |
tion.TransactionFactoryFactory 31 | Using default transaction strategy
(direct JDBC transactions)
10:00:01,715 | INFO | Thread-7 | tionManagerLookupFactory |
ransactionManagerLookupFactory 33 | No TransactionManagerLookup configured
(in JTA environment, use of read-write or transactional second-level cache
is not recommended)
10:00:01,715 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 134 | Automatic flush during
beforeCompletion(): disabled
10:00:01,715 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 138 | Automatic session close at end of
transaction: disabled
10:00:01,715 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 145 | JDBC batch size: 20
10:00:01,715 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 148 | JDBC batch updates for versioned data:
disabled
10:00:01,731 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 153 | Scrollable result sets: enabled
10:00:01,731 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 161 | JDBC3 getGeneratedKeys(): enabled
10:00:01,731 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 169 | Connection release mode: on_close
10:00:01,731 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 193 | Maximum outer join fetch depth: 2
10:00:01,731 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 196 | Default batch fetch size: 1
10:00:01,731 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 200 | Generate SQL with comments: disabled
10:00:01,731 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 204 | Order SQL updates by primary key:
disabled
10:00:01,731 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 369 | Query translator:
org.hibernate.hql.ast.ASTQueryTranslatorFactory
10:00:01,731 | INFO | Thread-7 | STQueryTranslatorFactory |
.ast.ASTQueryTranslatorFactory 24 | Using ASTQueryTranslatorFactory
10:00:01,731 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 212 | Query language substitutions:
{false='F', true='T'}
10:00:01,746 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 217 | JPA-QL strict compliance: disabled
10:00:01,746 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 222 | Second-level cache: enabled
10:00:01,746 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 226 | Query cache: disabled
10:00:01,746 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 356 | Cache provider:
org.hibernate.cache.NoCacheProvider
10:00:01,746 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 241 | Optimize cache for minimal puts:
disabled
10:00:01,746 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 250 | Structured second-level cache entries:
disabled
10:00:01,746 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 270 | Echoing all SQL to stdout
10:00:01,746 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 277 | Statistics: disabled
10:00:01,746 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 281 | Deleted entity synthetic identifier
rollback: disabled
10:00:01,746 | INFO | Thread-7 | SettingsFactory |
.hibernate.cfg.SettingsFactory 296 | Default entity-mode: pojo
10:00:01,762 | INFO | Thread-7 | DatabaseMetadata |
.tool.hbm2ddl.DatabaseMetadata 96 | table not found: Customer_Relationship
10:00:01,762 | INFO | Thread-7 | C3P0ConnectionProvider |
nection.C3P0ConnectionProvider 50 | C3P0 using driver:
com.mysql.jdbc.Driver at URL: jdbc:mysql://localhost:3306/test
10:00:01,762 | INFO | Thread-7 | C3P0ConnectionProvider |
nection.C3P0ConnectionProvider 51 | Connection properties: {user=root,
password=****, release_mode=on_close}
10:00:01,762 | INFO | Thread-7 | C3P0ConnectionProvider |
nection.C3P0ConnectionProvider 54 | autocommit mode: false
10:00:01,825 | INFO | Thread-7 | PoolBackedDataSource |
e.v2.c3p0.PoolBackedDataSource 269 | Initializing c3p0 pool...
[EMAIL PROTECTED] [ connectionPoolDataSource
-> [EMAIL PROTECTED] [
acquireIncrement -> 1, acquireRetryAttempts -> 30, acquireRetryDelay ->
1000, autoCommitOnClose -> false, automaticTestTable -> null,
breakAfterAcquireFailure -> false, checkoutTimeout -> 0,
connectionTesterClassName ->
com.mchange.v2.c3p0.impl.DefaultConnectionTester, factoryClassLocation ->
null, forceIgnoreUnresolvedTransactions -> false, identityToken -> a53e68,
idleConnectionTestPeriod -> 3000, initialPoolSize -> 5, maxIdleTime -> 300,
maxPoolSize -> 20, maxStatements -> 0, maxStatementsPerConnection -> 0,
minPoolSize -> 5, nestedDataSource ->
[EMAIL PROTECTED] [ description -> null,
driverClass -> null, factoryClassLocation -> null, identityToken -> e2cf81,
jdbcUrl -> jdbc:mysql://localhost:3306/test, properties -> {user=******,
password=******, release_mode=on_close} ], preferredTestQuery -> null,
propertyCycle -> 300, testConnectionOnCheckin -> false,
testConnectionOnCheckout -> false, usesTraditionalReflectiveProxies ->
false; userOverrides: {} ], dataSourceName -> 1fccfe3, factoryClassLocation
-> null, identityToken -> 1fccfe3, numHelperThreads -> 3 ]
10:00:21,840 | WARN | Timer-123 | adPoolAsynchronousRunner |
hronousRunner$DeadlockDetector 429 |
[EMAIL PROTECTED]
-- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending
tasks!
10:00:21,840 | WARN | Timer-123 | adPoolAsynchronousRunner |
hronousRunner$DeadlockDetector 435 |
[EMAIL PROTECTED]
-- APPARENT DEADLOCK!!! Complete Status: [num_managed_threads: 3,
num_active: 3; activeTasks:
[EMAIL PROTECTED]
(com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1),
[EMAIL PROTECTED]
(com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0),
[EMAIL PROTECTED]
(com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2);
pendingTasks:
[EMAIL PROTECTED],
[EMAIL PROTECTED]
10:00:31,167 | WARN |
com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0 |
BasicResourcePool | .BasicResourcePool$AcquireTask 1277 |
[EMAIL PROTECTED] --
Acquisition Attempt Failed!!! Clearing pending acquires. While trying to
acquire a needed new resource, we failed to succeed more than the maximum
number of allowed acquisition attempts (30). Last acquisition attempt
exception:
com.mysql.jdbc.exceptions.MySQLNonTransientConnectionException: Data source
rejected establishment of connection, message from server: "Too many
connections"
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:921)
at com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:997)
at com.mysql.jdbc.Connection.createNewIO(Connection.java:2670)
at com.mysql.jdbc.Connection.<init>(Connection.java:1531)
at
com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:266)
at
com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:107)
at
com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:161)
at
com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:113)
at
com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:728)
at
com.mchange.v2.resourcepool.BasicResourcePool.access$700(BasicResourcePool.java:32)
at
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask.run(BasicResourcePool.java:1258)
at
com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:368)
10:00:31,230 | WARN |
com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2 |
BasicResourcePool | .BasicResourcePool$AcquireTask 1277 |
[EMAIL PROTECTED] --
Acquisition Attempt Failed!!! Clearing pending acquires. While trying to
acquire a needed new resource, we failed to succeed more than the maximum
number of allowed acquisition attempts (30). Last acquisition attempt
exception:
com.mysql.jdbc.exceptions.MySQLNonTransientConnectionException: Data source
rejected establishment of connection, message from server: "Too many
connections"
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:921)
at com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:997)
at com.mysql.jdbc.Connection.createNewIO(Connection.java:2670)
at com.mysql.jdbc.Connection.<init>(Connection.java:1531)
at
com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:266)
at
com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:107)
at
com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:161)
at
com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:113)
at
com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:728)
at
com.mchange.v2.resourcepool.BasicResourcePool.access$700(BasicResourcePool.java:32)
at
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask.run(BasicResourcePool.java:1258)
at
com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:368)
10:00:31,167 | WARN |
com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1 |
BasicResourcePool | .BasicResourcePool$AcquireTask 1277 |
[EMAIL PROTECTED] --
Acquisition Attempt Failed!!! Clearing pending acquires. While trying to
acquire a needed new resource, we failed to succeed more than the maximum
number of allowed acquisition attempts (30). Last acquisition attempt
exception:
com.mysql.jdbc.exceptions.MySQLNonTransientConnectionException: Data source
rejected establishment of connection, message from server: "Too many
connections"
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:921)
at com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:997)
at com.mysql.jdbc.Connection.createNewIO(Connection.java:2670)
at com.mysql.jdbc.Connection.<init>(Connection.java:1531)
at
com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:266)
at
com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:107)
at
com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:161)
at
com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.acquireResource(C3P0PooledConnectionPool.java:113)
at
com.mchange.v2.resourcepool.BasicResourcePool.doAcquire(BasicResourcePool.java:728)
at
com.mchange.v2.resourcepool.BasicResourcePool.access$700(BasicResourcePool.java:32)
at
com.mchange.v2.resourcepool.BasicResourcePool$AcquireTask.run(BasicResourcePool.java:1258)
at
com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:368)
#############################
FYI, before this exception occurs, the above situation is repeated about 20+
times for the different tables (POJOs) before coming into a deadlock. I
guess each table *creation* gets a connection from c3p0 and holds on while
the others are doing the same, causing the deadlock. Thanks in advance.
Using: hibernate-3.2.1.ga, c3p0-0.9.1-pre6, mysql-connector-java-5.0.4, smx
3.0.1
-los
--
View this message in context:
http://www.nabble.com/issues-with-deadlocking-upon-deployment-onto-SMX-w--hibernate%2C-c3p0-tf2775487s12049.html#a7742513
Sent from the ServiceMix - User mailing list archive at Nabble.com.
