[hibernate-dev] Missing transaction hangs the testsuite
Martin Simka
msimka at redhat.com
Wed Aug 19 09:47:02 EDT 2015
I'm now trying to run database testsuite against various databases. So far I've been successful with hibernate-core and hibernate-entitymanager tests on MariaDB and PostgreSQL (I had to add transaction to few test cases). But I can't run hibernate-envers tests on MariaDB because a lot of tests hang when dropping tables after the test is complete. Tests don't hang when I enable hibernate.connection.autocommit=true in hibernate.properties.
Is it good idea to enable autocommit in envers tests?
Thanks,
Martin
----- Original Message -----
> From: "Steve Ebersole" <steve at hibernate.org>
> To: "Sanne Grinovero" <sanne at hibernate.org>
> Cc: "Hibernate.org" <hibernate-dev at lists.jboss.org>
> 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 at hibernate.org> 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 at hibernate.org>
> > wrote:
> >
> >> Process != test. Process here == connection. You have multiple.
> >>
> >> On Fri, Jul 17, 2015, 11:12 AM Sanne Grinovero <sanne at hibernate.org>
> >> wrote:
> >>
> >>> On 17 July 2015 at 16:25, Steve Ebersole <steve at 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 <sanne at 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 <steve at 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 <steve at 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 at 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 at lists.jboss.org
> >>> >> >>> https://lists.jboss.org/mailman/listinfo/hibernate-dev
> >>>
> >>
> _______________________________________________
> hibernate-dev mailing list
> hibernate-dev at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/hibernate-dev
>
More information about the hibernate-dev
mailing list