I finally got to re-enable MariaDB and PostgreSQL based tests for Hibernate Search - which has been running on H2 only for some months - and had to debug a case of a single test hanging for a long time. Essentially it would block - for hours - on the SessionFactory#close() method, attempting to drop the database schema with the following statement: > alter table AncientBook_alternativeTitles drop constraint FKn8hhkmhof1mdgc4oi77ccq989 Dumping threads I would get a very similar stack trace on both databases; initially I thought someone had copy/pasted a socket handling bug from one JDBC driver to the other ;-) The PostgreSQL testsuite hanging: "main" prio=10 tid=0x00007f0f40009000 nid=0x5f7c runnable [0x00007f0f48956000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:152) at java.net.SocketInputStream.read(SocketInputStream.java:122) at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:145) at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:114) at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73) at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:274) at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1660) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257) - locked <0x00000007c11e3860> (a org.postgresql.core.v3.QueryExecutorImpl) at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:374) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:302) at org.hibernate.tool.hbm2ddl.DatabaseExporter.export(DatabaseExporter.java:47) at org.hibernate.tool.hbm2ddl.SchemaExport.perform(SchemaExport.java:476) at org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:430) at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:375) at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:371) at org.hibernate.internal.SessionFactoryImpl.close(SessionFactoryImpl.java:1069) at org.hibernate.search.test.util.FullTextSessionBuilder.close(FullTextSessionBuilder.java:149) at org.hibernate.search.test.util.FullTextSessionBuilder$1.evaluate(FullTextSessionBuilder.java:248) at org.junit.rules.RunRules.evaluate(RunRules.java:20) at org.junit.runners.ParentRunner.run(ParentRunner.java:309) at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264) at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153) at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124) at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200) at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153) at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103) The MariaDB testsuite hanging: "main" prio=10 tid=0x00007f8ca0009000 nid=0x4043 runnable [0x00007f8ca5f5c000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:152) at java.net.SocketInputStream.read(SocketInputStream.java:122) at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114) at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161) at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189) - locked <0x00000007c0baa518> (a com.mysql.jdbc.util.ReadAheadInputStream) at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2499) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2952) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2941) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3489) at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1959) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2113) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2562) - locked <0x00000007c0baa850> (a java.lang.Object) at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1664) - locked <0x00000007c0baa850> (a java.lang.Object) at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1583) at org.hibernate.tool.hbm2ddl.DatabaseExporter.export(DatabaseExporter.java:47) at org.hibernate.tool.hbm2ddl.SchemaExport.perform(SchemaExport.java:476) at org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:430) at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:375) at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:371) at org.hibernate.internal.SessionFactoryImpl.close(SessionFactoryImpl.java:1069) at org.hibernate.search.test.util.FullTextSessionBuilder.close(FullTextSessionBuilder.java:149) at org.hibernate.search.test.util.FullTextSessionBuilder$1.evaluate(FullTextSessionBuilder.java:248) at org.junit.rules.RunRules.evaluate(RunRules.java:20) at org.junit.runners.ParentRunner.run(ParentRunner.java:309) at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264) at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153) at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124) at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200) at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153) at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103) On Gail's suggestion I went looking for database level locks; I hadn't thought of that as I assumed it would have timed out more aggressively rather than have me wait for hours. It turns out she was right and the reason for blocking was a simple "count *" query being run as a post-test assertion, which we had forgotten to wrap in an "open transaction & commit" statements pair. The test assertion would be successful, but apparently it would hold on the table lock beyond closing the Session and, then fail to drop the database at the teardown of the test. I'm wondering if this is expected, or if there's something in the new transaction handling code which could be improved? It took me several hours to figure this out; maybe I'm just not using ORM as frequently as once :) If it's this critical to have the transaction, maybe it should be mandatory? And as a memo for next time, this is the query to figure out details about locks on our testing db: > SELECT * FROM pg_locks pl LEFT JOIN pg_stat_activity psa ON pl.pid = psa.pid where datname = 'testingdb'; Thanks, Sanne _______________________________________________ hibernate-dev mailing list hibernate-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/hibernate-dev

For what it is worth, I am running into the same problems on MySQL for the ORM tests in terms of blocks on dropping tables. PGSQL at least finishes, although I run into 55 errors which I still need to triage. On Thu, Jul 16, 2015 at 5:59 PM Steve Ebersole <steve(a)hibernate.org&gt; wrote: > > There is really nothing to improve. What would you suggest as an > improvement? I mean from a ORM perspective, we have an ato-commit > Connection (presumably) and run a query. How on earth would we know to > expect that the database is holding locks for that? > > As far as "requiring transactions" I have tried to fly that plane multiple > times in the past. I think it is absolutely ridiculous to allow these > auto-commit use cases. In fact I personally wanted to take it to the more > extreme case of always using JTA and simply mimicking "single resource JTA > transactions" internally in the "JDBC transaction" case. Gavin and I both > did in fact. But we got a lot of push back. > > So I am not sure exactly what the improvement here might be. What is it > you were thinking specifically? > > On Thu, Jul 16, 2015 at 5:36 PM Sanne Grinovero <sanne(a)hibernate.org&gt; > wrote: >> >> I finally got to re-enable MariaDB and PostgreSQL based tests for >> Hibernate Search - which has been running on H2 only for some months - >> and had to debug a case of a single test hanging for a long time. >> >> Essentially it would block - for hours - on the SessionFactory#close() >> method, attempting to drop the database schema with the following >> statement: >> > alter table AncientBook_alternativeTitles drop constraint >> FKn8hhkmhof1mdgc4oi77ccq989 >> >> Dumping threads I would get a very similar stack trace on both >> databases; initially I thought someone had copy/pasted a socket >> handling bug from one JDBC driver to the other ;-) >> >> The PostgreSQL testsuite hanging: >> >> "main" prio=10 tid=0x00007f0f40009000 nid=0x5f7c runnable >> [0x00007f0f48956000] >> java.lang.Thread.State: RUNNABLE >> at java.net.SocketInputStream.socketRead0(Native Method) >> at java.net.SocketInputStream.read(SocketInputStream.java:152) >> at java.net.SocketInputStream.read(SocketInputStream.java:122) >> at >> org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:145) >> at >> org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:114) >> at >> org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73) >> at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:274) >> at >> org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1660) >> at >> org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257) >> - locked <0x00000007c11e3860> (a >> org.postgresql.core.v3.QueryExecutorImpl) >> at >> org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500) >> at >> org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:374) >> at >> org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:302) >> at >> org.hibernate.tool.hbm2ddl.DatabaseExporter.export(DatabaseExporter.java:47) >> at org.hibernate.tool.hbm2ddl.SchemaExport.perform(SchemaExport.java:476) >> at org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:430) >> at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:375) >> at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:371) >> at >> org.hibernate.internal.SessionFactoryImpl.close(SessionFactoryImpl.java:1069) >> at >> org.hibernate.search.test.util.FullTextSessionBuilder.close(FullTextSessionBuilder.java:149) >> at >> org.hibernate.search.test.util.FullTextSessionBuilder$1.evaluate(FullTextSessionBuilder.java:248) >> at org.junit.rules.RunRules.evaluate(RunRules.java:20) >> at org.junit.runners.ParentRunner.run(ParentRunner.java:309) >> at >> org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264) >> at >> org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153) >> at >> org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124) >> at >> org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200) >> at >> org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153) >> at >> org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103) >> >> The MariaDB testsuite hanging: >> >> "main" prio=10 tid=0x00007f8ca0009000 nid=0x4043 runnable >> [0x00007f8ca5f5c000] >> java.lang.Thread.State: RUNNABLE >> at java.net.SocketInputStream.socketRead0(Native Method) >> at java.net.SocketInputStream.read(SocketInputStream.java:152) >> at java.net.SocketInputStream.read(SocketInputStream.java:122) >> at >> com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114) >> at >> com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161) >> at >> com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189) >> - locked <0x00000007c0baa518> (a >> com.mysql.jdbc.util.ReadAheadInputStream) >> at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2499) >> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2952) >> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2941) >> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3489) >> at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1959) >> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2113) >> at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2562) >> - locked <0x00000007c0baa850> (a java.lang.Object) >> at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1664) >> - locked <0x00000007c0baa850> (a java.lang.Object) >> at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1583) >> at >> org.hibernate.tool.hbm2ddl.DatabaseExporter.export(DatabaseExporter.java:47) >> at org.hibernate.tool.hbm2ddl.SchemaExport.perform(SchemaExport.java:476) >> at org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:430) >> at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:375) >> at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:371) >> at >> org.hibernate.internal.SessionFactoryImpl.close(SessionFactoryImpl.java:1069) >> at >> org.hibernate.search.test.util.FullTextSessionBuilder.close(FullTextSessionBuilder.java:149) >> at >> org.hibernate.search.test.util.FullTextSessionBuilder$1.evaluate(FullTextSessionBuilder.java:248) >> at org.junit.rules.RunRules.evaluate(RunRules.java:20) >> at org.junit.runners.ParentRunner.run(ParentRunner.java:309) >> at >> org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264) >> at >> org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153) >> at >> org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124) >> at >> org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200) >> at >> org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153) >> at >> org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103) >> >> On Gail's suggestion I went looking for database level locks; I hadn't >> thought of that as I assumed it would have timed out more aggressively >> rather than have me wait for hours. >> It turns out she was right and the reason for blocking was a simple >> "count *" query being run as a post-test assertion, which we had >> forgotten to wrap in an "open transaction & commit" statements pair. >> The test assertion would be successful, but apparently it would hold >> on the table lock beyond closing the Session and, then fail to drop >> the database at the teardown of the test. >> >> I'm wondering if this is expected, or if there's something in the new >> transaction handling code which could be improved? It took me several >> hours to figure this out; maybe I'm just not using ORM as frequently >> as once :) >> If it's this critical to have the transaction, maybe it should be >> mandatory? >> >> And as a memo for next time, this is the query to figure out details >> about locks on our testing db: >> > SELECT * FROM pg_locks pl LEFT JOIN pg_stat_activity psa ON pl.pid >> = psa.pid where datname = 'testingdb'; >> >> Thanks, >> Sanne >> _______________________________________________ >> hibernate-dev mailing list >> hibernate-dev(a)lists.jboss.org >> https://lists.jboss.org/mailman/listinfo/hibernate-dev

It would seem that this is a regression with ORM, I agree. However, we do not know how recent of a regression. And that is the problem. We have no idea how far back to look. Because the ORM CI jobs against MySQL, PostrgreSQL, Oracle, etc have not been running for many months. IIRC even when they were running on the old CI servers we had problems with those jobs that were not looked at for some time.

As far as what you see, I am not convinced it is what you think it is in terms of auto-commit for queries run outside of a transaction. This part has not changed in 5.0. Assuming you are using the "built in Connection pool", there is a setting that controls the auto-commit mode of the connections we create (hibernate.connection.autocommit). That setting has always been there, and it has always defaulted to false. This has not changed. In fact the same exact code is used in 4.3 and 5.0 for creating these Connections: org.hibernate.engine.jdbc.connections.internal.BasicConnectionCreator. The autoCommit value in there comes from the setting I just mentioned. The logical outcome is the same even before 4.3, just that it was done differently. So bottom line, if you are not seeing auto-commit on these Connections now, you never were. Now it is possible that their are some ancillary changes that cause the lack of auto-commit to now be an issue where it was not before. So first, I'd need to know whether the Connection here is auto-commit or is not. From there we can start drilling down on what might be a cause. But keep in mind too, that with hangs and deadlocks the process that hangs is often not the culprit; often it is the previous process that is holding locks that is the culprit.

My case is actually different, at least on the surface. Mine happens on dropping tables after the test is complete (for MySQL anyway). Which got me to looking at schema export and friends and how they handle connections. They handle connections quite differently. Again the same as they used to, but I mean very different from how sessions manage connections. In schema export the connections are always set to auto-commit mode at the start of processing. Then they never do anything with auto-commit afterwards. I am not sure this is right.

On Fri, Jul 17, 2015 at 3:51 AM Sanne Grinovero <sanne(a)hibernate.org&gt; wrote: > > Thanks Steve, I wasn't sure if I had found a problem. > Still, it looks like the Hibernate Search tests are not benefiting > from auto-commit, or I wouldn't have this problem right? Our testing > configuration properties have been the same for years and I'm just > re-enabling tests which haven't been run for a while, so I suspect > something changed in ORM. > > I think I'd expect Hibernate ORM to automatically enable auto-commit > on operations not running within a transaction, to make sure all locks > are released when the Session is closed. > > Thanks, > Sanne > > On 17 July 2015 at 00:14, Steve Ebersole <steve(a)hibernate.org&gt; wrote: > > For what it is worth, I am running into the same problems on MySQL for > > the > > ORM tests in terms of blocks on dropping tables. PGSQL at least > > finishes, > > although I run into 55 errors which I still need to triage. > > > > On Thu, Jul 16, 2015 at 5:59 PM Steve Ebersole <steve(a)hibernate.org&gt; > > wrote: > >> > >> There is really nothing to improve. What would you suggest as an > >> improvement? I mean from a ORM perspective, we have an ato-commit > >> Connection (presumably) and run a query. How on earth would we know to > >> expect that the database is holding locks for that? > >> > >> As far as "requiring transactions" I have tried to fly that plane > >> multiple > >> times in the past. I think it is absolutely ridiculous to allow these > >> auto-commit use cases. In fact I personally wanted to take it to the > >> more > >> extreme case of always using JTA and simply mimicking "single resource > >> JTA > >> transactions" internally in the "JDBC transaction" case. Gavin and I > >> both > >> did in fact. But we got a lot of push back. > >> > >> So I am not sure exactly what the improvement here might be. What is > >> it > >> you were thinking specifically? > >> > >> On Thu, Jul 16, 2015 at 5:36 PM Sanne Grinovero <sanne(a)hibernate.org&gt; > > >> wrote: > >>> > >>> I finally got to re-enable MariaDB and PostgreSQL based tests for > >>> Hibernate Search - which has been running on H2 only for some months - > >>> and had to debug a case of a single test hanging for a long time. > >>> > >>> Essentially it would block - for hours - on the SessionFactory#close() > >>> method, attempting to drop the database schema with the following > >>> statement: > >>> > alter table AncientBook_alternativeTitles drop constraint > >>> FKn8hhkmhof1mdgc4oi77ccq989 > >>> > >>> Dumping threads I would get a very similar stack trace on both > >>> databases; initially I thought someone had copy/pasted a socket > >>> handling bug from one JDBC driver to the other ;-) > >>> > >>> The PostgreSQL testsuite hanging: > >>> > >>> "main" prio=10 tid=0x00007f0f40009000 nid=0x5f7c runnable > >>> [0x00007f0f48956000] > >>> java.lang.Thread.State: RUNNABLE > >>> at java.net.SocketInputStream.socketRead0(Native Method) > >>> at java.net.SocketInputStream.read(SocketInputStream.java:152) > >>> at java.net.SocketInputStream.read(SocketInputStream.java:122) > >>> at > >>> > >>> org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:145) > >>> at > >>> > >>> org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:114) > >>> at > >>> > >>> org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73) > >>> at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:274) > >>> at > >>> > >>> org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1660) > >>> at > >>> > >>> org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257) > >>> - locked <0x00000007c11e3860> (a > >>> org.postgresql.core.v3.QueryExecutorImpl) > >>> at > >>> > >>> org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500) > >>> at > >>> > >>> org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:374) > >>> at > >>> > >>> org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:302) > >>> at > >>> > >>> org.hibernate.tool.hbm2ddl.DatabaseExporter.export(DatabaseExporter.java:47) > >>> at > >>> org.hibernate.tool.hbm2ddl.SchemaExport.perform(SchemaExport.java:476) > >>> at > >>> org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:430) > >>> at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:375) > >>> at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:371) > >>> at > >>> > >>> org.hibernate.internal.SessionFactoryImpl.close(SessionFactoryImpl.java:1069) > >>> at > >>> > >>> org.hibernate.search.test.util.FullTextSessionBuilder.close(FullTextSessionBuilder.java:149) > >>> at > >>> > >>> org.hibernate.search.test.util.FullTextSessionBuilder$1.evaluate(FullTextSessionBuilder.java:248) > >>> at org.junit.rules.RunRules.evaluate(RunRules.java:20) > >>> at org.junit.runners.ParentRunner.run(ParentRunner.java:309) > >>> at > >>> > >>> org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264) > >>> at > >>> > >>> org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153) > >>> at > >>> > >>> org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124) > >>> at > >>> > >>> org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200) > >>> at > >>> > >>> org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153) > >>> at > >>> > >>> org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103) > >>> > >>> The MariaDB testsuite hanging: > >>> > >>> "main" prio=10 tid=0x00007f8ca0009000 nid=0x4043 runnable > >>> [0x00007f8ca5f5c000] > >>> java.lang.Thread.State: RUNNABLE > >>> at java.net.SocketInputStream.socketRead0(Native Method) > >>> at java.net.SocketInputStream.read(SocketInputStream.java:152) > >>> at java.net.SocketInputStream.read(SocketInputStream.java:122) > >>> at > >>> > >>> com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114) > >>> at > >>> > >>> com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161) > >>> at > >>> > >>> com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189) > >>> - locked <0x00000007c0baa518> (a > >>> com.mysql.jdbc.util.ReadAheadInputStream) > >>> at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2499) > >>> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2952) > >>> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2941) > >>> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3489) > >>> at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1959) > >>> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2113) > >>> at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2562) > >>> - locked <0x00000007c0baa850> (a java.lang.Object) > >>> at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1664) > >>> - locked <0x00000007c0baa850> (a java.lang.Object) > >>> at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1583) > >>> at > >>> > >>> org.hibernate.tool.hbm2ddl.DatabaseExporter.export(DatabaseExporter.java:47) > >>> at > >>> org.hibernate.tool.hbm2ddl.SchemaExport.perform(SchemaExport.java:476) > >>> at > >>> org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:430) > >>> at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:375) > >>> at org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:371) > >>> at > >>> > >>> org.hibernate.internal.SessionFactoryImpl.close(SessionFactoryImpl.java:1069) > >>> at > >>> > >>> org.hibernate.search.test.util.FullTextSessionBuilder.close(FullTextSessionBuilder.java:149) > >>> at > >>> > >>> org.hibernate.search.test.util.FullTextSessionBuilder$1.evaluate(FullTextSessionBuilder.java:248) > >>> at org.junit.rules.RunRules.evaluate(RunRules.java:20) > >>> at org.junit.runners.ParentRunner.run(ParentRunner.java:309) > >>> at > >>> > >>> org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264) > >>> at > >>> > >>> org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153) > >>> at > >>> > >>> org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124) > >>> at > >>> > >>> org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200) > >>> at > >>> > >>> org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153) > >>> at > >>> > >>> org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103) > >>> > >>> On Gail's suggestion I went looking for database level locks; I hadn't > >>> thought of that as I assumed it would have timed out more aggressively > >>> rather than have me wait for hours. > >>> It turns out she was right and the reason for blocking was a simple > >>> "count *" query being run as a post-test assertion, which we had > >>> forgotten to wrap in an "open transaction & commit" statements pair. > >>> The test assertion would be successful, but apparently it would hold > >>> on the table lock beyond closing the Session and, then fail to drop > >>> the database at the teardown of the test. > >>> > >>> I'm wondering if this is expected, or if there's something in the new > >>> transaction handling code which could be improved? It took me several > >>> hours to figure this out; maybe I'm just not using ORM as frequently > >>> as once :) > >>> If it's this critical to have the transaction, maybe it should be > >>> mandatory? > >>> > >>> And as a memo for next time, this is the query to figure out details > >>> about locks on our testing db: > >>> > SELECT * FROM pg_locks pl LEFT JOIN pg_stat_activity psa ON pl.pid > >>> = psa.pid where datname = 'testingdb'; > >>> > >>> Thanks, > >>> Sanne > >>> _______________________________________________ > >>> hibernate-dev mailing list > >>> hibernate-dev(a)lists.jboss.org > >>> https://lists.jboss.org/mailman/listinfo/hibernate-dev

Process != test. Process here == connection. You have multiple. On Fri, Jul 17, 2015, 11:12 AM Sanne Grinovero <sanne(a)hibernate.org&gt; wrote: > On 17 July 2015 at 16:25, Steve Ebersole <steve(a)hibernate.org&gt; wrote: > > It would seem that this is a regression with ORM, I agree. However, we > do > > not know how recent of a regression. And that is the problem. We have > no > > idea how far back to look. Because the ORM CI jobs against MySQL, > > PostrgreSQL, Oracle, etc have not been running for many months. IIRC > even > > when they were running on the old CI servers we had problems with those > jobs > > that were not looked at for some time. > > Sure, same problem here: not run these tests for months, and you're > right I could do a quick check on a slightly older branch which is > using ORM 4.3 and I have the same problem. > > > As far as what you see, I am not convinced it is what you think it is in > > terms of auto-commit for queries run outside of a transaction. This > part > > has not changed in 5.0. Assuming you are using the "built in Connection > > pool", there is a setting that controls the auto-commit mode of the > > connections we create (hibernate.connection.autocommit). That setting > has > > always been there, and it has always defaulted to false. This has not > > changed. In fact the same exact code is used in 4.3 and 5.0 for > creating > > these Connections: > > org.hibernate.engine.jdbc.connections.internal.BasicConnectionCreator. > The > > autoCommit value in there comes from the setting I just mentioned. The > > logical outcome is the same even before 4.3, just that it was done > > differently. So bottom line, if you are not seeing auto-commit on these > > Connections now, you never were. Now it is possible that their are some > > ancillary changes that cause the lack of auto-commit to now be an issue > > where it was not before. So first, I'd need to know whether the > Connection > > here is auto-commit or is not. From there we can start drilling down on > > what might be a cause. But keep in mind too, that with hangs and > deadlocks > > the process that hangs is often not the culprit; often it is the > previous > > process that is holding locks that is the culprit. > > I understand, but in this specific case I can reproduce the issue by > running a single test. > Also that psql SQL I shared clearly shows which statement is causing it > to hang, > and I could fix the test by just wrapping that statement in a transaction. > > > > > My case is actually different, at least on the surface. Mine happens on > > dropping tables after the test is complete (for MySQL anyway). Which > got me > > to looking at schema export and friends and how they handle connections. > > They handle connections quite differently. Again the same as they used > to, > > but I mean very different from how sessions manage connections. In > schema > > export the connections are always set to auto-commit mode at the start > of > > processing. Then they never do anything with auto-commit afterwards. > I am > > not sure this is right. > > Actually it sounds like you're having the same problem. I debugged the > PosgreSQL tests first, but I had the same on MySQL (as in the > stacktrace I shared), > and the test also hangs on schema drop. > The problem is that the schema can't be dropped because a previous > statement - from a session which is now correctly closed - is still > holding locks. > > Thanks, > Sanne > > > > > > > > > > > On Fri, Jul 17, 2015 at 3:51 AM Sanne Grinovero <sanne(a)hibernate.org&gt; > wrote: > >> > >> Thanks Steve, I wasn't sure if I had found a problem. > >> Still, it looks like the Hibernate Search tests are not benefiting > >> from auto-commit, or I wouldn't have this problem right? Our testing > >> configuration properties have been the same for years and I'm just > >> re-enabling tests which haven't been run for a while, so I suspect > >> something changed in ORM. > >> > >> I think I'd expect Hibernate ORM to automatically enable auto-commit > >> on operations not running within a transaction, to make sure all locks > >> are released when the Session is closed. > >> > >> Thanks, > >> Sanne > >> > >> On 17 July 2015 at 00:14, Steve Ebersole <steve(a)hibernate.org&gt; wrote: > >> > For what it is worth, I am running into the same problems on MySQL > for > >> > the > >> > ORM tests in terms of blocks on dropping tables. PGSQL at least > >> > finishes, > >> > although I run into 55 errors which I still need to triage. > >> > > >> > On Thu, Jul 16, 2015 at 5:59 PM Steve Ebersole <steve(a)hibernate.org&gt; > >> > wrote: > >> >> > >> >> There is really nothing to improve. What would you suggest as an > >> >> improvement? I mean from a ORM perspective, we have an ato-commit > >> >> Connection (presumably) and run a query. How on earth would we > know to > >> >> expect that the database is holding locks for that? > >> >> > >> >> As far as "requiring transactions" I have tried to fly that plane > >> >> multiple > >> >> times in the past. I think it is absolutely ridiculous to allow > these > >> >> auto-commit use cases. In fact I personally wanted to take it to > the > >> >> more > >> >> extreme case of always using JTA and simply mimicking "single > resource > >> >> JTA > >> >> transactions" internally in the "JDBC transaction" case. Gavin and > I > >> >> both > >> >> did in fact. But we got a lot of push back. > >> >> > >> >> So I am not sure exactly what the improvement here might be. What > is > >> >> it > >> >> you were thinking specifically? > >> >> > >> >> On Thu, Jul 16, 2015 at 5:36 PM Sanne Grinovero < > sanne(a)hibernate.org&gt; > >> > >> >> wrote: > >> >>> > >> >>> I finally got to re-enable MariaDB and PostgreSQL based tests for > >> >>> Hibernate Search - which has been running on H2 only for some > months - > >> >>> and had to debug a case of a single test hanging for a long time. > >> >>> > >> >>> Essentially it would block - for hours - on the > SessionFactory#close() > >> >>> method, attempting to drop the database schema with the following > >> >>> statement: > >> >>> > alter table AncientBook_alternativeTitles drop constraint > >> >>> FKn8hhkmhof1mdgc4oi77ccq989 > >> >>> > >> >>> Dumping threads I would get a very similar stack trace on both > >> >>> databases; initially I thought someone had copy/pasted a socket > >> >>> handling bug from one JDBC driver to the other ;-) > >> >>> > >> >>> The PostgreSQL testsuite hanging: > >> >>> > >> >>> "main" prio=10 tid=0x00007f0f40009000 nid=0x5f7c runnable > >> >>> [0x00007f0f48956000] > >> >>> java.lang.Thread.State: RUNNABLE > >> >>> at java.net.SocketInputStream.socketRead0(Native Method) > >> >>> at java.net.SocketInputStream.read(SocketInputStream.java:152) > >> >>> at java.net.SocketInputStream.read(SocketInputStream.java:122) > >> >>> at > >> >>> > >> >>> > org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:145) > >> >>> at > >> >>> > >> >>> > org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:114) > >> >>> at > >> >>> > >> >>> > org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73) > >> >>> at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:274) > >> >>> at > >> >>> > >> >>> > org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1660) > >> >>> at > >> >>> > >> >>> > org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257) > >> >>> - locked <0x00000007c11e3860> (a > >> >>> org.postgresql.core.v3.QueryExecutorImpl) > >> >>> at > >> >>> > >> >>> > org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500) > >> >>> at > >> >>> > >> >>> > org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:374) > >> >>> at > >> >>> > >> >>> > org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:302) > >> >>> at > >> >>> > >> >>> > org.hibernate.tool.hbm2ddl.DatabaseExporter.export(DatabaseExporter.java:47) > >> >>> at > >> >>> > org.hibernate.tool.hbm2ddl.SchemaExport.perform(SchemaExport.java:476) > >> >>> at > >> >>> > org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:430) > >> >>> at > org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:375) > >> >>> at > org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:371) > >> >>> at > >> >>> > >> >>> > org.hibernate.internal.SessionFactoryImpl.close(SessionFactoryImpl.java:1069) > >> >>> at > >> >>> > >> >>> > org.hibernate.search.test.util.FullTextSessionBuilder.close(FullTextSessionBuilder.java:149) > >> >>> at > >> >>> > >> >>> > org.hibernate.search.test.util.FullTextSessionBuilder$1.evaluate(FullTextSessionBuilder.java:248) > >> >>> at org.junit.rules.RunRules.evaluate(RunRules.java:20) > >> >>> at org.junit.runners.ParentRunner.run(ParentRunner.java:309) > >> >>> at > >> >>> > >> >>> > org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264) > >> >>> at > >> >>> > >> >>> > org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153) > >> >>> at > >> >>> > >> >>> > org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124) > >> >>> at > >> >>> > >> >>> > org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200) > >> >>> at > >> >>> > >> >>> > org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153) > >> >>> at > >> >>> > >> >>> > org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103) > >> >>> > >> >>> The MariaDB testsuite hanging: > >> >>> > >> >>> "main" prio=10 tid=0x00007f8ca0009000 nid=0x4043 runnable > >> >>> [0x00007f8ca5f5c000] > >> >>> java.lang.Thread.State: RUNNABLE > >> >>> at java.net.SocketInputStream.socketRead0(Native Method) > >> >>> at java.net.SocketInputStream.read(SocketInputStream.java:152) > >> >>> at java.net.SocketInputStream.read(SocketInputStream.java:122) > >> >>> at > >> >>> > >> >>> > com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114) > >> >>> at > >> >>> > >> >>> > com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161) > >> >>> at > >> >>> > >> >>> > com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189) > >> >>> - locked <0x00000007c0baa518> (a > >> >>> com.mysql.jdbc.util.ReadAheadInputStream) > >> >>> at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2499) > >> >>> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2952) > >> >>> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2941) > >> >>> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3489) > >> >>> at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1959) > >> >>> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2113) > >> >>> at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2562) > >> >>> - locked <0x00000007c0baa850> (a java.lang.Object) > >> >>> at > com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1664) > >> >>> - locked <0x00000007c0baa850> (a java.lang.Object) > >> >>> at > com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1583) > >> >>> at > >> >>> > >> >>> > org.hibernate.tool.hbm2ddl.DatabaseExporter.export(DatabaseExporter.java:47) > >> >>> at > >> >>> > org.hibernate.tool.hbm2ddl.SchemaExport.perform(SchemaExport.java:476) > >> >>> at > >> >>> > org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:430) > >> >>> at > org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:375) > >> >>> at > org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:371) > >> >>> at > >> >>> > >> >>> > org.hibernate.internal.SessionFactoryImpl.close(SessionFactoryImpl.java:1069) > >> >>> at > >> >>> > >> >>> > org.hibernate.search.test.util.FullTextSessionBuilder.close(FullTextSessionBuilder.java:149) > >> >>> at > >> >>> > >> >>> > org.hibernate.search.test.util.FullTextSessionBuilder$1.evaluate(FullTextSessionBuilder.java:248) > >> >>> at org.junit.rules.RunRules.evaluate(RunRules.java:20) > >> >>> at org.junit.runners.ParentRunner.run(ParentRunner.java:309) > >> >>> at > >> >>> > >> >>> > org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264) > >> >>> at > >> >>> > >> >>> > org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153) > >> >>> at > >> >>> > >> >>> > org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124) > >> >>> at > >> >>> > >> >>> > org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200) > >> >>> at > >> >>> > >> >>> > org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153) > >> >>> at > >> >>> > >> >>> > org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103) > >> >>> > >> >>> On Gail's suggestion I went looking for database level locks; I > hadn't > >> >>> thought of that as I assumed it would have timed out more > aggressively > >> >>> rather than have me wait for hours. > >> >>> It turns out she was right and the reason for blocking was a simple > >> >>> "count *" query being run as a post-test assertion, which we had > >> >>> forgotten to wrap in an "open transaction & commit" statements > pair. > >> >>> The test assertion would be successful, but apparently it would > hold > >> >>> on the table lock beyond closing the Session and, then fail to drop > >> >>> the database at the teardown of the test. > >> >>> > >> >>> I'm wondering if this is expected, or if there's something in the > new > >> >>> transaction handling code which could be improved? It took me > several > >> >>> hours to figure this out; maybe I'm just not using ORM as > frequently > >> >>> as once :) > >> >>> If it's this critical to have the transaction, maybe it should be > >> >>> mandatory? > >> >>> > >> >>> And as a memo for next time, this is the query to figure out > details > >> >>> about locks on our testing db: > >> >>> > SELECT * FROM pg_locks pl LEFT JOIN pg_stat_activity psa ON > pl.pid > >> >>> = psa.pid where datname = 'testingdb'; > >> >>> > >> >>> Thanks, > >> >>> Sanne > >> >>> _______________________________________________ > >> >>> hibernate-dev mailing list > >> >>> hibernate-dev(a)lists.jboss.org > >> >>> https://lists.jboss.org/mailman/listinfo/hibernate-dev >

From: "Steve Ebersole" <steve(a)hibernate.org&gt; To: "Sanne Grinovero" <sanne(a)hibernate.org&gt; Cc: "Hibernate.org" <hibernate-dev(a)lists.jboss.org&gt; Sent: Saturday, 18 July, 2015 12:04:01 AM Subject: Re: [hibernate-dev] Missing transaction hangs the testsuite So this is definitely not limited to 5.0. This happens in 4.3 as well. I pointed 4.3 locally to my MariaDB instance and it is hanging. In every case I have seen so far, this is problems in the test code though. On Fri, Jul 17, 2015 at 1:33 PM Steve Ebersole <steve(a)hibernate.org&gt; wrote: > Here is something else interesting... > > So at the point that the test hang against MySQL for me, I have: > > MariaDB [(none)]> SHOW FULL processlist; > > +-----+--------------------+-----------------+--------------------+---------+------+---------------------------------+--------------------------------+----------+ > | Id | User | Host | db | > Command | Time | State | Info > | Progress | > > +-----+--------------------+-----------------+--------------------+---------+------+---------------------------------+--------------------------------+----------+ > | 138 | root | localhost | NULL | Query > | 0 | init | SHOW FULL processlist > | 0.000 | > | 139 | hibernate_orm_test | localhost:52853 | hibernate_orm_test | Sleep > | 12 | | NULL > | 0.000 | > | 140 | hibernate_orm_test | localhost:52854 | hibernate_orm_test | Query > | 12 | Waiting for table metadata lock | drop table if exists TheEntity > | 0.000 | > > +-----+--------------------+-----------------+--------------------+---------+------+---------------------------------+--------------------------------+----------+ > > So we see 2 JDBC connections with process ids 139 and 140. You can see > 139 blocked waiting to be able to drop a table; specifically waiting on a > lock of some sort. > > However, `SHOW OPEN TABLES;` shows no tables in use and no tables locked. > > Unfortunately that is the extent of my "MySQL debugging skills". > > > On Fri, Jul 17, 2015 at 11:14 AM Steve Ebersole <steve(a)hibernate.org&gt; > wrote: > >> Process != test. Process here == connection. You have multiple. >> >> On Fri, Jul 17, 2015, 11:12 AM Sanne Grinovero <sanne(a)hibernate.org&gt; >> wrote: >> >>> On 17 July 2015 at 16:25, Steve Ebersole <steve(a)hibernate.org&gt; wrote: >>> > It would seem that this is a regression with ORM, I agree. However, >>> we do >>> > not know how recent of a regression. And that is the problem. We >>> have no >>> > idea how far back to look. Because the ORM CI jobs against MySQL, >>> > PostrgreSQL, Oracle, etc have not been running for many months. IIRC >>> even >>> > when they were running on the old CI servers we had problems with >>> those jobs >>> > that were not looked at for some time. >>> >>> Sure, same problem here: not run these tests for months, and you're >>> right I could do a quick check on a slightly older branch which is >>> using ORM 4.3 and I have the same problem. >>> >>> > As far as what you see, I am not convinced it is what you think it is >>> in >>> > terms of auto-commit for queries run outside of a transaction. This >>> part >>> > has not changed in 5.0. Assuming you are using the "built in >>> Connection >>> > pool", there is a setting that controls the auto-commit mode of the >>> > connections we create (hibernate.connection.autocommit). That setting >>> has >>> > always been there, and it has always defaulted to false. This has not >>> > changed. In fact the same exact code is used in 4.3 and 5.0 for >>> creating >>> > these Connections: >>> > >>> org.hibernate.engine.jdbc.connections.internal.BasicConnectionCreator. >>> The >>> > autoCommit value in there comes from the setting I just mentioned. The >>> > logical outcome is the same even before 4.3, just that it was done >>> > differently. So bottom line, if you are not seeing auto-commit on >>> these >>> > Connections now, you never were. Now it is possible that their are >>> some >>> > ancillary changes that cause the lack of auto-commit to now be an issue >>> > where it was not before. So first, I'd need to know whether the >>> Connection >>> > here is auto-commit or is not. From there we can start drilling down >>> on >>> > what might be a cause. But keep in mind too, that with hangs and >>> deadlocks >>> > the process that hangs is often not the culprit; often it is the >>> previous >>> > process that is holding locks that is the culprit. >>> >>> I understand, but in this specific case I can reproduce the issue by >>> running a single test. >>> Also that psql SQL I shared clearly shows which statement is causing it >>> to hang, >>> and I could fix the test by just wrapping that statement in a >>> transaction. >>> >>> > >>> > My case is actually different, at least on the surface. Mine happens >>> on >>> > dropping tables after the test is complete (for MySQL anyway). Which >>> got me >>> > to looking at schema export and friends and how they handle >>> connections. >>> > They handle connections quite differently. Again the same as they >>> used to, >>> > but I mean very different from how sessions manage connections. In >>> schema >>> > export the connections are always set to auto-commit mode at the start >>> of >>> > processing. Then they never do anything with auto-commit afterwards. >>> I am >>> > not sure this is right. >>> >>> Actually it sounds like you're having the same problem. I debugged the >>> PosgreSQL tests first, but I had the same on MySQL (as in the >>> stacktrace I shared), >>> and the test also hangs on schema drop. >>> The problem is that the schema can't be dropped because a previous >>> statement - from a session which is now correctly closed - is still >>> holding locks. >>> >>> Thanks, >>> Sanne >>> >>> > >>> > >>> > >>> > >>> > On Fri, Jul 17, 2015 at 3:51 AM Sanne Grinovero <sanne(a)hibernate.org&gt; >>> wrote: >>> >> >>> >> Thanks Steve, I wasn't sure if I had found a problem. >>> >> Still, it looks like the Hibernate Search tests are not benefiting >>> >> from auto-commit, or I wouldn't have this problem right? Our testing >>> >> configuration properties have been the same for years and I'm just >>> >> re-enabling tests which haven't been run for a while, so I suspect >>> >> something changed in ORM. >>> >> >>> >> I think I'd expect Hibernate ORM to automatically enable auto-commit >>> >> on operations not running within a transaction, to make sure all locks >>> >> are released when the Session is closed. >>> >> >>> >> Thanks, >>> >> Sanne >>> >> >>> >> On 17 July 2015 at 00:14, Steve Ebersole <steve(a)hibernate.org&gt; wrote: >>> >> > For what it is worth, I am running into the same problems on MySQL >>> for >>> >> > the >>> >> > ORM tests in terms of blocks on dropping tables. PGSQL at least >>> >> > finishes, >>> >> > although I run into 55 errors which I still need to triage. >>> >> > >>> >> > On Thu, Jul 16, 2015 at 5:59 PM Steve Ebersole <steve(a)hibernate.org >>> > >>> >> > wrote: >>> >> >> >>> >> >> There is really nothing to improve. What would you suggest as an >>> >> >> improvement? I mean from a ORM perspective, we have an ato-commit >>> >> >> Connection (presumably) and run a query. How on earth would we >>> know to >>> >> >> expect that the database is holding locks for that? >>> >> >> >>> >> >> As far as "requiring transactions" I have tried to fly that plane >>> >> >> multiple >>> >> >> times in the past. I think it is absolutely ridiculous to allow >>> these >>> >> >> auto-commit use cases. In fact I personally wanted to take it to >>> the >>> >> >> more >>> >> >> extreme case of always using JTA and simply mimicking "single >>> resource >>> >> >> JTA >>> >> >> transactions" internally in the "JDBC transaction" case. Gavin >>> and I >>> >> >> both >>> >> >> did in fact. But we got a lot of push back. >>> >> >> >>> >> >> So I am not sure exactly what the improvement here might be. What >>> is >>> >> >> it >>> >> >> you were thinking specifically? >>> >> >> >>> >> >> On Thu, Jul 16, 2015 at 5:36 PM Sanne Grinovero < >>> sanne(a)hibernate.org&gt; >>> >> >>> >> >> wrote: >>> >> >>> >>> >> >>> I finally got to re-enable MariaDB and PostgreSQL based tests for >>> >> >>> Hibernate Search - which has been running on H2 only for some >>> months - >>> >> >>> and had to debug a case of a single test hanging for a long time. >>> >> >>> >>> >> >>> Essentially it would block - for hours - on the >>> SessionFactory#close() >>> >> >>> method, attempting to drop the database schema with the following >>> >> >>> statement: >>> >> >>> > alter table AncientBook_alternativeTitles drop constraint >>> >> >>> FKn8hhkmhof1mdgc4oi77ccq989 >>> >> >>> >>> >> >>> Dumping threads I would get a very similar stack trace on both >>> >> >>> databases; initially I thought someone had copy/pasted a socket >>> >> >>> handling bug from one JDBC driver to the other ;-) >>> >> >>> >>> >> >>> The PostgreSQL testsuite hanging: >>> >> >>> >>> >> >>> "main" prio=10 tid=0x00007f0f40009000 nid=0x5f7c runnable >>> >> >>> [0x00007f0f48956000] >>> >> >>> java.lang.Thread.State: RUNNABLE >>> >> >>> at java.net.SocketInputStream.socketRead0(Native Method) >>> >> >>> at java.net.SocketInputStream.read(SocketInputStream.java:152) >>> >> >>> at java.net.SocketInputStream.read(SocketInputStream.java:122) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:145) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:114) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73) >>> >> >>> at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:274) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1660) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257) >>> >> >>> - locked <0x00000007c11e3860> (a >>> >> >>> org.postgresql.core.v3.QueryExecutorImpl) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:374) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:302) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.hibernate.tool.hbm2ddl.DatabaseExporter.export(DatabaseExporter.java:47) >>> >> >>> at >>> >> >>> >>> org.hibernate.tool.hbm2ddl.SchemaExport.perform(SchemaExport.java:476) >>> >> >>> at >>> >> >>> >>> org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:430) >>> >> >>> at >>> org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:375) >>> >> >>> at >>> org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:371) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.hibernate.internal.SessionFactoryImpl.close(SessionFactoryImpl.java:1069) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.hibernate.search.test.util.FullTextSessionBuilder.close(FullTextSessionBuilder.java:149) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.hibernate.search.test.util.FullTextSessionBuilder$1.evaluate(FullTextSessionBuilder.java:248) >>> >> >>> at org.junit.rules.RunRules.evaluate(RunRules.java:20) >>> >> >>> at org.junit.runners.ParentRunner.run(ParentRunner.java:309) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103) >>> >> >>> >>> >> >>> The MariaDB testsuite hanging: >>> >> >>> >>> >> >>> "main" prio=10 tid=0x00007f8ca0009000 nid=0x4043 runnable >>> >> >>> [0x00007f8ca5f5c000] >>> >> >>> java.lang.Thread.State: RUNNABLE >>> >> >>> at java.net.SocketInputStream.socketRead0(Native Method) >>> >> >>> at java.net.SocketInputStream.read(SocketInputStream.java:152) >>> >> >>> at java.net.SocketInputStream.read(SocketInputStream.java:122) >>> >> >>> at >>> >> >>> >>> >> >>> >>> com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114) >>> >> >>> at >>> >> >>> >>> >> >>> >>> com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161) >>> >> >>> at >>> >> >>> >>> >> >>> >>> com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189) >>> >> >>> - locked <0x00000007c0baa518> (a >>> >> >>> com.mysql.jdbc.util.ReadAheadInputStream) >>> >> >>> at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2499) >>> >> >>> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2952) >>> >> >>> at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2941) >>> >> >>> at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3489) >>> >> >>> at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1959) >>> >> >>> at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2113) >>> >> >>> at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2562) >>> >> >>> - locked <0x00000007c0baa850> (a java.lang.Object) >>> >> >>> at >>> com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1664) >>> >> >>> - locked <0x00000007c0baa850> (a java.lang.Object) >>> >> >>> at >>> com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1583) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.hibernate.tool.hbm2ddl.DatabaseExporter.export(DatabaseExporter.java:47) >>> >> >>> at >>> >> >>> >>> org.hibernate.tool.hbm2ddl.SchemaExport.perform(SchemaExport.java:476) >>> >> >>> at >>> >> >>> >>> org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:430) >>> >> >>> at >>> org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:375) >>> >> >>> at >>> org.hibernate.tool.hbm2ddl.SchemaExport.drop(SchemaExport.java:371) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.hibernate.internal.SessionFactoryImpl.close(SessionFactoryImpl.java:1069) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.hibernate.search.test.util.FullTextSessionBuilder.close(FullTextSessionBuilder.java:149) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.hibernate.search.test.util.FullTextSessionBuilder$1.evaluate(FullTextSessionBuilder.java:248) >>> >> >>> at org.junit.rules.RunRules.evaluate(RunRules.java:20) >>> >> >>> at org.junit.runners.ParentRunner.run(ParentRunner.java:309) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:264) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:153) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:124) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:200) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:153) >>> >> >>> at >>> >> >>> >>> >> >>> >>> org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103) >>> >> >>> >>> >> >>> On Gail's suggestion I went looking for database level locks; I >>> hadn't >>> >> >>> thought of that as I assumed it would have timed out more >>> aggressively >>> >> >>> rather than have me wait for hours. >>> >> >>> It turns out she was right and the reason for blocking was a >>> simple >>> >> >>> "count *" query being run as a post-test assertion, which we had >>> >> >>> forgotten to wrap in an "open transaction & commit" statements >>> pair. >>> >> >>> The test assertion would be successful, but apparently it would >>> hold >>> >> >>> on the table lock beyond closing the Session and, then fail to >>> drop >>> >> >>> the database at the teardown of the test. >>> >> >>> >>> >> >>> I'm wondering if this is expected, or if there's something in the >>> new >>> >> >>> transaction handling code which could be improved? It took me >>> several >>> >> >>> hours to figure this out; maybe I'm just not using ORM as >>> frequently >>> >> >>> as once :) >>> >> >>> If it's this critical to have the transaction, maybe it should be >>> >> >>> mandatory? >>> >> >>> >>> >> >>> And as a memo for next time, this is the query to figure out >>> details >>> >> >>> about locks on our testing db: >>> >> >>> > SELECT * FROM pg_locks pl LEFT JOIN pg_stat_activity psa ON >>> pl.pid >>> >> >>> = psa.pid where datname = 'testingdb'; >>> >> >>> >>> >> >>> Thanks, >>> >> >>> Sanne >>> >> >>> _______________________________________________ >>> >> >>> hibernate-dev mailing list >>> >> >>> hibernate-dev(a)lists.jboss.org >>> >> >>> https://lists.jboss.org/mailman/listinfo/hibernate-dev >>> >> _______________________________________________ hibernate-dev mailing list hibernate-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/hibernate-dev