search

swaldman / c3p0

a mature, highly concurrent JDBC Connection pooling library, with support for caching and reuse of PreparedStatements.
http://www.mchange.com/projects/c3p0
Other
1.28k stars 338 forks source link

Java deadlock - Hibernate/C3P0/MySQL #143

Closed asgs closed 4 months ago

asgs commented 4 years ago

Hello. I've reviewed the issues #10 and #84 . Though those look similar, the issue outlined below is slightly different (in that the deadlock happens on different monitor objects LoadBalancedConnectionProxy and ReplicationConnectionProxy) and the version we use at the moment is newer than the ones in those issues.

C3P0 version - 0.9.5.1 MySQL Connector - 5.1.40 JRE - OpenJDK Runtime Environment (build 1.8.0_171-b10)

Let me know if there's any additional information required, please


waiting to lock monitor 0x00007fd26c222328 (object 0x00000000d327ff70, a com.mysql.jdbc.LoadBalancedConnectionProxy),
which is held by pool-23-thread-637
pool-23-thread-637:
waiting to lock monitor 0x00007fd28caca978 (object 0x00000000d326b578, a com.mysql.jdbc.ReplicationConnectionProxy),
which is held by pool-23-thread-643
Java stack information for the threads listed above:

pool-23-thread-643:
at com.mysql.jdbc.MultiHostConnectionProxy.invoke(MultiHostConnectionProxy.java:409)
- waiting to lock <0x00000000d327ff70> (a com.mysql.jdbc.LoadBalancedConnectionProxy)
at com.sun.proxy..prepareStatement(Unknown Source)
at com.mysql.jdbc.MultiHostMySQLConnection.prepareStatement(MultiHostMySQLConnection.java:1994)
at sun.reflect.GeneratedMethodAccessor121.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.mysql.jdbc.ReplicationConnectionProxy.invokeMore(ReplicationConnectionProxy.java:309)
at com.mysql.jdbc.MultiHostConnectionProxy.invoke(MultiHostConnectionProxy.java:452)
- locked <0x00000000d326b578> (a com.mysql.jdbc.ReplicationConnectionProxy)
at com.sun.proxy..prepareStatement(Unknown Source)
at com.mchange.v2.c3p0.impl.NewProxyConnection.prepareStatement(NewProxyConnection.java:387)
- locked <0x00000000d330b528> (a com.mchange.v2.c3p0.impl.NewProxyConnection)
at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:534)
at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:452)
at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:161)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1573)
at org.hibernate.loader.Loader.doQuery(Loader.java:696)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:259)
at org.hibernate.loader.Loader.loadEntity(Loader.java:1881)
at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:71)
at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:65)
at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3072)
at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:434)
at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:415)
at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:165)
at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:121)
at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:905)
at org.hibernate.impl.SessionImpl.immediateLoad(SessionImpl.java:863)
at org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:95)
at org.hibernate.proxy.AbstractLazyInitializer.getImplementation(AbstractLazyInitializer.java:140)
at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:190)
at com.abc.Model1_5634_jvstc67_10c.isEnabled(Model1_5634_jvstc67_10c.java)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
pool-23-thread-637:
at com.mysql.jdbc.ResultSetImpl.next(ResultSetImpl.java:6301)
- waiting to lock <0x00000000d326b578> (a com.mysql.jdbc.ReplicationConnectionProxy)
at sun.reflect.GeneratedMethodAccessor107.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.mysql.jdbc.MultiHostConnectionProxy.invoke(MultiHostConnectionProxy.java:103)
- locked <0x00000000d327ff70> (a com.mysql.jdbc.LoadBalancedConnectionProxy)
at com.sun.proxy..next(Unknown Source)
at sun.reflect.GeneratedMethodAccessor107.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.mysql.jdbc.MultiHostConnectionProxy.invoke(MultiHostConnectionProxy.java:103)
- locked <0x00000000d327ff70> (a com.mysql.jdbc.LoadBalancedConnectionProxy)
at com.sun.proxy..next(Unknown Source)
at com.mchange.v2.c3p0.impl.NewProxyResultSet.next(NewProxyResultSet.java:685)
at org.hibernate.loader.Loader.doQuery(Loader.java:720)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:259)
at org.hibernate.loader.Loader.loadEntity(Loader.java:1881)
at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:71)
at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:65)
at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3072)
at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:434)
at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:415)
at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:165)
at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:121)
at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:905)
at org.hibernate.impl.SessionImpl.immediateLoad(SessionImpl.java:863)
at org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:95)
at org.hibernate.proxy.AbstractLazyInitializer.getImplementation(AbstractLazyInitializer.java:140)
at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:190)
at com.abc.Model2_5634_jvstc67_e.getName(Model2_5634_jvstc67_e.java)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.
asgs commented 4 years ago

@swaldman any chance you could take a look, please?

swaldman commented 6 months ago

Both of the locks contributing to the deadlock are within MySQL code. c3p0/hibernate seem to be simultaneously preparing a new statement and trying to iterate over a ResultSet (which must have been the result from some prior Statement. It seems legit for these things to be happening simultaneously. In particular Connection objects are supposed to be thread-safe at the top level, so preparing a new Statement shouldn't interfere with other Statements or ResultSets. It seems like this might be an issue with the MySQL JDBC driver under replication and and load balancing.

asgs commented 4 months ago

@swaldman thank you for your response

It has been some time now. So, I don't remember what exactly we did to circumvent this issue but I guess we disabled lazy init on some of the Hibernate fields which seemed to have triggered this concurrent access resulting in deadlock

at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:190) at com.abc.Model1_5634_jvstc67_10c.isEnabled(Model1_5634_jvstc67_10c.java)