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 <st...@hibernate.org> wrote: > Process != test. Process here == connection. You have multiple. > > On Fri, Jul 17, 2015, 11:12 AM Sanne Grinovero <sa...@hibernate.org> > wrote: > >> On 17 July 2015 at 16:25, Steve Ebersole <st...@hibernate.org> 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 <sa...@hibernate.org> >> 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 <st...@hibernate.org> 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 <st...@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 < >> sa...@hibernate.org> >> >> >> >> >> 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@lists.jboss.org >> >> >>> https://lists.jboss.org/mailman/listinfo/hibernate-dev >> > _______________________________________________ hibernate-dev mailing list hibernate-dev@lists.jboss.org https://lists.jboss.org/mailman/listinfo/hibernate-dev
