[hibernate-dev] Missing transaction hangs the testsuite

Fri Jul 17 11:25:54 EDT 2015

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 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
>