Hi again,
I said before that my problem was a deadlock. It's not actually. It's just a lock timeout generated by the fact that I intend to insert a new line in a table with a foreign key using a record that was just inserted by another transaction (which is not closed yet)
I've made some investigations and did find something : every time a JPA transaction is started, and joined with the current one (which is the expected behavior of the propagation.REQUIRED used in my services' methods), a new connection is taken fromt the pool managed by c3p0. Thus, MySQL start a new transaction.
Should a new transaction be started instead of using the existing one ? If not, this seems to me like
XA Transactions are used, or intented to use on the JPA side but that MySQL does not see it in that way.
Here is the log written by my app while generating the lock issue :
Quote:
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Creating new transaction with name [gpaf.services.impl.UserService.find]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@15d4273] for JPA transaction
17 juin 2011 05:09:39 [main] com.mchange.v2.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@5d855f [managed: 5, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@1758cd1)
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@15c6c8d]
17 juin 2011 05:09:39 [main] com.mchange.v2.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@5d855f [managed: 5, unused: 3, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@1758cd1)
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl@17cff66]
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
17 juin 2011 05:09:39 [main] org.hibernate.SQL - select user0_.ID as ID3_0_, user0_.droits as droits3_0_, user0_.hibernate_version as hibernate3_3_0_, user0_.login as login3_0_, user0_.password as password3_0_ from user user0_ where user0_.ID=?
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - cxnStmtMgr.statementSet( com.mysql.jdbc.JDBC4Connection@1195c2b ).size(): 1
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 1; checked out: 1; num connections: 1; num keys: 1
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 1; checked out: 0; num connections: 1; num keys: 1
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Initiating transaction commit
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@15d4273]
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinAll(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 1; checked out: 0; num connections: 1; num keys: 1
17 juin 2011 05:09:39 [main] com.mchange.v2.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@5d855f [managed: 5, unused: 3, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@1758cd1)
17 juin 2011 05:09:39 [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinAll(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 1; checked out: 0; num connections: 1; num keys: 1
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinAll(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 1; checked out: 0; num connections: 1; num keys: 1
17 juin 2011 05:09:39 [main] com.mchange.v2.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@5d855f [managed: 5, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@1758cd1)
17 juin 2011 05:09:39 [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinAll(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 1; checked out: 0; num connections: 1; num keys: 1
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@15d4273] after transaction
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.EntityManagerFactoryUtils - Closing JPA EntityManager
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Creating new transaction with name [gpaf.services.impl.VersionApplicativeService.findLastVaVersionNumber]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@c360a5] for JPA transaction
17 juin 2011 05:09:39 [main] com.mchange.v2.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@5d855f [managed: 5, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@1758cd1)
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@145c761]
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl@c360a5] for JPA transaction
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Participating in existing transaction
17 juin 2011 05:09:39 [main] com.mchange.v2.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@5d855f [managed: 5, unused: 3, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@1758cd1)
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl@24c672]
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
17 juin 2011 05:09:39 [main] org.hibernate.SQL - select max(this_.VERSION) as y0_ from version_applicative this_
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - cxnStmtMgr.statementSet( com.mysql.jdbc.JDBC4Connection@dc1f04 ).size(): 1
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 2; checked out: 1; num connections: 2; num keys: 2
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 2; checked out: 0; num connections: 2; num keys: 2
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Initiating transaction commit
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@c360a5]
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinAll(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 2; checked out: 0; num connections: 2; num keys: 2
17 juin 2011 05:09:39 [main] com.mchange.v2.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@5d855f [managed: 5, unused: 3, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@1758cd1)
17 juin 2011 05:09:39 [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinAll(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 2; checked out: 0; num connections: 2; num keys: 2
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinAll(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 2; checked out: 0; num connections: 2; num keys: 2
17 juin 2011 05:09:39 [main] com.mchange.v2.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@5d855f [managed: 5, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@1758cd1)
17 juin 2011 05:09:39 [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinAll(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 2; checked out: 0; num connections: 2; num keys: 2
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@c360a5] after transaction
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.EntityManagerFactoryUtils - Closing JPA EntityManager
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - No local transaction to join
17 juin 2011 05:09:39 [main] com.mchange.v2.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@5d855f [managed: 5, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@1758cd1)
17 juin 2011 05:09:39 [main] org.hibernate.SQL - select abaque0_.ID as ID0_0_, abaque0_.DATE_DEB as DATE2_0_0_, abaque0_.DATE_FIN as DATE3_0_0_, abaque0_.hibernate_version as hibernate4_0_0_, abaque0_.NOM as NOM0_0_ from abaque abaque0_ where abaque0_.ID=?
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - cxnStmtMgr.statementSet( com.mysql.jdbc.JDBC4Connection@dc1f04 ).size(): 2
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 3; checked out: 1; num connections: 2; num keys: 3
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 3; checked out: 0; num connections: 2; num keys: 3
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinAll(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 3; checked out: 0; num connections: 2; num keys: 3
17 juin 2011 05:09:39 [main] com.mchange.v2.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@5d855f [managed: 5, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@1758cd1)
17 juin 2011 05:09:39 [com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinAll(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 3; checked out: 0; num connections: 2; num keys: 3
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Creating new transaction with name [gpaf.services.impl.VersionApplicativeService.createVa]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@a37c6a] for JPA transaction
17 juin 2011 05:09:39 [main] com.mchange.v2.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@5d855f [managed: 5, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@1758cd1)
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Exposing JPA transaction as JDBC transaction [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@7881db]
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl@a37c6a] for JPA transaction
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Participating in existing transaction
17 juin 2011 05:09:39 [main] com.mchange.v2.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@5d855f [managed: 5, unused: 3, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@1758cd1)
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl@24c672]
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
17 juin 2011 05:09:39 [main] org.hibernate.SQL - select max(this_.VERSION) as y0_ from version_applicative this_
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - cxnStmtMgr.statementSet( com.mysql.jdbc.JDBC4Connection@1195c2b ).size(): 2
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 4; checked out: 1; num connections: 2; num keys: 4
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 4; checked out: 0; num connections: 2; num keys: 4
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
17 juin 2011 05:09:39 [main] org.hibernate.SQL - select this_.ID as ID9_0_, this_.ID_ABAQUE as ID9_9_0_, this_.ANNEE as ANNEE9_0_, this_.DATE_MEP as DATE3_9_0_, this_.DATE_MES as DATE4_9_0_, this_.hibernate_version as hibernate5_9_0_, this_.PALIER as PALIER9_0_, this_.STATUT_VERSION as STATUT7_9_0_, this_.VERSION as VERSION9_0_ from version_applicative this_ where this_.VERSION=?
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - cxnStmtMgr.statementSet( com.mysql.jdbc.JDBC4Connection@1195c2b ).size(): 3
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 5; checked out: 1; num connections: 2; num keys: 5
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 5; checked out: 0; num connections: 2; num keys: 5
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
17 juin 2011 05:09:39 [main] org.hibernate.SQL - insert into version_applicative (ID_ABAQUE, ANNEE, DATE_MEP, DATE_MES, hibernate_version, PALIER, STATUT_VERSION, VERSION) values (?, ?, ?, ?, ?, ?, ?, ?)
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - cxnStmtMgr.statementSet( com.mysql.jdbc.JDBC4Connection@1195c2b ).size(): 4
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 6; checked out: 1; num connections: 2; num keys: 6
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 6; checked out: 0; num connections: 2; num keys: 6
17 juin 2011 05:09:39 [main] org.hibernate.SQL - select processusa0_.ID_VERSION_APPLICATIVE as ID7_9_1_, processusa0_.ID as ID1_, processusa0_.ID as ID8_0_, processusa0_.DESCR as DESCR8_0_, processusa0_.DESC_SFG as DESC3_8_0_, processusa0_.hibernate_version as hibernate4_8_0_, processusa0_.NOM as NOM8_0_, processusa0_.REF_SFG as REF6_8_0_, processusa0_.ID_VERSION_APPLICATIVE as ID7_8_0_ from processus_applicatif processusa0_ where processusa0_.ID_VERSION_APPLICATIVE=?
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - cxnStmtMgr.statementSet( com.mysql.jdbc.JDBC4Connection@1195c2b ).size(): 5
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 7; checked out: 1; num connections: 2; num keys: 7
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkinStatement(): com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 7; checked out: 0; num connections: 2; num keys: 7
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl@a37c6a] for JPA transaction
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.JpaTransactionManager - Participating in existing transaction
17 juin 2011 05:09:39 [main] com.mchange.v2.resourcepool.BasicResourcePool - trace com.mchange.v2.resourcepool.BasicResourcePool@5d855f [managed: 5, unused: 2, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@1758cd1)
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Starting resource local transaction on application-managed EntityManager [org.hibernate.ejb.EntityManagerImpl@65394b]
17 juin 2011 05:09:39 [main] org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler - Joined local transaction
17 juin 2011 05:09:39 [main] org.hibernate.SQL - insert into processus_applicatif (DESCR, DESC_SFG, hibernate_version, NOM, REF_SFG, ID_VERSION_APPLICATIVE) values (?, ?, ?, ?, ?, ?)
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - cxnStmtMgr.statementSet( com.mysql.jdbc.JDBC4Connection@6d999a ).size(): 1
17 juin 2011 05:09:39 [main] com.mchange.v2.c3p0.stmt.GooGooStatementCache - checkoutStatement: com.mchange.v2.c3p0.stmt.GlobalMaxOnlyStatementCache stats -- total size: 8; checked out: 1; num connections: 3; num keys: 8
17 juin 2011 05:10:30 [main] com.mchange.v2.c3p0.impl.NewPooledConnection - com.mchange.v2.c3p0.impl.NewPooledConnection@14b9a74 handling a throwable.
java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction
Anyone ?
Thanks